あひるの勉強部屋

つらつらつら~と不定期にカキコするブログ

debian busterのstableにおけるiostatの異常値

debian busterのstableを運用しているマシンで iostat における %util についてNVMe SSDの場合のみ異常に数値が高かったのでとりあえず調査した。 特に原因の特定とかまではできておらず、雑に調べた内容を適当にメモしておくだけ。

現象

最初に書いた通り iostat%util の値が NVMe SSD に対してのみ高い。(2台のマシン、合計3つのメーカーが異なるNVMe SSDで再現を確認)
型番メモるのめんどいのでやる気が出たら追記する。
ちなみにHDDは特に異常に見える値は出ていなかった。

問題が発覚したマシンの iostat の結果が以下の通り。

Device            r/s     w/s     rMB/s     wMB/s   rrqm/s   wrqm/s  %rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz  svctm  %util
nvme0n1         21.29   33.76      0.27      1.11     1.09     3.00   4.88   8.15    0.73    0.27   0.87    13.13    33.81  15.38  84.65
sda              7.00    3.64      0.99      0.21     0.00     1.34   0.04  26.91    2.43   10.41   0.05   145.53    57.86   1.58   1.68

nvme0n1%util がやたら高い数値になっている。

調査内容

Debian の stable と testing の最新を使って差異を確認した。
ちなみにいずれもクリーンインストールした状態で行った。

調査環境

- -
マシン Lenovo E495 Ryzen5 3500U
ディスク WD BLUE SN550
OS Debian Buster (4.19.0-10), Debian Bullseye (5.7.0-2)

調査途中結果

二つのカーネルで大きな差が出た。
iostat に関してはバージョンの違いにより項目が変わっていたりするが %util を比較すると 4.19 の高さが際立つ。
/proc/diskstats の差も見ると time spent doing I/Os (ms)weighted time spent doing I/Os (ms) の値が大きく違うことが分かる。
いずれのdiskstatsの値も起動後10分程度で取得した値である。
10分のうち7分以上もI/Oに費やされているとは思えない。

これらはカーネルの更新によって直ったとみるべきだろうか。
なお、/proc/diskstats の項目数が異なるのはカーネル5.5+より2項目増えたためである。 *1

時間とやる気ができればそのうちもうちょっと調べるかもしれない。

Debian Buster (4.19.0-10) の場合

sysstat のバージョンをメモるのを忘れたが、たしか 12.0.3 だったと思う。

$ iostat -xdm
Linux 4.19.0-10-amd64 (auburn)  08/09/2020      _x86_64_        (8 CPU)

Device            r/s     w/s     rMB/s     wMB/s   rrqm/s   wrqm/s  %rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz  svctm  %util
nvme0n1          7.26    3.18      0.38      0.17     0.01     0.60   0.11  15.79    1.01    0.90   0.95    53.29    54.02  90.74  94.74

$ cat /proc/diskstats
 259       0 nvme0n1 3744 4 399146 3734 1630 308 175074 1406 0 456044 459884 0 0 0 0
 259       1 nvme0n1p1 1133 0 7370 2560 2 0 2 0 0 32 2484 0 0 0 0
 259       2 nvme0n1p2 2375 4 378624 1151 1248 308 175072 1295 0 1392 2400 0 0 0 0
 259       3 nvme0n1p3 153 0 9752 7 0 0 0 0 0 8 8 0 0 0 0

Debian Bullseye (5.7.0-2) の場合

sysstat のバージョンは 12.3.3 だった。

$ iostat -xdm
Linux 5.7.0-2-amd64 (auburn)    08/09/2020      _x86_64_        (8 CPU)

Device            r/s     rMB/s   rrqm/s  %rrqm r_await rareq-sz     w/s     wMB/s   wrqm/s  %wrqm w_await wareq-sz     d/s     dMB/s   drqm/s  %drqm d_await dareq-sz     f/s f_await  aqu-sz  %util
nvme0n1          3.25      0.26     0.02   0.53    0.40    81.37    2.72      0.20     0.44  13.95    1.01    76.00    0.00      0.00     0.00   0.00    0.00     0.00    0.49    0.31    0.00   0.40

