概要

  • HDDのRAID1を組んでfstabでマウントするように設定した後、シャットダウン時に blk-availability.service がタイムアウトする。
  • 待たされるのもイヤだしディスク周りなので安全のため調査した。
  • raidのresync中なのが原因だったらしい。そんなん数分で終わる訳ないんだから、resyncを待つんじゃなくて mdadm -S(--stop) 後に数秒だけ待機するように調整した。

問題発生時のログ

$ sudo journalctl -b -1 -u blk-availability.service
-- Logs begin at Thu 2021-03-18 00:56:47 JST, end at Thu 2021-03-18 13:09:03 JST. --
Mar 18 12:56:52 sirius systemd[1]: Starting Availability of block devices...
Mar 18 12:56:52 sirius systemd[1]: Finished Availability of block devices.
Mar 18 13:06:04 sirius systemd[1]: Stopping Availability of block devices...
Mar 18 13:06:04 sirius blkdeactivate[2630]: Deactivating block devices:
Mar 18 13:06:05 sirius blkdeactivate[2630]:   [UMOUNT]: unmounting md127 (md127) mounted on /x... done
Mar 18 13:07:34 sirius systemd[1]: blk-availability.service: Stopping timed out. Terminating.
Mar 18 13:07:34 sirius systemd[1]: blk-availability.service: Control process exited, code=killed, status=15/TERM
Mar 18 13:07:34 sirius blkdeactivate[2630]:   [MD]: deactivating raid1 device md127... resync action in progress...
Mar 18 13:07:34 sirius systemd[1]: blk-availability.service: Failed with result 'timeout'.
Mar 18 13:07:34 sirius systemd[1]: Stopped Availability of block devices.

効果がなかったこと

https://bugs.launchpad.net/ubuntu/+source/lvm2/+bug/1780196 を見て sudo apt install dracut-core を試してみる。インストール直後から2回rebootして効果なし。


ログ出力の強化

https://askubuntu.com/questions/1051856/timed-out-availability-of-block-devices をみて /lib/systemd/system/blk-availability.service の行 ExecStop=/sbin/blkdeactivate ... に -vv オプションを追加してログ出力を強化してみる。

$ sudo journalctl -b -1 -u blk-availability.service
-- Logs begin at Thu 2021-03-18 00:56:47 JST, end at Thu 2021-03-18 13:28:08 JST. --
Mar 18 13:25:18 sirius systemd[1]: Starting Availability of block devices...
Mar 18 13:25:18 sirius systemd[1]: Finished Availability of block devices.
Mar 18 13:25:32 sirius systemd[1]: Stopping Availability of block devices...
(snip...)
Mar 18 13:25:33 sirius blkdeactivate[1502]: ++ /sbin/mdadm -vv -W /dev/md0
Mar 18 13:27:03 sirius systemd[1]: blk-availability.service: Stopping timed out. Terminating.
Mar 18 13:27:03 sirius systemd[1]: blk-availability.service: Control process exited, code=killed, status=15/TERM
Mar 18 13:27:03 sirius systemd[1]: blk-availability.service: Failed with result 'timeout'.
Mar 18 13:27:03 sirius systemd[1]: Stopped Availability of block devices.

調査

どうも /sbin/mdadm -vv -W /dev/md0 が遅いらしい。

resyncの進行状況は watch -n 1 cat /proc/mdstat で見れる。

Personalities : [raid1] [linear] [multipath] [raid0] [raid6] [raid5] [raid4] [raid10]
md0 : active raid1 sdb1[1] sda1[0]
      5860388864 blocks super 1.2 [2/2] [UU]
      [=================>...]  resync = 88.3% (5180243456/5860388864) finish=135.7min speed=83484K/sec
      bitmap: 8/44 pages [32KB], 65536KB chunk

unused devices: <none>

speed=83484K/sec の数字はデバイスの性能を十分に発揮しているらしく、sysctl -w dev.raid.speed_limit_max=9999999999 は効果がなかった。

/sbin/mdadm -vv -W /dev/md0を起動している/sbin/blkdeactivateを眺めた感じ、-r wait が指定されている場合は $SYS_BLK_DIR/$kname/md/sync_actionidle以外なら"$MDADM" $MDADM_OPTS -W "$DEV_DIR/$kname" "$OUT" "$ERR" を起動するようだった。

その後に mdadm -S して終了コードが正常なら “done” をログに出力する。

$man mdadm
(snip...)
 -W, --wait : For each md device given, wait for any resync, recovery, or reshape activity to finish before returning.  mdadm will return with success if it actually waited for every device listed, otherwise it will return failure.
(snip...)
-S, --stop : deactivate array, releasing all resources.

対応

…いや、こんなの数分で終わる訳がないし、どっちにしろタイムアウトするんなら待たなくていいだろう。 しかしディスク操作の直後にシャットダウンが発生するのも気持ち悪い。

cp -a /sbin/blkdeactivate /sbin/blkdeactivate.custom してcustom版に以下のような変更を行う。

