Strange kernel info

[imsodin (Simon)]

Syncthing is running fine with pid 10336 before and after the following kernel messages. Apart from these message, I see no evidence of another syncthing process with pid 10421.So there is no actual problem for me right know, still I wonder: Does anyone know what the following might mean and whether I need to care?

Kernel messages in reverse time order:

Feb 10 23:48:17 homeserver kernel:  [<ffffffff937f9c3b>] ? system_call_fast_compare_end+0xc/0x9b
Feb 10 23:48:17 homeserver kernel:  [<ffffffff9343630c>] ? SyS_fsync+0xc/0x10
Feb 10 23:48:17 homeserver kernel:  [<ffffffff93436098>] ? do_fsync+0x38/0x60
Feb 10 23:48:17 homeserver kernel:  [<ffffffffc03e1ca5>] ? ext4_sync_file+0x1a5/0x380 [ext4]
Feb 10 23:48:17 homeserver kernel:  [<ffffffff932b8ca0>] ? prepare_to_wait_event+0xf0/0xf0
Feb 10 23:48:17 homeserver kernel:  [<ffffffffc03cb603>] ? jbd2_log_wait_commit+0x93/0x110 [jbd2]
Feb 10 23:48:17 homeserver kernel:  [<ffffffff937f5382>] ? schedule+0x32/0x80
Feb 10 23:48:17 homeserver kernel:  [<ffffffff937f4eb3>] ? __schedule+0x233/0x6d0
Feb 10 23:48:17 homeserver kernel: Call Trace:
Feb 10 23:48:17 homeserver kernel:  0000000000000246 ffff8c9fefd58300 ffff8c9fe1deb088 ffff8c9f70420080
Feb 10 23:48:17 homeserver kernel:  ffff8c9f8fc81240 ffff9ca38bcafe60 ffffffff937f4eb3 ffff8c9fe1deb0a0
Feb 10 23:48:17 homeserver kernel:  ffff8c9fe35f9800 ffff8c9fe35f9800 ffff8c9f70420080 ffff8c9fefd58300
Feb 10 23:48:17 homeserver kernel: syncthing       D    0 10421      1 0x00000000
Feb 10 23:48:17 homeserver kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Feb 10 23:48:17 homeserver kernel:       Not tainted 4.9.0-1-amd64 #1
Feb 10 23:48:17 homeserver kernel: INFO: task syncthing:10421 blocked for more than 120 seconds.
Feb 10 23:46:16 homeserver kernel:  [<ffffffff937f9c3b>] ? system_call_fast_compare_end+0xc/0x9b
Feb 10 23:46:16 homeserver kernel:  [<ffffffff9343630c>] ? SyS_fsync+0xc/0x10
Feb 10 23:46:16 homeserver kernel:  [<ffffffff93436098>] ? do_fsync+0x38/0x60
Feb 10 23:46:16 homeserver kernel:  [<ffffffffc03e1ca5>] ? ext4_sync_file+0x1a5/0x380 [ext4]
Feb 10 23:46:16 homeserver kernel:  [<ffffffff932b8ca0>] ? prepare_to_wait_event+0xf0/0xf0
Feb 10 23:46:16 homeserver kernel:  [<ffffffffc03cb603>] ? jbd2_log_wait_commit+0x93/0x110 [jbd2]
Feb 10 23:46:16 homeserver kernel:  [<ffffffff937f5382>] ? schedule+0x32/0x80
Feb 10 23:46:16 homeserver kernel:  [<ffffffff937f4eb3>] ? __schedule+0x233/0x6d0
Feb 10 23:46:16 homeserver kernel: Call Trace:
Feb 10 23:46:16 homeserver kernel:  0000000000000246 ffff8c9fefd58300 ffff8c9fe1deb088 ffff8c9f70420080
Feb 10 23:46:16 homeserver kernel:  ffff8c9f8fc81240 ffff9ca38bcafe60 ffffffff937f4eb3 ffff8c9fe1deb0a0
Feb 10 23:46:16 homeserver kernel:  ffff8c9fe35f9800 ffff8c9fe35f9800 ffff8c9f70420080 ffff8c9fefd58300
Feb 10 23:46:16 homeserver kernel: syncthing       D    0 10421      1 0x00000000
Feb 10 23:46:16 homeserver kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Feb 10 23:46:16 homeserver kernel:       Not tainted 4.9.0-1-amd64 #1
Feb 10 23:46:16 homeserver kernel: INFO: task syncthing:10421 blocked for more than 120 seconds.

[AudriusButkevicius]

It happens on fsync, which implies your storage is either in trouble or slow and we are flushing a lot of writes (like alot alot 120s worth of disk writes)

[AudriusButkevicius]

Actually, the interwebs are telling me it could just be a Xen’s domU kernel magic, if you are running in a VM.

[imsodin (Simon)]

No VMs involved, just a plain debian stretch. The periodic smartmontool checks don’t report any problems, so hopefully nothing is dying almost silently. And I just saw that one core was on 70% io wait and my data disk on near 100% utilization for 20min covering the time of these kernel messages. Unfortunately I don’t know what syncthing was doing then, there is nothing in the logs. Well, I guess I will just wait and see, hoping that it doesn’t come up again.

[AudriusButkevicius]

Well from the kernel logs it seems we are just flushing the dirty pages, which implies we might have downloaded a big file, and asking the kernel just to actually flush it to disk.