$ cat /proc/diskstats
 259       0 nvme0n1 2610 14 424763 1036 2183 354 331801 2211 0 3240 3372 0 0 0 0 394 124
 259       1 nvme0n1p1 107 0 6323 26 1 0 1 0 0 72 26 0 0 0 0 0 0
 259       2 nvme0n1p2 2325 14 409240 999 1788 354 331800 2084 0 3168 3084 0 0 0 0 0 0
 259       3 nvme0n1p3 114 0 6800 4 0 0 0 0 0 48 4 0 0 0 0 0 0

参考情報

DebianBug Report #927184 に同じような症状の報告が上がっていた。

s25t障害に関する事後報告20200802

s25t HDD炎上障害報告

2020年7月28日に social.mikutter.hachune.net(以下s25t)においてサーバーにアクセスができない問題が発生しました。

復旧までに1週間弱かかりましたが、幸いデータの破損等はありませんでした。

障害発生期間

2020/07/28 01:30 ~ 2020/08/01 19:40

障害内容

サーバー内のHDDに使用されていたペリフェラル電源−SATA電源変換ケーブルが焼けました。

焼けたコネクタの写真
焼けたコネクタ

amzn.to

被害

  • 障害期間中、全ユーザーがサーバへアクセスできませんでした

原因

ペリフェラル電源−SATA電源変換ケーブルが焼けたことが原因です。

上記変換ケーブルを利用していた理由としては、使用していたHDDが3.3V問題を抱えていたため、これを回避するために使用していました。

構成

マストドンでアップロードされた画像等のメディアデータは、先日問題が発生したSSDではなく、HDD上に保存していました。

先月の問題発生によってSSDのバックアップは設定したが、HDDは画像だけだし、そのうちでいいかと思っていたところに、今回の事件が発生しました。

そのことによって、画像等のデータに全てアクセスできなくなるだけでも、事実上サービスを提供できなくなるということが判明しました。

3.3V問題

SATA3.2規格のHDDで、3.3Vの電源入力があると動作しないHDDがあります。

今回問題となったHDDは、もともと外付けHDDとして販売されていたものをバラして内蔵HDDとして転用したもので、この問題によって動作しませんでした。

マシン構築当時は、ペリフェラル電源−SATA電源変換ケーブルでは3.3Vのピンがないことを利用して、この問題を回避していました。

対応

  • HDDの交換を行いました。
  • 電源ユニットの交換を行いました。
  • ペリフェラル電源−SATA電源変換ケーブルを取り除きました。

対応経緯

月日 時分 事象
7/28 01:30 ケーブルが焼ける
01:50 サーバー管理者がインシデントに気づく。この時点でサーバーの設置部屋と廊下がダイオキシンの匂いが充満していた。
02:00 配線が焼けているのを発見した。この時点で電源は落ちていた。電源ケーブルをコンセントから抜く。
07:00 起床して夢じゃないことを確認
21:40 HDDを @sushi に郵送
7/29 19:40 交換用の電源ユニットを発注@sushi
7/30 21:30 @ahiruからHDDが届き初期診断
22:00 今回は焼けたHDDから直接データを取り出す方針とし、まずは焼損部分の除去を開始
23:13 除去後には電源投入でき、HDDの全データをコピー開始
7/31 18:30 電源ユニットが@ahiruの元に到着
20:20 全データのコピー完了を確認できた
20:45 HDDを @ahiru に郵送
8/1 09:55 @sushi によって復旧されたHDDが到着
14:00 電源ユニットとHDDの交換作業開始
17:40 HDDの3.3Vのピンの除去作業
19:40 復旧完了
20:00 フリージア をかけて復旧を祝う

Appendix.A データサルベージ

焼けた状態のHDDが到着し、まずは初期診断を実施

コネクタの除去をしている写真
コネクタの除去

