Hung task timeout reported by CI

[plbossart]

https://sof-ci.sh.intel.com/#/result/planresultdetail/9293?model=CML_SKU0955_HDA&testcase=multiple-pause-resume-50

https://sof-ci.sh.intel.com/#/result/planresultdetail/9293?model=TGLH_SKU0A70_HDA&testcase=volume-basic-test-50

.===========================>>
[ 3318.829119] kernel: INFO: task kworker/u16:0:17963 blocked for more than 122 seconds.
[ 3318.829227] kernel: Not tainted 5.16.0-rc1-daily-default-20220111-0 #55744127
[ 3318.829239] kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
<<===========================

[marc-hb]

A few weeks ago I spent some time investigating a similar report for a volume-basic-test. My preliminary conclusion was that the storage was overwhelmed by the volume of kernel logs.

• https://sof-ci.01.org/sofpr/PR5343/build11983/devicetest/?model=CML_SKU0955_HDA&testcase=multiple-pipeline-playback
• https://sof-ci.01.org/linuxpr/PR3338/build7152/devicetest/?model=CML_SKU0955_HDA&testcase=check-playback-3times
• daily 10105?model=TGLU_SKU0A32_SDCA&testcase=check-kmod-load-unload-25
• daily 10221?model=TGLU_SKU0A3E_SDW&testcase=multiple-pause-resume-50
• https://sof-ci.01.org/softestpr/PR861/build982/devicetest/?model=CML_SKU0955_HDA&testcase=multiple-pipeline-playback
• https://sof-ci.01.org/softestpr/PR903/build21/devicetest/?model=CML_SKU0955_HDA&testcase=check-pause-resume-playback-10

[kv2019i]

(comment deleted, this is with HDA so not related to #3392 )

[marc-hb]

Just found by chance that journald.conf has some rate limit options, worth a try.

[marc-hb]

My preliminary conclusion was that the storage was overwhelmed by the volume of kernel logs.

Another side effect: on some devices we have less than 1 week of logs:

jf-cml-hel-rt5682-02 $ journalctl --disk-usage
Archived and active journals take up 3.6G in the file system.

jf-cml-hel-rt5682-02 $  journalctl -b| head
-- Logs begin at Sat 2022-02-05 20:51:08 UTC, end at Fri 2022-02-11 23:31:14 UTC. --

Would some log level tuning make sense?

cc: @fredoh9 , @keqiaozhang , @aiChaoSONG , @kv2019i

[plbossart]

new one: https://sof-ci.01.org/linuxpr/PR3338/build7152/devicetest/?model=CML_SKU0955_HDA&testcase=check-playback-3times

looks like file system issues again

[  246.845593] kernel: INFO: task kworker/u16:3:87 blocked for more than 122 seconds.
[  246.845793] kernel:       Not tainted 5.16.0-rc1-pr3338-7152-default #35fa8225
[  246.845825] kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  246.845858] kernel: task:kworker/u16:3   state:D stack:12752 pid:   87 ppid:     2 flags:0x00004000
[  246.845878] kernel: Workqueue: writeback wb_workfn (flush-259:0)
[  246.845897] kernel: Call Trace:
[  246.845901] kernel:  
[  246.845913] kernel:  __schedule+0x2ac/0x850
[  246.845936] kernel:  schedule+0x49/0xc0
[  246.845947] kernel:  io_schedule+0x36/0x60
[  246.845957] kernel:  blk_mq_get_tag+0x117/0x280
[  246.845970] kernel:  ? lock_release+0x148/0x3f0
[  246.845979] kernel:  ? wait_woken+0x70/0x70
[  246.845993] kernel:  __blk_mq_alloc_requests+0x15e/0x2a0
[  246.846010] kernel:  blk_mq_submit_bio+0x1f6/0x810
[  246.846033] kernel:  submit_bio_noacct+0x254/0x2a0
[  246.846049] kernel:  ext4_io_submit+0x44/0x50
[  246.846059] kernel:  ext4_bio_write_page+0x145/0x3e0
[  246.846073] kernel:  mpage_submit_page+0x49/0x60
[  246.846084] kernel:  mpage_process_page_bufs+0xfc/0x110
[  246.846139] kernel:  mpage_prepare_extent_to_map+0x1d3/0x2b0
[  246.846178] kernel:  ext4_writepages+0x30c/0xeb0
[  246.846202] kernel:  ? __lock_acquire.isra.0+0x125/0x550
[  246.846238] kernel:  do_writepages+0xba/0x180
[  246.846253] kernel:  ? find_held_lock+0x32/0x90
[  246.846267] kernel:  ? sched_clock_cpu+0xd/0xd0
[  246.846285] kernel:  __writeback_single_inode+0x66/0x420
[  246.846307] kernel:  writeback_sb_inodes+0x20f/0x4d0
[  246.846341] kernel:  __writeback_inodes_wb+0x47/0xe0
[  246.846360] kernel:  wb_writeback+0x2da/0x360
[  246.846386] kernel:  wb_workfn+0x38c/0x520
[  246.846423] kernel:  process_one_work+0x291/0x530
[  246.846453] kernel:  worker_thread+0x48/0x3d0
[  246.846470] kernel:  ? process_one_work+0x530/0x530
[  246.846483] kernel:  kthread+0x175/0x1a0
[  246.846500] kernel:  ? set_kthread_struct+0x40/0x40
[  246.846520] kernel:  ret_from_fork+0x1f/0x30
[  246.846560] kernel:  
[  246.846607] kernel: 
                       Showing all locks held in the system:

[keqiaozhang]

Another one:
http://sof-ci.sh.intel.com/#/result/planresultdetail/10270?model=CML_SKU0955_HDA&testcase=volume-basic-test-50

2022-02-16 23:32:04 UTC [ERROR] Caught kernel log error
===========================>>
[ 3564.574060] kernel: INFO: task systemd-journal:256 blocked for more than 368 seconds.
[ 3564.574106] kernel:       Not tainted 5.16.0-rc1-daily-default-20220216-0 #5eef692b
[ 3564.574139] kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 3564.574528] kernel: INFO: task kworker/u16:5:355 blocked for more than 368 seconds.
[ 3564.574561] kernel:       Not tainted 5.16.0-rc1-daily-default-20220216-0 #5eef692b
[ 3564.574594] kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

[plbossart]

Another one: http://sof-ci.sh.intel.com/#/result/planresultdetail/10270?model=CML_SKU0955_HDA&testcase=volume-basic-test-50

2022-02-16 23:32:04 UTC [ERROR] Caught kernel log error
===========================>>
[ 3564.574060] kernel: INFO: task systemd-journal:256 blocked for more than 368 seconds.
[ 3564.574106] kernel:       Not tainted 5.16.0-rc1-daily-default-20220216-0 #5eef692b
[ 3564.574139] kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 3564.574528] kernel: INFO: task kworker/u16:5:355 blocked for more than 368 seconds.
[ 3564.574561] kernel:       Not tainted 5.16.0-rc1-daily-default-20220216-0 #5eef692b
[ 3564.574594] kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

yes, but look further and it's again ext4 locking issues. Nothing apparently to do with SOF.

[marc-hb]

Here's another interesting issue that happened in daily 11687?model=TGLH_SKU0A70_HDA&testcase=volume-basic-test-50

  < huge volume of logs >
 250636 Apr 07 22:23:09 sh-tglh-0a70-hda-01 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc3_hda_dai_trigger: cmd=3
 250637 Apr 07 22:23:09 sh-tglh-0a70-hda-01 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
 250638 Apr 07 22:23:09 sh-tglh-0a70-hda-01 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x80010000: GLB_DAI_MSG: CONFIG
 250639 Apr 07 22:23:09 sh-tglh-0a70-hda-01 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda_link_dma_trigger: cmd=4
 250640 Apr 07 22:23:09 sh-tglh-0a70-hda-01 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc3_hda_dai_trigger: cmd=4
 250641 Apr 07 22:59:03 sh-tglh-0a70-hda-01 systemd-journald[330]: Missed 77443 kernel messages
 250642 Apr 07 22:59:03 sh-tglh-0a70-hda-01 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
 250643 Apr 07 22:59:03 sh-tglh-0a70-hda-01 systemd-journald[330]: Missed 2 kernel messages
 250644 Apr 07 22:59:03 sh-tglh-0a70-hda-01 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
 250645 Apr 07 22:59:03 sh-tglh-0a70-hda-01 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
 250646 Apr 07 22:59:03 sh-tglh-0a70-hda-01 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
 250647 Apr 07 22:59:03 sh-tglh-0a70-hda-01 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
 250648 Apr 07 22:59:03 sh-tglh-0a70-hda-01 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
 250649 Apr 07 22:59:03 sh-tglh-0a70-hda-01 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
   < huge volume of logs >

Note the 35 minutes gap!

@plbossart is there an easy way to reduce the log volume of this test? sof-logger has the ability to fine-tune per component log levels at run time silly me these are kernel logs.

Tracepoints maybe? #3482

[plbossart]

Indeed this GLB_TRACE_MSG: DMA_POSITION is not very useful, we should check if we can remove it.