# diff -Naru /sbin/blkdeactivate /sbin/blkdeactivate.custom
--- /sbin/blkdeactivate 2020-02-14 06:21:51.000000000 +0900
+++ /sbin/blkdeactivate.custom  2021-03-18 15:19:21.798002190 +0900
@@ -297,26 +297,22 @@

        deactivate_holders "$DEV_DIR/$xname" || return 1

-       echo -n "  [MD]: deactivating $devtype device $kname... "
-
-       test "$MDRAID_DO_WAIT" -eq 1 && {
-               sync_action=$(cat "$SYS_BLK_DIR/$kname/md/sync_action")
-               test "$sync_action" != "idle" && {
-                       echo -n "$sync_action action in progress... "
-                       if eval "$MDADM" $MDADM_OPTS -W "$DEV_DIR/$kname" "$OUT" "$ERR"; then
-                               echo -n "complete... "
-                       else
-                               test $? -ne 1 && echo -n "failed to wait for $sync_action action... "
-                       fi
-               }
+       sync_action=$(cat "$SYS_BLK_DIR/$kname/md/sync_action")
+       test "$sync_action" != "idle" && {
+           echo "  [MD]: device $kname : $sync_action action in progress... "
        }

+       echo -n "  [MD]: deactivating $devtype device $kname... "
        if eval "$MDADM" $MDADM_OPTS -S "$xname" "$OUT" "$ERR"; then
                echo "done"
        else
                echo "skipping"
                add_device_to_skip_list
        fi
+
+       echo "  [MD]: sleep 5 second, then get current status."
+       sleep 5
+       cat /proc/mdstat
 }

 deactivate () {

次に /lib/systemd/system/blk-availability.service の行 ExecStop=/sbin/blkdeactivate ... を変更して /sbin/blkdeactivate.custom を呼び出すようにする。

変更内容はこんな感じ。

  • mdadm -W で待機しない。ただし現在のsync_actionはログに出力する。
  • ‘mdadm -S’ の後に5秒待った後にcat /proc/mdstatする

動作確認

シャットダウン時のログは以下のようになった。

$ sudo journalctl -b -1 -u blk-availability.service
-- Logs begin at Thu 2021-03-18 00:56:47 JST, end at Thu 2021-03-18 15:20:37 JST. --
Mar 18 15:05:01 sirius systemd[1]: Starting Availability of block devices...
Mar 18 15:05:01 sirius systemd[1]: Finished Availability of block devices.
Mar 18 15:19:26 sirius systemd[1]: Stopping Availability of block devices...
Mar 18 15:19:26 sirius blkdeactivate.custom[2168]: Deactivating block devices:
Mar 18 15:19:27 sirius blkdeactivate.custom[2168]:   [UMOUNT]: unmounting md0 (md0) mounted on /x... done
Mar 18 15:19:27 sirius blkdeactivate.custom[2168]:   [MD]: device md0 : resync action in progress...
Mar 18 15:19:27 sirius blkdeactivate.custom[2168]:   [MD]: deactivating raid1 device md0... done
Mar 18 15:19:27 sirius blkdeactivate.custom[2168]:   [MD]: sleep 5 second, then get current status.
Mar 18 15:19:32 sirius blkdeactivate.custom[2721]: Personalities : [raid1] [linear] [multipath] [raid0] [raid6] [raid5] [raid4] [raid10]
Mar 18 15:19:32 sirius blkdeactivate.custom[2721]: unused devices: <none>
Mar 18 15:19:32 sirius systemd[1]: blk-availability.service: Succeeded.
Mar 18 15:19:32 sirius systemd[1]: Stopped Availability of block devices.

cat /proc/mdstat の内容がunused devices: <none>だけなので、mdadmがRAIDボリュームを使わなくなった後にhaltしているはずだ。

@tateisu
mod
creator
11M

蛇足だが、定期的なチェックはいつ発生するのかというとUbuntu 20 では以下のサービスが管理してるらしい。

$ systemctl status mdcheck_start.timer
● mdcheck_start.timer - MD array scrubbing
     Loaded: loaded (/lib/systemd/system/mdcheck_start.timer; enabled; vendor preset: enabled)
     Active: active (waiting) since Thu 2021-03-18 15:20:24 JST; 23min ago
    Trigger: Sun 2021-04-04 17:58:21 JST; 2 weeks 3 days left
   Triggers: ● mdcheck_start.service

Mar 18 15:20:24 sirius systemd[1]: Started MD array scrubbing.

$ systemctl status mdcheck_start.service
● mdcheck_start.service - MD array scrubbing
     Loaded: loaded (/lib/systemd/system/mdcheck_start.service; static; vendor preset: enabled)
     Active: inactive (dead)
TriggeredBy: ● mdcheck_start.timer
⌚ガジェット
!gadgets

    ガジェット関連の記事を収集します

    • 0 users online
    • 1 user / day
    • 1 user / week
    • 1 user / month
    • 1 user / 6 months
    • 3 subscribers
    • 16 Posts
    • 13 Comments
    • Modlog