焼損部分は変換ケーブル側の12V付近とHDDの電源コネクタに限られたため、下記の道具を用意し焼けたコネクタの除去を行いました。

  • 無水エタノール
  • 歯ブラシ
  • ペンチ
  • マイナスドライバー
  • カッターナイフ

コネクタ除去後のSATA端子の写真
除去後の端子

その後は用意していた同容量HDDにデータをすべて移し替えました。

移行元と移行先HDDを並べている写真
移行元と移行先HDD

Appendix.B 3.3V問題の解決

  • 根本的問題解決のため@sushi の指導の下、HDDの3.3Vのピンを切除しました。
    3.3Vピンを切除したHDDのSATA端子の写真
    3.3Vピン切除後

youtu.be

謝辞

前回の障害に引き続きs25tユーザーの皆様におかれましては、サーバの復旧を待っていただきありがとうございました。

asciidoctor-revealjsでスライド作成

Asciidocを使ってスライドを作ってみたくなった。

スライドを作るだけなら asciidoctor のリポジトリで管理されている asciidoctor.jsasciidoctor-revealjs を使うだけで済む。
npmパッケージを使用する場合は、公式の手順通りに上記パッケージをインストールしてコマンドを叩くだけだ。

今回はこれに加えてスライド作成時にライブリロードをしたかったので、そのあたりで試行錯誤したことを備忘録として書いておく。

なお、文章の体裁は崩壊してる。

やりたいこと

  • Asciidoc でスライドを作成する
  • スライド作成時にライブリロードしたい

使うもの

やったこと

まずはadocファイルの変更を検知してスライドのhtmlファイルに変換することを考えた。
ファイルの変更検知をどうするか適当に調べてみると、node.js標準の fs.watch とか、それをラップした Chokidar などが使えそうだった。

次にadocから生成されたhtmlのライブリロードについては、browser-sync というものを使ってみようとなった。
これによってファイル変更時のブラウザのライブリロードが実現できる。
つまり fs.watch とか Chokidar とかを別途入れて検知しなくても、browser-sync の監視対象のファイルをadocファイルにして、変更検知時にhtmlを生成させたうえでリロードできればいけるじゃんとなった。
ちなみに browser-sync の依存関係を追っていくと、chokidar を使っているようだった。 ドキュメントに chokidar 向けの設定に関して書かれていて気づいた。

browser-syncasciidoctor-revealjs にはスクリプトで使用するためのインターフェースも用意されていたため、以下のようなスクリプトで実現できた。

browserSync.watch で ファイル名が .adoc で終わるファイルの変更を監視し、変更時は index.adoc をhtmlに変換したうえで browserSync.reload('index.html') でページのリロードを行っている。

このスクリプトの前提としては index.adoc がスライドのadocファイルのエントリポイントとなる。
ここをわざわざ変えたいことは自分はないだろうということでハードコードした。

後で気づいたけど、browser-sync はデフォだと change イベントしかリッスンしないので、if (event === 'change') ブロックいらないな。

スライド作成の環境整えて満足したのでスライド作成が進んでいない。

s25t障害に関する事後報告

2020年6月22日に social.mikutter.hachune.net(以下s25t)においてサーバーにアクセスができない問題が発生しました。

復旧まで1週間弱かかりましたが、幸いなことにデータの破損等は見受けられませんでした。

なお復旧後確認したところ、過去30日間のSLA80.5029%(thx @2bo)でした。

復旧後はユーザーより

  • SLA39.39%からほど遠い
  • SLA39.39%以下になって初めてSLAを守れたといえるのではないのか

などと厳しい追及を受けております。 精進いたします。

障害発生期間

2020/06/22 02:10 ~ 2020/06/27 22:26

障害内容

ディスクに対するあらゆるIOが不可能な状態になり、その結果サーバーに対する一切の接続ができない状況が発生しました。

