canonical-ubuntu-qa team mailing list archive

Thread
Date
[Bug 2057886] [NEW] prio-inv from ubuntu_stress_smoke_test hangs on GCP g1-small with 5.4 / 4.15 / 4.4 lowlatency

To: canonical-ubuntu-qa@xxxxxxxxxxxxxxxxxxx
From: Po-Hsu Lin <2057886@xxxxxxxxxxxxxxxxxx>
Date: Thu, 14 Mar 2024 08:10:14 -0000
Reply-to: Bug 2057886 <2057886@xxxxxxxxxxxxxxxxxx>
Sender: noreply@xxxxxxxxxxxxx
Public bug reported:

Issue found exclusively on GCP "g1-small" instance with the following kernels:
  * X 4.4.0-252.286 lowlatency (cycle
  * X-hwe 4.15.0-223.235~16.04.1 lowlatency (s2024.02.05 cycle)
  * F 5.4.0-175.195 lowlatency (2024.03.04 cycle)

It looks like it's not 100% reproducible as it has passed with
  * B-lowlatency 4.15.0-223.235 (s2024.02.05 cycle)
  * F 5.4.0-174.193 lowlatency (s2024.02.05 cycle)

When this happens, test will be interrupted:
14:49:12 INFO |     START    ubuntu_stress_smoke_test.prio-inv    ubuntu_stress_smoke_test.prio-inv    timestamp=1710254952    timeout=2100    localtime=Mar 12 14:49:12     14:49:12 DEBUG| Persistent state client._record_indent now set to 2
14:49:12 DEBUG| Persistent state client.unexpected_reboot now set to ('ubuntu_stress_smoke_test.prio-inv', 'ubuntu_stress_smoke_test.prio-inv')
14:49:12 DEBUG| Waiting for pid 12620 for 2100 seconds
14:49:12 DEBUG| Running '/home/ubuntu/autotest/client/tests/ubuntu_stress_smoke_test/ubuntu_stress_single_smoke_test.sh prio-inv'
14:49:12 DEBUG| [stdout] Free memory: 1217 MB
14:49:12 DEBUG| [stdout] Memory used: 705 MB
14:49:12 DEBUG| [stdout] Using cgroup version 1 
14:49:12 ERROR| [stderr] /home/ubuntu/autotest/client/tests/ubuntu_stress_smoke_test/ubuntu_stress_single_smoke_test.sh: line 32: [: too many arguments
14:49:12 DEBUG| [stdout]  
14:49:12 DEBUG| [stdout] Machine Configuration
14:49:12 DEBUG| [stdout] Physical Pages:  431526
14:49:12 DEBUG| [stdout] Pages available: 311706
14:49:12 DEBUG| [stdout] Page Size:       4096
14:49:12 DEBUG| [stdout] Zswap enabled:   Y
14:49:12 DEBUG| [stdout]  
14:49:12 DEBUG| [stdout] Free memory:
14:49:12 DEBUG| [stdout]               total        used        free      shared  buff/cache   available
14:49:12 DEBUG| [stdout] Mem:        1726104      134820     1246824       11344      344460     1328560
14:49:12 DEBUG| [stdout] Swap:       1048572         512     1048060
14:49:12 DEBUG| [stdout]  
14:49:12 DEBUG| [stdout] Number of CPUs: 1
14:49:12 DEBUG| [stdout] Number of CPUs Online: 1
14:49:12 DEBUG| [stdout] 
14:49:12 DEBUG| [stdout] Maximum bogo ops: 3000 
14:49:12 DEBUG| [stdout]  
14:49:12 DEBUG| [stdout] prio-inv STARTING
(system disconnects here)
rsync: connection unexpectedly closed (0 bytes received so far) [Receiver] 
rsync error: unexplained error (code 255) at io.c(231) [Receiver=3.2.7]

Here is the collected console log:
Mar 14 07:42:15 f-l-ll-5-4-g1sml-u-stress-smk-test systemd[1]: Finished GCE Workload Certificate refresh.^M
Mar 14 07:42:24 f-l-ll-5-4-g1sml-u-stress-smk-test systemd[1]: Started Session 7 of user ubuntu.^M
Mar 14 07:46:04 f-l-ll-5-4-g1sml-u-stress-smk-test PackageKit: daemon quit^M
Mar 14 07:46:04 f-l-ll-5-4-g1sml-u-stress-smk-test systemd[1]: packagekit.service: Succeeded.^M
Mar 14 07:48:28 [ 1847.057112] INFO: task jbd2/sda1-8:280 blocked for more than 123 seconds.^M
[ 1847.067198]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 1847.073489] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 1847.081740] INFO: task kworker/u2:1:17304 blocked for more than 123 seconds.^M
[ 1850.064409]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 1850.070514] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 1973.046096] INFO: task jbd2/sda1-8:280 blocked for more than 249 seconds.^M
[ 1973.061945]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 1976.044464] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 1976.053184] INFO: task systemd-journal:355 blocked for more than 128 seconds.^M
[ 1976.060673]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 1976.066844] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 1982.044713] INFO: task rs:main Q:Reg:719 blocked for more than 134 seconds.^M
[ 1982.052278]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 1982.058451] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 1982.066722] INFO: task kworker/u2:1:17304 blocked for more than 258 seconds.^M
[ 1985.063183]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 1988.047580] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 2114.030688] INFO: task jbd2/sda1-8:280 blocked for more than 390 seconds.^M
[ 2114.038876]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 2114.045149] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 2114.053295] INFO: task systemd-journal:355 blocked for more than 266 seconds.^M
[ 2117.036368]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 2117.042507] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 2117.050832] INFO: task rs:main Q:Reg:719 blocked for more than 269 seconds.^M
[ 2120.034201]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 2120.040333] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 2120.048505] INFO: task kworker/u2:1:17304 blocked for more than 396 seconds.^M
[ 2123.035654]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 2123.041809] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M

