Long (re)boot time

[solracsf]

I'm trying s3backer on dev environnement using a S3 compatible service (Scaleway). I've set up my box 95% accordingly to Wiki pages (configuration, fstab..) and uploaded some files on it. So far, so good.

But, when I've tried to reboot the system to see "what happens" iv'e experienced a long boot time (>10mn); also, on some tries, the filesystem mount has failed.

When mount has failed, this is the syslog:

Jan 26 23:12:35 scw-s3backer s3backer: mounting /mnt/s3b/fuse
Jan 26 23:12:35 scw-s3backer kernel: [   14.905269] SGI XFS with ACLs, security attributes, realtime, no debug enabled
Jan 26 23:12:35 scw-s3backer kernel: [   15.432447] XFS (loop5): Mounting V5 Filesystem
Jan 26 23:12:37 scw-s3backer systemd[1]: dmesg.service: Succeeded.
Jan 26 23:12:37 scw-s3backer s3backer: non-zero block survey completed (3911 non-zero blocks reported)
Jan 26 23:12:39 scw-s3backer kernel: [   18.773848] XFS (loop5): Ending clean mount
Jan 26 23:12:56 scw-s3backer systemd[1]: systemd-fsckd.service: Succeeded.
Jan 26 23:14:04 scw-s3backer systemd[1]: mnt-s3b-xfs.mount: Mounting timed out. Terminating.
Jan 26 23:15:10 scw-s3backer s3backer: rec'd 500 response: GET https://s3backer-cloudeezy.s3.fr-par.scw.cloud/62a3cbc3-6c3ffff9
Jan 26 23:15:20 scw-s3backer s3backer: retrying query (attempt #2): GET https://s3backer-cloudeezy.s3.fr-par.scw.cloud/62a3cbc3-6c3ffff9
Jan 26 23:15:34 scw-s3backer systemd[1]: mnt-s3b-xfs.mount: Mount process timed out. Killing.
Jan 26 23:15:34 scw-s3backer systemd[1]: mnt-s3b-xfs.mount: Killing process 1433 (mount) with signal SIGKILL.
Jan 26 23:17:04 scw-s3backer systemd[1]: mnt-s3b-xfs.mount: Mount process still around after SIGKILL. Ignoring.
Jan 26 23:17:04 scw-s3backer systemd[1]: mnt-s3b-xfs.mount: Failed with result 'timeout'.
Jan 26 23:17:04 scw-s3backer systemd[1]: Failed to mount /mnt/s3b/xfs.
Jan 26 23:17:04 scw-s3backer systemd[1]: Dependency failed for Remote File Systems.
Jan 26 23:17:04 scw-s3backer systemd[1]: remote-fs.target: Job remote-fs.target/start failed with result 'dependency'.

On dmesg, no mater if mount succeed or fails, this is the output:

[27430.039930] INFO: task s3backer:1373 blocked for more than 120 seconds.
[27430.040714]       Tainted: P           O      5.4.0-96-generic #109-Ubuntu
[27430.041521] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[27430.042720] s3backer        D    0  1373      1 0x00004000
[27430.042723] Call Trace:
[27430.042731]  __schedule+0x2e3/0x740
[27430.042733]  schedule+0x42/0xb0
[27430.042735]  schedule_timeout+0x10e/0x160
[27430.042737]  ? blk_finish_plug+0x26/0x40
[27430.042739]  wait_for_completion+0xb1/0x120
[27430.042742]  ? wake_up_q+0x70/0x70
[27430.042776]  ? __xfs_buf_submit+0x138/0x260 [xfs]
[27430.042801]  xfs_buf_iowait+0x26/0xe0 [xfs]
[27430.042824]  __xfs_buf_submit+0x138/0x260 [xfs]
[27430.042845]  _xfs_buf_read+0x27/0x30 [xfs]
[27430.042866]  xfs_buf_read_map+0x132/0x1d0 [xfs]
[27430.042868]  ? __switch_to_asm+0x34/0x70
[27430.042897]  xfs_trans_read_buf_map+0xca/0x350 [xfs]
[27430.042927]  xfs_imap_to_bp+0x66/0xd0 [xfs]
[27430.042955]  xfs_iflush+0x116/0x240 [xfs]
[27430.042981]  xfs_reclaim_inode+0x257/0x350 [xfs]
[27430.043045]  xfs_reclaim_inodes_ag+0x1fb/0x380 [xfs]
[27430.043069]  ? xfs_inode_set_reclaim_tag+0xb5/0x170 [xfs]
[27430.043096]  ? xfs_fs_destroy_inode+0x13b/0x1d0 [xfs]
[27430.043099]  ? destroy_inode+0x41/0x80
[27430.043101]  ? evict+0x14c/0x1b0
[27430.043125]  xfs_reclaim_inodes_nr+0x35/0x40 [xfs]
[27430.043150]  xfs_fs_free_cached_objects+0x19/0x20 [xfs]
[27430.043153]  super_cache_scan+0x160/0x1b0
[27430.043156]  do_shrink_slab+0x150/0x2a0
[27430.043158]  ? shrink_node_memcg+0x2e5/0x370
[27430.043160]  shrink_slab+0x20c/0x2a0
[27430.043161]  shrink_node+0xd3/0x410
[27430.043163]  do_try_to_free_pages+0xd7/0x3a0
[27430.043165]  try_to_free_pages+0xea/0x1d0
[27430.043168]  __alloc_pages_slowpath+0x447/0xe50
[27430.043171]  ? update_curr+0x78/0x1e0
[27430.043173]  ? get_page_from_freelist+0x89/0x3f0
[27430.043175]  __alloc_pages_nodemask+0x2d0/0x320
[27430.043177]  alloc_pages_vma+0x7f/0x200
[27430.043179]  do_anonymous_page+0x118/0x650
[27430.043181]  __handle_mm_fault+0x760/0x7a0
[27430.043183]  handle_mm_fault+0xca/0x200
[27430.043186]  do_user_addr_fault+0x1f9/0x450
[27430.043187]  __do_page_fault+0x58/0x90
[27430.043190]  ? exit_to_usermode_loop+0x8f/0x160
[27430.043191]  do_page_fault+0x2c/0xe0
[27430.043193]  do_async_page_fault+0x39/0x70
[27430.043195]  async_page_fault+0x34/0x40
[27430.043197] RIP: 0033:0x7f65b1f74113
[27430.043202] Code: Bad RIP value.
[27430.043203] RSP: 002b:00007f658a3f86c8 EFLAGS: 00010246
[27430.043204] RAX: 0000000000000009 RBX: 00007f652c238888 RCX: 00007f652c20f390
[27430.043205] RDX: 000000000004b240 RSI: 00007f652c331000 RDI: 00007f652c2b0f50
[27430.043205] RBP: 00007f652c238860 R08: 00007f652c238888 R09: 0000000000000001
[27430.043206] R10: 0000000000000009 R11: 00007f652c20f390 R12: 00007f652c27c0f0
[27430.043206] R13: 00007f652c2fc1b0 R14: 00000000000800a0 R15: 0000000000000001
[27430.043210] INFO: task s3backer:1375 blocked for more than 120 seconds.
[27430.044159]       Tainted: P           O      5.4.0-96-generic #109-Ubuntu
[27430.046352] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[27430.049240] s3backer        D    0  1375      1 0x00000000
[27430.049245] Call Trace:
[27430.049256]  __schedule+0x2e3/0x740
[27430.049259]  schedule+0x42/0xb0
[27430.049263]  rwsem_down_read_slowpath+0x16c/0x4a0
[27430.049267]  down_read+0x85/0xa0
[27430.049270]  __do_sys_madvise+0x774/0xb30
[27430.049274]  ? vfs_read+0x12e/0x160
[27430.049276]  ? fput+0x13/0x20
[27430.049278]  __x64_sys_madvise+0x1a/0x20
[27430.049280]  ? __x64_sys_madvise+0x1a/0x20
[27430.049283]  do_syscall_64+0x57/0x190
[27430.049285]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[27430.049288] RIP: 0033:0x7f65b1d61bdb
[27430.049294] Code: Bad RIP value.
[27430.049295] RSP: 002b:00007f65893f6778 EFLAGS: 00000246 ORIG_RAX: 000000000000001c
[27430.049297] RAX: ffffffffffffffda RBX: 00000000001f9d40 RCX: 00007f65b1d61bdb
[27430.049298] RDX: 0000000000000004 RSI: 00000000001d9000 RDI: 00007f65303f3000
[27430.049299] RBP: 00007f6530000020 R08: 0000000000000007 R09: 00007f65b1e31b80
[27430.049300] R10: 0000000000000007 R11: 0000000000000246 R12: 00000000001d9000
[27430.049301] R13: 00000000003f3000 R14: 00007f6530000000 R15: 00007f65303d22c0
[27430.049304] INFO: task s3backer:1377 blocked for more than 120 seconds.
[27430.050978]       Tainted: P           O      5.4.0-96-generic #109-Ubuntu
[27430.051571] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[27430.052273] s3backer        D    0  1377      1 0x00000000
[27430.052276] Call Trace:
[27430.052281]  __schedule+0x2e3/0x740
[27430.052282]  schedule+0x42/0xb0
[27430.052283]  rwsem_down_read_slowpath+0x16c/0x4a0
[27430.052285]  down_read+0x85/0xa0
[27430.052287]  __do_sys_madvise+0x774/0xb30
[27430.052289]  ? vfs_read+0x12e/0x160
[27430.052290]  ? fput+0x13/0x20
[27430.052291]  __x64_sys_madvise+0x1a/0x20
[27430.052291]  ? __x64_sys_madvise+0x1a/0x20
[27430.052293]  do_syscall_64+0x57/0x190
[27430.052294]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[27430.052296] RIP: 0033:0x7f65b1d61bdb
[27430.052310] Code: Bad RIP value.
[27430.052311] RSP: 002b:00007f65883f4778 EFLAGS: 00000246 ORIG_RAX: 000000000000001c
[27430.052312] RAX: ffffffffffffffda RBX: 000000000017db10 RCX: 00007f65b1d61bdb
[27430.052313] RDX: 0000000000000004 RSI: 000000000015d000 RDI: 00007f65184c9000
[27430.052314] RBP: 00007f6518000020 R08: 0000000000000007 R09: 00007f65b1e31b80
[27430.052314] R10: 0000000000000007 R11: 0000000000000246 R12: 000000000015d000
[27430.052315] R13: 00000000004c9000 R14: 00007f6518000000 R15: 00007f65184a84f0
[27430.052317] INFO: task s3backer:1380 blocked for more than 120 seconds.
[27430.052929]       Tainted: P           O      5.4.0-96-generic #109-Ubuntu
[27430.053548] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[27430.054366] s3backer        D    0  1380      1 0x00000000
[27430.054368] Call Trace:
[27430.054373]  __schedule+0x2e3/0x740
[27430.054375]  schedule+0x42/0xb0
[27430.054376]  rwsem_down_read_slowpath+0x16c/0x4a0
[27430.054378]  down_read+0x85/0xa0
[27430.054379]  __do_sys_madvise+0x774/0xb30
[27430.054381]  ? vfs_read+0x12e/0x160
[27430.054382]  ? fput+0x13/0x20
[27430.054383]  __x64_sys_madvise+0x1a/0x20
[27430.054383]  ? __x64_sys_madvise+0x1a/0x20
[27430.054385]  do_syscall_64+0x57/0x190
[27430.054386]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[27430.054387] RIP: 0033:0x7f65b1d61bdb
[27430.054391] Code: Bad RIP value.
[27430.054391] RSP: 002b:00007f6586bf1778 EFLAGS: 00000246 ORIG_RAX: 000000000000001c
[27430.054392] RAX: ffffffffffffffda RBX: 000000000014d480 RCX: 00007f65b1d61bdb
[27430.054393] RDX: 0000000000000004 RSI: 000000000012d000 RDI: 00007f6510402000
[27430.054393] RBP: 00007f6510000020 R08: 0000000000000007 R09: 00007f65b1e31b80
[27430.054394] R10: 0000000000000007 R11: 0000000000000246 R12: 000000000012d000
[27430.054394] R13: 0000000000402000 R14: 00007f6510000000 R15: 00007f65103e1b80
[27430.054396] INFO: task s3backer:1381 blocked for more than 120 seconds.
[27430.055208]       Tainted: P           O      5.4.0-96-generic #109-Ubuntu
[27430.055819] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[27430.056489] s3backer        D    0  1381      1 0x00000000
[27430.056491] Call Trace:
[27430.056498]  __schedule+0x2e3/0x740
[27430.056500]  schedule+0x42/0xb0
[27430.056501]  rwsem_down_read_slowpath+0x16c/0x4a0
[27430.056504]  ? do_futex+0x3be/0x4d0
[27430.056505]  down_read+0x85/0xa0
[27430.056508]  do_user_addr_fault+0x38d/0x450
[27430.056509]  __do_page_fault+0x58/0x90
[27430.056510]  do_page_fault+0x2c/0xe0
[27430.056512]  do_async_page_fault+0x39/0x70
[27430.056513]  async_page_fault+0x34/0x40
[27430.056515] RIP: 0033:0x7f65b1ce04fa
[27430.056520] Code: Bad RIP value.
[27430.056520] RSP: 002b:00007f65863f0640 EFLAGS: 00010206
[27430.056521] RAX: 0000000000000201 RBX: 00007f6528000020 RCX: 00007f6528695e00
[27430.056522] RDX: 00007f65b1e31b80 RSI: 00000000000800c4 RDI: 0000000000714000
[27430.056522] RBP: 00000000000800c5 R08: 00007f6528615d50 R09: 0000000000691000
[27430.056523] R10: 00007f6528691000 R11: fffffffffffff000 R12: 000000000007b2c0
[27430.056523] R13: 0000000000001000 R14: 00007f6528615d40 R15: 00000000000800e0
[27430.056526] INFO: task s3backer:1387 blocked for more than 120 seconds.
[27430.057164]       Tainted: P           O      5.4.0-96-generic #109-Ubuntu
[27430.057895] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[27430.058685] s3backer        D    0  1387      1 0x00000000
[27430.058687] Call Trace:
[27430.058694]  __schedule+0x2e3/0x740
[27430.058696]  schedule+0x42/0xb0
[27430.058697]  rwsem_down_read_slowpath+0x16c/0x4a0
[27430.058699]  down_read+0x85/0xa0
[27430.058701]  __do_sys_madvise+0x774/0xb30
[27430.058703]  ? vfs_read+0x12e/0x160
[27430.058704]  ? fput+0x13/0x20
[27430.058705]  __x64_sys_madvise+0x1a/0x20
[27430.058706]  ? __x64_sys_madvise+0x1a/0x20
[27430.058709]  do_syscall_64+0x57/0x190
[27430.058710]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[27430.058712] RIP: 0033:0x7f65b1d61bdb
[27430.058716] Code: Bad RIP value.
[27430.058717] RSP: 002b:00007f65833ea778 EFLAGS: 00000246 ORIG_RAX: 000000000000001c
[27430.058718] RAX: ffffffffffffffda RBX: 000000000017ea10 RCX: 00007f65b1d61bdb
[27430.058719] RDX: 0000000000000004 RSI: 000000000015e000 RDI: 00007f650c405000
[27430.058719] RBP: 00007f650c000020 R08: 0000000000000007 R09: 00007f650c0008d0
[27430.058720] R10: 00007f650c0008d0 R11: 0000000000000246 R12: 000000000015e000
[27430.058720] R13: 0000000000405000 R14: 00007f650c000000 R15: 00007f650c3e45f0
[27430.058723] INFO: task s3backer:1388 blocked for more than 120 seconds.
[27430.059287]       Tainted: P           O      5.4.0-96-generic #109-Ubuntu
[27430.059896] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[27430.060576] s3backer        D    0  1388      1 0x00000000
[27430.060578] Call Trace:
[27430.060582]  __schedule+0x2e3/0x740
[27430.060584]  ? __switch_to_asm+0x40/0x70
[27430.060585]  ? __switch_to_asm+0x34/0x70
[27430.060586]  schedule+0x42/0xb0
[27430.060588]  rwsem_down_read_slowpath+0x16c/0x4a0
[27430.060589]  down_read+0x85/0xa0
[27430.060592]  do_user_addr_fault+0x38d/0x450
[27430.060593]  __do_page_fault+0x58/0x90
[27430.060595]  ? exit_to_usermode_loop+0x8f/0x160
[27430.060596]  do_page_fault+0x2c/0xe0
[27430.060598]  do_async_page_fault+0x39/0x70
[27430.060600]  async_page_fault+0x34/0x40
[27430.060601] RIP: 0033:0x7f65b1ce04fa
[27430.060603] Code: Bad RIP value.
[27430.060604] RSP: 002b:00007f6582be96a0 EFLAGS: 00010206
[27430.060605] RAX: 0000000000000a91 RBX: 00007f64f8000020 RCX: 00007f64f857f570
[27430.060605] RDX: 00007f65b1e31b80 RSI: 00000000000800c4 RDI: 00000000005ce000
[27430.060606] RBP: 00000000000800c5 R08: 00007f64f84ff4c0 R09: 0000000000573000
[27430.060606] R10: 00007f64f8573000 R11: fffffffffffff000 R12: 0000000000073b50
[27430.060607] R13: 0000000000001000 R14: 00007f64f84ff4b0 R15: 00000000000800e0
[27430.060609] INFO: task s3backer:1389 blocked for more than 120 seconds.
[27430.061378]       Tainted: P           O      5.4.0-96-generic #109-Ubuntu
[27430.062530] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[27430.063724] s3backer        D    0  1389      1 0x00000000
[27430.063727] Call Trace:
[27430.063733]  __schedule+0x2e3/0x740
[27430.063735]  ? __switch_to_asm+0x40/0x70
[27430.063736]  ? __switch_to_asm+0x34/0x70
[27430.063738]  schedule+0x42/0xb0
[27430.063741]  rwsem_down_read_slowpath+0x16c/0x4a0
[27430.063743]  down_read+0x85/0xa0
[27430.063746]  do_user_addr_fault+0x38d/0x450
[27430.063748]  __do_page_fault+0x58/0x90
[27430.063751]  ? exit_to_usermode_loop+0x8f/0x160
[27430.063752]  do_page_fault+0x2c/0xe0
[27430.063754]  do_async_page_fault+0x39/0x70
[27430.063756]  async_page_fault+0x34/0x40
[27430.063758] RIP: 0033:0x7f65b1dd48e9
[27430.063762] Code: Bad RIP value.
[27430.063762] RSP: 002b:00007f65823e8618 EFLAGS: 00010202
[27430.063764] RAX: 000056443c33d25e RBX: 000056443beba330 RCX: 000056443c1fd612
[27430.063764] RDX: 0000000000003fa2 RSI: 000056443c1f9690 RDI: 000056443c33d25e
[27430.063765] RBP: 0000000000000004 R08: 0000000000000015 R09: 000056443c341260
[27430.063766] R10: 0000000000000000 R11: 000056443c341275 R12: 000056443beba330
[27430.063767] R13: 00007f65b22476c0 R14: 00007f65823e86e0 R15: 0000000000004037
[27430.063771] INFO: task s3backer:1395 blocked for more than 120 seconds.
[27430.064791]       Tainted: P           O      5.4.0-96-generic #109-Ubuntu
[27430.065530] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[27430.066319] s3backer        D    0  1395      1 0x00000000
[27430.066321] Call Trace:
[27430.066324]  __schedule+0x2e3/0x740
[27430.066325]  schedule+0x42/0xb0
[27430.066326]  rwsem_down_read_slowpath+0x16c/0x4a0
[27430.066328]  down_read+0x85/0xa0
[27430.066330]  __do_sys_madvise+0x774/0xb30
[27430.066332]  ? vfs_read+0x12e/0x160
[27430.066333]  ? fput+0x13/0x20
[27430.066334]  __x64_sys_madvise+0x1a/0x20
[27430.066335]  ? __x64_sys_madvise+0x1a/0x20
[27430.066336]  do_syscall_64+0x57/0x190
[27430.066337]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[27430.066338] RIP: 0033:0x7f65b1d61bdb
[27430.066340] Code: Bad RIP value.
[27430.066340] RSP: 002b:00007f657f3e2778 EFLAGS: 00000246 ORIG_RAX: 000000000000001c
[27430.066341] RAX: ffffffffffffffda RBX: 0000000000123bc0 RCX: 00007f65b1d61bdb
[27430.066342] RDX: 0000000000000004 RSI: 0000000000103000 RDI: 00007f64ec3f9000
[27430.066342] RBP: 00007f64ec000020 R08: 0000000000000007 R09: 00007f65b1e31b80
[27430.066343] R10: 0000000000000007 R11: 0000000000000246 R12: 0000000000103000
[27430.066343] R13: 00000000003f9000 R14: 00007f64ec000000 R15: 00007f64ec3d8440

My config is:

# s3backer config

# Geometry
--size=2000t
--blockSize=512k

# Credentials
--vhost
--accessFile=/etc/s3backer-credentials.conf
--baseURL=https://s3.fr-par.scw.cloud/
--authVersion=aws2

# List blocks on startup
--listBlocks
--listBlocksThreads=16

# Encryption
--ssl
--encrypt
--passwordFile=/etc/s3backer-passwd

# Block cache
--blockCacheFile=/var/cache/s3backer-cachefile
--blockCacheRecoverDirtyBlocks
--blockHashPrefix

# Misc
--timeout=300

Even when manually mounting the filesystem, it takes 8mn to get up:

11:58:55 scw-s3backer kernel: [ 7379.037125] XFS (loop0): Mounting V5 Filesystem
11:58:58 scw-s3backer kernel: [ 7382.100197] XFS (loop0): Ending clean mount
12:06:02 scw-s3backer kernel: [ 7806.032660] xfs filesystem being mounted at /mnt/s3b/xfs supports timestamps until 2038 (0x7fffffff)

I've read https://github.com/archiecobbs/s3backer/wiki/Creating-a-New-Filesystem and the note:

Important: the number of blocks that have to be written to initialize a filesystem (and therefore the amount of time it takes) depends entirely on the filesystem. Use --listBlocks to ensure that if any of those blocks are all zeroes, no network traffic has to occur. Otherwise, the filesystem initialization could take hours.

and so, should this be considered "normal"?

System is a 4 vCPU with 8Gb RAM and 80Gb SSD under Ubuntu 20.04 with Kernel 5.4.0-96-generic.

[solracsf]

It also causes a long WAIT; is this related to my settings in any way?

top - 10:46:06 up 50 min,  2 users,  load average: 4.83, 5.37, 4.82
Tasks: 147 total,   1 running, 146 sleeping,   0 stopped,   0 zombie
%Cpu(s): 11.5 us, 11.0 sy,  0.0 ni, 25.5 id, 50.8 wa,  0.0 hi,  1.0 si,  0.2 st

System is running s3backer only, and i'm rsyncing from a remote system to the mounted s3backer filesystem (to test concurrent writes)

[archiecobbs]

Not sure how XFS behaves on first mount. It may just be doing a bunch of I/O that's taking a long time.

The default block cache size is very small (1000 blocks). Try increasing the size with ---blockCacheSize (changing this value will preserve your existing cache file) and also configuring a --blockCacheWriteDelay so you get write-back instead of write-through for less cache churn.

You might also try running s3backer in the foreground with -f --debug so you can see what it's doing (if anything). Is it doing a bunch of I/O for 10 minutes or just sitting there? Is the backend responding in a timely manner?

If you keep seeing this you might also enable --http-debug (or just --debug with latest git version) to see what problem is being reported:

rec'd 500 response: GET https://s3backer-cloudeezy.s3.fr-par.scw.cloud/62a3cbc3-6c3ffff9

[solracsf]

Thanks, i'll do a bit more tests and debugging on this.

[solracsf]

Ok I think the problem was a dependency on systemd-resolved.service After set it, boot time is now normal.

Closing.