被害

  • 全ユーザーが障害期間中へのインスタンスへのアクセスができない
  • shibafu528のtootを気軽に通報できない
  • 障害期間中、TLを見れないことによってVtuberにハマり、復活後もTLを見ることが減ったためオタクが治ったと勘違いするユーザが続出

原因

ディスクイメージのバックアップ後に、サーバーが不安定になり始めた前後のログを確認しましたが、有用な情報は一切得られませんでした。
ディスクイメージ吸出しにあたり、ディスクの読み込みは問題ありませんでした。
更に吸出し後にホストに接続したところ問題なく起動しました。
起動後にストレージの状態をnvme-cliで確認しましたが、問題となるような情報は得られませんでした。
以上のことから原因不明と結論付けました。

対応

  • memtest86+を2周してエラーがないことを確認しました。
  • NVMe SSDのディスクイメージのバックアップを行いました。
  • 予備のNVMe SSDを調達しましたが、交換対応は見送りました。
    • nvme-cliで確認したところ一切のエラーが発見されず、今回の原因がディスクであると断定できなかったため。
  • NVMe SSDヒートシンク CRYORIG Frostbit を購入しましたが設置は見送りました。
    • 運用時にヒートシンクなしで35℃程度と優秀であったため。
    • しばらくは今回の記念碑として扱います。
  • 適切なスケジュールでバックアップが実行されるように設定しました。
  • 今回の障害のテーマ曲としてフリージアを採用。mora.jpでハイレゾ版を購入し、これを聴きながら復旧作業にあたりました。
    • モチベーションを上げるため。

対応経緯

月日 時分 事象
1/12 ホストマシンをNUCから現在のマシンに移行。バックアップ設定は来週やることに。
1月中旬 このあたりからサーバ管理者が一ヶ月くらい寝込む。
2月中旬 体調が回復。バックアップの設定変更のことは忘れている。
6/22 02:10 CPU,Load Averageの急激な上昇,Disk IOの急激な低下
02:30 監視系への通知が停止
07:15 起床。体調がここ半年で最も悪い状態だった。
07:29 サーバー管理者が監視系の異常に気付き調査の開始
08:52 サーバーの電源を落とす。以降はまっとうな社会人として仕事を行っていた。
12:00 午後休を取るも体調がよくなる傾向が皆無であったため、復旧は週末と決めた。
18:00 最後のバックアップが1/12で停止していることが判明。この時点ではSSDの破損が強く疑われていたため、半年のデータ巻き戻りを前提に休養を進めることに。
20:20 503ページの公開
6/24 18:02 memtest86+によるRAMメモリーチェックを開始
6/25 07:56 memtest86+を2周した結果エラーなしを確認
6/26 17:37 作業用BGMとしてフリージアを購入
21:38 フリージアをかけながら、翌日に行う復旧の手順書の作成と確認
6/27 10:00 復旧作業の事前準備
14:00 復旧の開始
17:51 サーバーのテスト起動
22:00頃 フリージアをかけながらDNSの切り替え完了を待つ
22:26 インスタンスの疎通確認

謝辞

s25tユーザーの皆様に関しては、インスタンスの復旧を気長に待っていただきありがとうございました。
特に、復旧するにあたり相談させていただいたs25t管理者の方々には心より御礼申し上げます。
彼らがいたからこそ適切に復旧できたといっても過言ではありません。

mastodonのElasticsearch有効化(docker)