** Affects: ubuntu-kernel-tests
     Importance: Undecided
         Status: New


** Tags: 4.15 4.4 5.4 focal gcp sru-20240304 sru-s20240205 ubuntu-stress-smoke-test xenial

-- 
You received this bug notification because you are a member of Canonical
Platform QA Team, which is subscribed to ubuntu-kernel-tests.
https://bugs.launchpad.net/bugs/2057886

Title:
  prio-inv from ubuntu_stress_smoke_test hangs on GCP g1-small with 5.4
  / 4.15 / 4.4 lowlatency

Status in ubuntu-kernel-tests:
  New

Bug description:
  Issue found exclusively on GCP "g1-small" instance with the following kernels:
    * X 4.4.0-252.286 lowlatency (cycle
    * X-hwe 4.15.0-223.235~16.04.1 lowlatency (s2024.02.05 cycle)
    * F 5.4.0-175.195 lowlatency (2024.03.04 cycle)

  It looks like it's not 100% reproducible as it has passed with
    * B-lowlatency 4.15.0-223.235 (s2024.02.05 cycle)
    * F 5.4.0-174.193 lowlatency (s2024.02.05 cycle)

  When this happens, test will be interrupted:
  14:49:12 INFO |     START    ubuntu_stress_smoke_test.prio-inv    ubuntu_stress_smoke_test.prio-inv    timestamp=1710254952    timeout=2100    localtime=Mar 12 14:49:12     14:49:12 DEBUG| Persistent state client._record_indent now set to 2
  14:49:12 DEBUG| Persistent state client.unexpected_reboot now set to ('ubuntu_stress_smoke_test.prio-inv', 'ubuntu_stress_smoke_test.prio-inv')
  14:49:12 DEBUG| Waiting for pid 12620 for 2100 seconds
  14:49:12 DEBUG| Running '/home/ubuntu/autotest/client/tests/ubuntu_stress_smoke_test/ubuntu_stress_single_smoke_test.sh prio-inv'
  14:49:12 DEBUG| [stdout] Free memory: 1217 MB
  14:49:12 DEBUG| [stdout] Memory used: 705 MB
  14:49:12 DEBUG| [stdout] Using cgroup version 1 
  14:49:12 ERROR| [stderr] /home/ubuntu/autotest/client/tests/ubuntu_stress_smoke_test/ubuntu_stress_single_smoke_test.sh: line 32: [: too many arguments
  14:49:12 DEBUG| [stdout]  
  14:49:12 DEBUG| [stdout] Machine Configuration
  14:49:12 DEBUG| [stdout] Physical Pages:  431526
  14:49:12 DEBUG| [stdout] Pages available: 311706
  14:49:12 DEBUG| [stdout] Page Size:       4096
  14:49:12 DEBUG| [stdout] Zswap enabled:   Y
  14:49:12 DEBUG| [stdout]  
  14:49:12 DEBUG| [stdout] Free memory:
  14:49:12 DEBUG| [stdout]               total        used        free      shared  buff/cache   available
  14:49:12 DEBUG| [stdout] Mem:        1726104      134820     1246824       11344      344460     1328560
  14:49:12 DEBUG| [stdout] Swap:       1048572         512     1048060
  14:49:12 DEBUG| [stdout]  
  14:49:12 DEBUG| [stdout] Number of CPUs: 1
  14:49:12 DEBUG| [stdout] Number of CPUs Online: 1
  14:49:12 DEBUG| [stdout] 
  14:49:12 DEBUG| [stdout] Maximum bogo ops: 3000 
  14:49:12 DEBUG| [stdout]  
  14:49:12 DEBUG| [stdout] prio-inv STARTING
  (system disconnects here)
  rsync: connection unexpectedly closed (0 bytes received so far) [Receiver] 
  rsync error: unexplained error (code 255) at io.c(231) [Receiver=3.2.7]

  Here is the collected console log:
  Mar 14 07:42:15 f-l-ll-5-4-g1sml-u-stress-smk-test systemd[1]: Finished GCE Workload Certificate refresh.^M
  Mar 14 07:42:24 f-l-ll-5-4-g1sml-u-stress-smk-test systemd[1]: Started Session 7 of user ubuntu.^M
  Mar 14 07:46:04 f-l-ll-5-4-g1sml-u-stress-smk-test PackageKit: daemon quit^M
  Mar 14 07:46:04 f-l-ll-5-4-g1sml-u-stress-smk-test systemd[1]: packagekit.service: Succeeded.^M
  Mar 14 07:48:28 [ 1847.057112] INFO: task jbd2/sda1-8:280 blocked for more than 123 seconds.^M
  [ 1847.067198]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
  [ 1847.073489] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
  [ 1847.081740] INFO: task kworker/u2:1:17304 blocked for more than 123 seconds.^M
  [ 1850.064409]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
  [ 1850.070514] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
  [ 1973.046096] INFO: task jbd2/sda1-8:280 blocked for more than 249 seconds.^M
  [ 1973.061945]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
  [ 1976.044464] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
  [ 1976.053184] INFO: task systemd-journal:355 blocked for more than 128 seconds.^M
  [ 1976.060673]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
  [ 1976.066844] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
  [ 1982.044713] INFO: task rs:main Q:Reg:719 blocked for more than 134 seconds.^M
  [ 1982.052278]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
  [ 1982.058451] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
  [ 1982.066722] INFO: task kworker/u2:1:17304 blocked for more than 258 seconds.^M
  [ 1985.063183]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
  [ 1988.047580] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
  [ 2114.030688] INFO: task jbd2/sda1-8:280 blocked for more than 390 seconds.^M
  [ 2114.038876]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
  [ 2114.045149] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
  [ 2114.053295] INFO: task systemd-journal:355 blocked for more than 266 seconds.^M
  [ 2117.036368]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
  [ 2117.042507] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
  [ 2117.050832] INFO: task rs:main Q:Reg:719 blocked for more than 269 seconds.^M
  [ 2120.034201]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
  [ 2120.040333] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
  [ 2120.048505] INFO: task kworker/u2:1:17304 blocked for more than 396 seconds.^M
  [ 2123.035654]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
  [ 2123.041809] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu-kernel-tests/+bug/2057886/+subscriptions
Follow ups

[Bug 2057886] Re: prio-inv from ubuntu_stress_smoke_test hangs on GCP g1-small with 5.4 / 4.15 / 4.4 lowlatency
From: Po-Hsu Lin, 2024-03-20
[Bug 2057886] Re: prio-inv from ubuntu_stress_smoke_test hangs on GCP g1-small with 5.4 / 4.15 / 4.4 lowlatency
From: Po-Hsu Lin, 2024-03-15
[Bug 2057886] Re: prio-inv from ubuntu_stress_smoke_test hangs on GCP g1-small with 5.4 / 4.15 / 4.4 lowlatency
From: Po-Hsu Lin, 2024-03-14
[Bug 2057886] Re: prio-inv from ubuntu_stress_smoke_test hangs on GCP g1-small with 5.4 / 4.15 / 4.4 lowlatency
From: Po-Hsu Lin, 2024-03-14