手順

  1. docker-compose.yml のelasticsearchに関する記述のコメントイン
    @@ -21,17 +21,17 @@ services:
        volumes:
        - ./redis:/data
    
    -#  es:
    -#    restart: always
    -#    image: docker.elastic.co/elasticsearch/elasticsearch-oss:6.1.3
    -#    environment:
    -#      - "ES_JAVA_OPTS=-Xms512m -Xmx512m"
    -#    networks:
    -#      - internal_network
    -#    healthcheck:
    -#      test: ["CMD-SHELL", "curl --silent --fail localhost:9200/_cluster/health || exit 1"]
    -#    volumes:
    -#      - ./elasticsearch:/usr/share/elasticsearch/data
    +  es:
    +    restart: always
    +    image: docker.elastic.co/elasticsearch/elasticsearch-oss:6.1.3
    +    environment:
    +      - "ES_JAVA_OPTS=-Xms512m -Xmx512m"
    +    networks:
    +      - internal_network
    +    healthcheck:
    +      test: ["CMD-SHELL", "curl --silent --fail localhost:9200/_cluster/health || exit 1"]
    +    volumes:
    +      - ./elasticsearch:/usr/share/elasticsearch/data
    
    web:
        build: .
    @@ -49,7 +49,7 @@ services:
        depends_on:
        - db
        - redis
    -#      - es
    +      - es
        volumes:
        - ./public/system:/mastodon/public/system
    
  2. envファイルのコメントイン
    -#ES_ENABLED=true
    -#ES_HOST=es
    -#ES_PORT=9200
    +ES_ENABLED=true
    +ES_HOST=es
    +ES_PORT=9200
    
  3. マウントするディレクトリの作成。
    所有者を 1000:1000 にしないと起動時にアクセスできずエラーとなる。
    $ mkdir -p elasticsearch
    $ chown -R 1000:1000 elasticsearch
    
  4. vm.max_map_count を 26144 に上げる。
    これをしないと起動に失敗する。なお、この変更はansible側で行った。
    - name: increase vm.max_map_count to maximum
      sysctl:
        name: vm.max_map_count
        value: 26144
        state: present
        reload: yes
    
  5. elasticsearchコンテナを立ち上げて、落ち着いたら chewy:deploy を実行して完了
    $ docker-compose up -d
    $ docker-compose run --rm web rails chewy:deploy
    

今後やっておきたいこと

  • 本番機に展開する際は XmsXmx を上げておきたい
  • 日本語の検索がかなり怪しいので形態素解析の導入をしたほうがいいかもしれない
  • hoge で検索しても取り切れていないものがあるのが謎なので余裕があれば調べる(調べない)

debianインストール時のメモ書き

備忘録として記録する。

debian-10.1.0-amd64-netinst.iso の graphical install で一通りインストールした。 ファイルシステムは btrfs にしたのとスワップ領域を減らした以外は特にいじった記憶がない。

以下、graphical install 後に変更・修正した内容である。

ブートローダーの変更

iso では grub2 をブートローダーとしてインストールしたが、システム全体が systemd なので統一してみたく systemd-boot に変更してみた。 以下、その際の作業内容になる。

  1. インストール

    # bootctl install

    必要に応じて --path オプションをつける。
    これで systemd-boot に必要なファイルが efi パーティションに展開される。
    今回は /boot/efiefi パーティションである前提で続ける。

  2. ブートエントリの追加 /boot/efi/loader/entries/debian.conf に下記のように書く。

    title   Debian
    linux   /vmlinuz-4.19.0-6-amd64
    initrd  /initrd.img-4.19.0-6-amd64
    options root=PARTUUID=YOUR_PART_UUID_HERE rw quiet nouveau.modeset=0
     
    linuxinitrd には /boot/efi をルートとしたパスが必要だった。
    optionsPARTUUIDblkid コマンドで調べた。 自分の環境の場合、grub2 の際に /boot 配下に vmlinuz や initrd.img があったため、それらをコピーして efi パーティションに設置した。
    これってシンボリックリンクでもいいんだろうか…?

    この辺りはメモを忘れてうろ覚えだが、efibootmgr コマンドでブート順序を確認した記憶がある。 起動順序で Linux Boot Manager が最初になっていれば systemd-boot で起動する。

なお、この辺りで参考にしたのは Arch Wiki

nouveau nomodeset

ブートオプションを追加した話。

起動時にコンソールの表示が妙に伸びており、下記エラーが表示されていた。

[    4.953345] nouveau 0000:07:00.0: DRM: failed to create kernel channel, -22
[    5.074717] nouveau 0000:07:00.0: DRM: allocated 1920x2160 fb: 0x200000, bo 00000000ab79588a

マシンは NVidiaGPU を使っており、そのドライバに起因するものらしい。
今回 GPU は緊急時のコンソール表示のためにつけており、基本は ssh で使う予定なのでブートオプションで KMS を無効化してしまう。
先の systemd-boot の conf にも書いてあるように、以下の nouveau.modeset=0ブートローダーのエントリの設定に追加した。

options root=PARTUUID=YOUR_PART_UUID_HERE rw quiet nouveau.modeset=0

このあたり、実はちゃんと理解しておらず nouveau って KMS に対応してるはずでは?とか疑問が残っている。 そのうち調べる。

realtek ドライバ

[    3.553551] r8169 0000:05:00.0: firmware: failed to load rtl_nic/rtl8168h-2.fw (-2)
[    3.553616] firmware_class: See https://wiki.debian.org/Firmware for information about missing firmware
[    3.553690] r8169 0000:05:00.0: Direct firmware load for rtl_nic/rtl8168h-2.fw failed with error -2
[    3.553693] r8169 0000:05:00.0 enp5s0: unable to load firmware patch rtl_nic/rtl8168h-2.fw (-2)

apt の non-free なリポジトリを追加して firmware-realtek パッケージを取得することで解決した。

Watchdog 問題

[    3.382156] sp5100_tco: SP5100/SB800 TCO WatchDog Timer Driver
[    3.382217] sp5100-tco sp5100-tco: Using 0xfed80b00 for watchdog MMIO address
[    3.382227] sp5100-tco sp5100-tco: Watchdog hardware is disabled

特段使う予定もなく、disabledになっていて問題はないがいちいち disabled と出して欲しくなかったためロードしないようにした。

# cat << EOF > /etc/modprobe.d/sp5100_tco.conf 
blacklist sp5100_tco
EOF

上記は調べている時に見つけた これ を参考にしている。

lm_sensors

CPU温度を mackerel に飛ばしたかったので、lm_sensors を入れた。

# apt install lm_sensors

sensors-detect して sensors を実行すれば取れるはずがCPUの温度情報が取れていなかった。
sensors-detect の出力をよく見ると下記の情報が得られた。

To load everything that is needed, add this to /etc/modules:
#----cut here----
# Chip drivers
nct6775
#----cut here----

このガイドを元に /etc/modulesnct6775 を追記して再起動したらCPU温度を CPUTIN として取得できるようになった。
sensors の出力結果の CPUIN の行は次のようだった。

CPUTIN:                 +26.5°C  (high = +80.0°C, hyst = +75.0°C)  sensor = thermistor

この温度の数値部分(26.5)を mackerel に飛ばすために値を整形するのは下記のようにしてみた。

$ sensors|grep CPUTIN|awk '{print $2}'|sed -E 's/^\+(.+)°C$/\1/g'

とりあえずここまで。
まだ設定は全てしていないかもしれないので、気づいたものがあれば追記する。

mikutter on dockerでリンクが開けない問題へのワークアラウンド

dockerコンテナでmikutterを動かしてみたところ、認証時につまづいたことがあったので共有します。
なお、今回の問題とワークアラウンドについてはAppImageユーザーにとっても有用です。
今回話す環境は以下のリポジトリgui付きのコンテナを実行した時のものです。
docker mikutter

問題

dockerコンテナで動かすmikutterでURLを開こうとしても開かないです。
dockerのコンテナ内にはブラウザがないためです。
このままだと最初のアカウント追加時に認可できずに詰んでしまいます。

ワークアラウンド

mikutter の 「設定 -> 表示 -> URLを開く方法」に下記設定をします。
次のコマンドを使う を選択して、テキストボックスに echo と入力。

f:id:ahiruZ:20190723200522p:plain
mikutter setting

上記を実行することで、リンクを押したときにmikutterのログにリンクが表示されます。

f:id:ahiruZ:20190723201433p:plain
url shown in log

まとめ

これを設定することでアカウント追加時のリンクで詰まなくなるので困っている方はお試しください。