Actions
action #14804
closedencoder still stalls
Added by coolo over 7 years ago. Updated over 7 years ago.
Start date:
2016-11-24
Due date:
% Done:
100%
Estimated time:
(Total: 0.00 h)
Description
Something strange is still going on with stuck builds. The encoder part is only writing to a file by now :(
00:16:21.9731 14142 no change 18
00:16:22.9743 14142 no change 17
00:16:34.2678 14142 WARNING: enqueue_screenshot took 11.10 seconds - slow IO? (opencv: 0.01 - encoder: 11.08)
00:16:36.8034 14142 no change 3
00:16:36.8038 14142 WARNING: There is some problem with your environment, we detected a stall for 13 seconds
00:16:36.8170 14142 no change 3
00:16:37.8055 14142 no change 2
Updated by coolo over 7 years ago
Following Santi's advise I packaged and installed atop on openqaworker2 to get more details about this.
And the biggest time of tonight was:
04:51:07.5483 Debug: /var/lib/openqa/share/tests/sle/tests/qa_automation/patch_and_reboot.pm:24 called qa_run::system_login
04:51:07.5484 1457 <<< testapi::type_string(string='setterm -blank 0', max_interval=250, wait_screen_changes=0)
04:51:12.1727 1470 WARNING: enqueue_screenshot took 4.56 seconds - slow IO? (opencv: 0.01 - encoder: 4.56)
It should be noted that a parallel job had a similiar problem:
04:51:08.2241 1633 no match 190
04:51:11.9038 1633 WARNING: enqueue_screenshot took 3.67 seconds - slow IO? (opencv: 0.01 - encoder: 3.66)
Atop samples every 10 seconds, so I can only tell what happened around that time - but it doesn't look severe:
ATOP - openqaworker2 2016/11/23 05:51:04 ------------- 10s elapsed
PRC | sys 4.97s | user 2m09s | | | #proc 514 | #trun 13 | | #tslpi 761 | #tslpu 1 | | #zombie 0 | clones 151 | | | no procacct |
CPU | sys 51% | user 1470% | | irq 1% | | idle 1611% | | wait 69% | | | steal 0% | guest 369% | curf 2.24GHz | | curscal 69% |
cpu | sys 1% | user 82% | | irq 0% | | idle 16% | | cpu016 w 0% | | | steal 0% | guest 66% | curf 2.67GHz | | curscal 83% |
cpu | sys 1% | user 78% | | irq 0% | | idle 22% | | cpu015 w 0% | | | steal 0% | guest 14% | curf 2.80GHz | | curscal 87% |
cpu | sys 2% | user 67% | | irq 0% | | idle 31% | | cpu014 w 0% | | | steal 0% | guest 15% | curf 1.38GHz | | curscal 43% |
cpu | sys 1% | user 67% | | irq 0% | | idle 32% | | cpu010 w 0% | | | steal 0% | guest 0% | curf 2.78GHz | | curscal 86% |
cpu | sys 6% | user 60% | | irq 0% | | idle 34% | | cpu025 w 0% | | | steal 0% | guest 48% | curf 1.27GHz | | curscal 39% |
cpu | sys 1% | user 55% | | irq 0% | | idle 35% | | cpu002 w 9% | | | steal 0% | guest 12% | curf 2.60GHz | | curscal 81% |
cpu | sys 1% | user 54% | | irq 0% | | idle 45% | | cpu011 w 0% | | | steal 0% | guest 8% | curf 2.78GHz | | curscal 86% |
cpu | sys 1% | user 54% | | irq 0% | | idle 45% | | cpu013 w 0% | | | steal 0% | guest 15% | curf 1.50GHz | | curscal 46% |
cpu | sys 2% | user 52% | | irq 0% | | idle 46% | | cpu008 w 0% | | | steal 0% | guest 2% | curf 1.30GHz | | curscal 40% |
cpu | sys 0% | user 53% | | irq 0% | | idle 46% | | cpu027 w 0% | | | steal 0% | guest 0% | curf 2.83GHz | | curscal 88% |
cpu | sys 0% | user 51% | | irq 0% | | idle 45% | | cpu022 w 3% | | | steal 0% | guest 0% | curf 2.67GHz | | curscal 83% |
cpu | sys 1% | user 49% | | irq 0% | | idle 49% | | cpu021 w 1% | | | steal 0% | guest 31% | curf 2.40GHz | | curscal 75% |
cpu | sys 2% | user 48% | | irq 0% | | idle 48% | | cpu001 w 2% | | | steal 0% | guest 2% | curf 2.68GHz | | curscal 83% |
cpu | sys 1% | user 49% | | irq 0% | | idle 44% | | cpu004 w 6% | | | steal 0% | guest 2% | curf 2.50GHz | | curscal 78% |
cpu | sys 1% | user 48% | | irq 0% | | idle 50% | | cpu006 w 1% | | | steal 0% | guest 12% | curf 2.65GHz | | curscal 82% |
cpu | sys 2% | user 46% | | irq 0% | | idle 44% | | cpu005 w 8% | | | steal 0% | guest 5% | curf 2.40GHz | | curscal 74% |
cpu | sys 0% | user 46% | | irq 0% | | idle 52% | | cpu023 w 1% | | | steal 0% | guest 29% | curf 2.62GHz | | curscal 81% |
cpu | sys 7% | user 39% | | irq 0% | | idle 54% | | cpu024 w 0% | | | steal 0% | guest 20% | curf 1.29GHz | | curscal 40% |
cpu | sys 2% | user 44% | | irq 0% | | idle 47% | | cpu003 w 8% | | | steal 0% | guest 1% | curf 2.65GHz | | curscal 82% |
cpu | sys 1% | user 44% | | irq 0% | | idle 55% | | cpu017 w 0% | | | steal 0% | guest 0% | curf 2.60GHz | | curscal 81% |
cpu | sys 1% | user 42% | | irq 0% | | idle 46% | | cpu019 w 11% | | | steal 0% | guest 3% | curf 2.67GHz | | curscal 83% |
cpu | sys 1% | user 42% | | irq 0% | | idle 58% | | cpu012 w 0% | | | steal 0% | guest 11% | curf 1.29GHz | | curscal 40% |
cpu | sys 1% | user 42% | | irq 0% | | idle 58% | | cpu020 w 0% | | | steal 0% | guest 5% | curf 2.60GHz | | curscal 81% |
cpu | sys 1% | user 39% | | irq 0% | | idle 54% | | cpu018 w 6% | | | steal 0% | guest 1% | curf 2.68GHz | | curscal 83% |
cpu | sys 1% | user 38% | | irq 0% | | idle 54% | | cpu007 w 7% | | | steal 0% | guest 8% | curf 2.65GHz | | curscal 82% |
cpu | sys 1% | user 36% | | irq 0% | | idle 58% | | cpu028 w 5% | | | steal 0% | guest 25% | curf 1.20GHz | | curscal 37% |
cpu | sys 7% | user 29% | | irq 0% | | idle 64% | | cpu026 w 0% | | | steal 0% | guest 0% | curf 2.78GHz | | curscal 86% |
cpu | sys 1% | user 30% | | irq 0% | | idle 67% | | cpu029 w 2% | | | steal 0% | guest 0% | curf 1.59GHz | | curscal 49% |
cpu | sys 0% | user 30% | | irq 0% | | idle 70% | | cpu009 w 0% | | | steal 0% | guest 9% | curf 1.20GHz | | curscal 37% |
cpu | sys 2% | user 19% | | irq 0% | | idle 79% | | cpu031 w 0% | | | steal 0% | guest 3% | curf 2.63GHz | | curscal 82% |
cpu | sys 1% | user 19% | | irq 0% | | idle 80% | | cpu030 w 0% | | | steal 0% | guest 11% | curf 1.29GHz | | curscal 40% |
cpu | sys 1% | user 17% | | irq 1% | | idle 82% | | cpu000 w 0% | | | steal 0% | guest 10% | curf 2.62GHz | | curscal 81% |
CPL | avg1 13.45 | | avg5 13.95 | | avg15 13.57 | | | csw 227248 | | intr 87981 | | | | numcpu 32 | |
MEM | tot 251.8G | free 53.9G | cache 167.0G | dirty 1.3G | buff 1.7G | slab 4.3G | slrec 3.3G | shmem 72.7M | shrss 0.0M | shswp 0.0M | | vmbal 0.0M | | hptot 0.0M | hpuse 0.0M |
SWP | tot 2.0G | free 1.9G | | | | | | | | | | | vmcom 33.2G | vmlim 127.9G | |
MDD | md1 | busy 0% | | read 0 | write 44 | | KiB/r 0 | KiB/w 41 | | MBr/s 0.0 | MBw/s 0.2 | | avq 0.00 | avio 0.00 ms | |
DSK | sda | busy 4% | | read 0 | write 50 | | KiB/r 0 | KiB/w 37 | | MBr/s 0.0 | MBw/s 0.2 | | avq 5.17 | avio 8.56 ms | |
DSK | sdb | busy 4% | | read 0 | write 49 | | KiB/r 0 | KiB/w 37 | | MBr/s 0.0 | MBw/s 0.2 | | avq 5.01 | avio 8.41 ms | |
NFM | openqa/share | srv openqa.s | read 0K | write 0K | | nread 156.0M | nwrit 0K | | dread 0K | dwrit 0K | | mread 0K | mwrit 0K | | |
NET | transport | tcpi 6628 | tcpo 22107 | | udpi 10 | udpo 14 | tcpao 127 | tcppo 15 | | tcprs 74 | tcpie 0 | tcpor 2 | udpnp 0 | | udpie 0 |
NET | network | ipi 6748 | | ipo 6969 | ipfrw 0 | | deliv 6638 | | | | | | icmpi 0 | icmpo 0 | |
NET | eth3 0% | sp 10 Gbps | | pcki 387 | pcko 17797 | | si 20 Kbps | so 19 Mbps | | coll 0 | mlti 114 | erri 0 | erro 0 | drpi 0 | drpo 0 |
NET | bond0 0% | sp 20 Gbps | | pcki 3066 | pcko 17811 | | si 221 Kbps | so 19 Mbps | | coll 0 | mlti 257 | erri 0 | erro 0 | drpi 0 | drpo 0 |
NET | eth2 0% | sp 10 Gbps | | pcki 2679 | pcko 14 | | si 200 Kbps | so 1 Kbps | | coll 0 | mlti 143 | erri 0 | erro 0 | drpi 0 | drpo 0 |
NET | br0 ---- | sp 0 Mbps | | pcki 3066 | pcko 2585 | | si 186 Kbps | so 18 Mbps | | coll 0 | mlti 0 | erri 0 | erro 0 | drpi 0 | drpo 0 |
NET | lo ---- | sp 0 Mbps | | pcki 4384 | pcko 4384 | | si 6170 Kbps | so 6170 Kbps | | coll 0 | mlti 0 | erri 0 | erro 0 | drpi 0 | drpo 0 |
PID TID RUID EUID THR SYSCPU USRCPU VGROW RGROW RDDSK WRDSK ST EXC S CPUNR CPU CMD 1/23
965 - _openqa- _openqa- 17 0.35s 10.18s 0K 79872K 0K 99500K -- - S 4 106% qemu-system-x8
1639 - _openqa- _openqa- 8 0.89s 8.81s 272.0M 283.3M 0K 28K -- - S 13 97% qemu-system-x8
21319 - _openqa- _openqa- 2 0.02s 8.70s 3536K 3836K 0K 2288K -- - S 27 88% /usr/bin/isoto
31588 - _openqa- _openqa- 2 0.04s 8.60s 0K 0K 0K 1472K -- - S 21 87% /usr/bin/isoto
21184 - _openqa- _openqa- 2 0.05s 8.42s 2324K 2220K 0K 5956K -- - R 10 85% /usr/bin/isoto
32562 - _openqa- _openqa- 2 0.02s 8.24s 0K 0K 0K 1840K -- - R 18 83% /usr/bin/isoto
31971 - _openqa- _openqa- 11 0.02s 6.80s -8196K -8K 0K 960K -- - S 14 68% qemu-system-x8
21151 - _openqa- _openqa- 2 0.00s 6.46s 0K 0K 0K 292K -- - R 19 65% /usr/bin/isoto
21090 - _openqa- _openqa- 2 0.01s 5.63s 4140K 4140K 0K 3236K -- - R 12 57% /usr/bin/isoto
21112 - _openqa- _openqa- 13 1.54s 3.60s 40980K 2048K 8K 929.4M -- - S 12 52% qemu-system-x8
1470 - _openqa- _openqa- 2 0.03s 5.07s 46048K 46048K 0K 172K -- - R 7 51% /usr/bin/isoto
21190 - _openqa- _openqa- 27 0.06s 4.72s 128.1M 6112K 0K 5144K -- - S 13 48% qemu-system-x8
21205 - _openqa- _openqa- 8 0.09s 4.59s -8196K -24K 0K 5196K -- - S 22 47% qemu-system-x8
1633 - _openqa- _openqa- 2 0.05s 2.98s 22904K 22972K 0K 1524K -- - S 5 30% /usr/bin/isoto
21201 - _openqa- _openqa- 2 0.01s 2.65s 0K 0K 0K 312K -- - S 4 27% videoencoder
31590 - _openqa- _openqa- 2 0.00s 2.47s 0K 0K 0K 164K -- - S 20 25% videoencoder
32564 - _openqa- _openqa- 2 0.00s 2.20s 0K 0K 0K 816K -- - S 5 22% videoencoder
961 - _openqa- _openqa- 2 0.00s 2.15s 284K 416K 0K 1072K -- - R 11 22% videoencoder
21199 - _openqa- _openqa- 2 0.00s 2.14s 15364K 15360K 0K 4208K -- - S 4 21% /usr/bin/isoto
21186 - _openqa- _openqa- 2 0.00s 2.10s 0K 0K 0K 96K -- - S 9 21% videoencoder
1635 - _openqa- _openqa- 2 0.01s 2.04s 400K 17192K 0K 500K -- - S 8 21% videoencoder
21103 - _openqa- _openqa- 2 0.00s 1.76s 0K 0K 0K 0K -- - S 13 18% videoencoder
21153 - _openqa- _openqa- 2 0.00s 1.75s 0K 0K 0K 28K -- - R 9 18% videoencoder
21257 - _openqa- _openqa- 2 0.00s 1.74s 0K 0K 0K 0K -- - S 12 17% videoencoder
31967 - _openqa- _openqa- 2 0.00s 1.69s 0K 0K 0K 180K -- - S 4 17% videoencoder
21321 - _openqa- _openqa- 2 0.00s 1.59s 0K 0K 0K 60K -- - R 31 16% videoencoder
21096 - _openqa- _openqa- 2 0.00s 1.56s 0K 0K 0K 48K -- - S 9 16% videoencoder
1473 - _openqa- _openqa- 2 0.00s 1.52s 0K 0K 0K 4K -- - S 8 15% videoencoder
1816 - _openqa- _openqa- 1 0.00s 1.44s 14336K 4380K 0K 128K N- - R 1 14% optipng
21157 - _openqa- _openqa- 5 0.86s 0.51s 0K 0K 0K 565.8M -- - S 3 14% qemu-system-x8
21325 - _openqa- _openqa- 11 0.05s 1.26s 24588K 0K 0K 3852K -- - S 8 13% qemu-system-x8
959 - _openqa- _openqa- 2 0.00s 0.97s 0K 0K 0K 992K -- - S 4 10% /usr/bin/isoto
31965 - _openqa- _openqa- 2 0.00s 0.66s 0K 0K 0K 688K -- - S 13 7% /usr/bin/isoto
1479 - _openqa- _openqa- 6 0.03s 0.58s -8196K -1772K 0K 200K -- - S 4 6% qemu-system-x8
20804 - root root 1 0.43s 0.00s 0K 0K 0K 0K -- - D 22 4% kworker/u65:0
21182 - _openqa- _openqa- 2 0.00s 0.38s 0K 0K 0K 1784K -- - S 2 4% /usr/bin/isoto
ATOP - openqaworker2 2016/11/23 05:51:14 ------------- 10s elapsed
PRC | sys 2.20s | user 97.19s | | | #proc 516 | #trun 16 | | #tslpi 730 | #tslpu 0 | | #zombie 0 | clones 91 | | | no procacct |
CPU | sys 23% | user 1209% | | irq 1% | | idle 1793% | | wait 177% | | | steal 0% | guest 304% | curf 2.29GHz | | curscal 71% |
cpu | sys 0% | user 100% | | irq 0% | | idle 0% | | cpu016 w 0% | | | steal 0% | guest 99% | curf 2.68GHz | | curscal 83% |
cpu | sys 1% | user 74% | | irq 0% | | idle 25% | | cpu008 w 0% | | | steal 0% | guest 11% | curf 2.70GHz | | curscal 84% |
cpu | sys 1% | user 62% | | irq 0% | | idle 31% | | cpu007 w 6% | | | steal 0% | guest 8% | curf 2.60GHz | | curscal 81% |
cpu | sys 1% | user 59% | | irq 0% | | idle 31% | | cpu004 w 9% | | | steal 0% | guest 5% | curf 2.68GHz | | curscal 83% |
cpu | sys 2% | user 56% | | irq 0% | | idle 36% | | cpu006 w 6% | | | steal 0% | guest 32% | curf 1.21GHz | | curscal 37% |
cpu | sys 1% | user 55% | | irq 0% | | idle 42% | | cpu011 w 2% | | | steal 0% | guest 17% | curf 2.79GHz | | curscal 87% |
cpu | sys 0% | user 55% | | irq 0% | | idle 43% | | cpu031 w 2% | | | steal 0% | guest 27% | curf 2.41GHz | | curscal 75% |
cpu | sys 1% | user 54% | | irq 0% | | idle 45% | | cpu009 w 0% | | | steal 0% | guest 6% | curf 1.23GHz | | curscal 38% |
cpu | sys 2% | user 50% | | irq 0% | | idle 45% | | cpu003 w 3% | | | steal 0% | guest 19% | curf 2.40GHz | | curscal 75% |
cpu | sys 1% | user 45% | | irq 0% | | idle 54% | | cpu010 w 0% | | | steal 0% | guest 2% | curf 1.56GHz | | curscal 48% |
cpu | sys 0% | user 43% | | irq 0% | | idle 54% | | cpu018 w 3% | | | steal 0% | guest 0% | curf 2.37GHz | | curscal 73% |
cpu | sys 1% | user 41% | | irq 0% | | idle 36% | | cpu005 w 22% | | | steal 0% | guest 2% | curf 2.30GHz | | curscal 71% |
cpu | sys 0% | user 42% | | irq 0% | | idle 57% | | cpu028 w 1% | | | steal 0% | guest 1% | curf 1.73GHz | | curscal 54% |
cpu | sys 1% | user 41% | | irq 0% | | idle 58% | | cpu014 w 0% | | | steal 0% | guest 9% | curf 2.78GHz | | curscal 87% |
cpu | sys 0% | user 38% | | irq 0% | | idle 62% | | cpu017 w 0% | | | steal 0% | guest 0% | curf 2.68GHz | | curscal 83% |
cpu | sys 1% | user 37% | | irq 0% | | idle 62% | | cpu029 w 0% | | | steal 0% | guest 15% | curf 1.90GHz | | curscal 59% |
cpu | sys 1% | user 37% | | irq 0% | | idle 58% | | cpu013 w 4% | | | steal 0% | guest 1% | curf 2.40GHz | | curscal 75% |
cpu | sys 1% | user 35% | | irq 0% | | idle 33% | | cpu001 w 31% | | | steal 0% | guest 6% | curf 2.60GHz | | curscal 81% |
cpu | sys 0% | user 36% | | irq 0% | | idle 63% | | cpu012 w 0% | | | steal 0% | guest 9% | curf 2.40GHz | | curscal 75% |
cpu | sys 1% | user 35% | | irq 0% | | idle 57% | | cpu002 w 7% | | | steal 0% | guest 3% | curf 2.40GHz | | curscal 75% |
cpu | sys 1% | user 33% | | irq 0% | | idle 62% | | cpu026 w 4% | | | steal 0% | guest 0% | curf 1.22GHz | | curscal 38% |
cpu | sys 2% | user 27% | | irq 0% | | idle 69% | | cpu015 w 2% | | | steal 0% | guest 20% | curf 2.77GHz | | curscal 86% |
cpu | sys 1% | user 25% | | irq 0% | | idle 43% | | cpu021 w 32% | | | steal 0% | guest 3% | curf 2.30GHz | | curscal 71% |
cpu | sys 0% | user 23% | | irq 0% | | idle 77% | | cpu023 w 0% | | | steal 0% | guest 0% | curf 2.68GHz | | curscal 83% |
cpu | sys 0% | user 19% | | irq 0% | | idle 70% | | cpu025 w 11% | | | steal 0% | guest 0% | curf 2.70GHz | | curscal 84% |
cpu | sys 1% | user 18% | | irq 0% | | idle 80% | | cpu030 w 1% | | | steal 0% | guest 4% | curf 1.39GHz | | curscal 43% |
cpu | sys 1% | user 16% | | irq 0% | | idle 76% | | cpu022 w 7% | | | steal 0% | guest 0% | curf 1.42GHz | | curscal 44% |
cpu | sys 1% | user 14% | | irq 0% | | idle 73% | | cpu020 w 12% | | | steal 0% | guest 3% | curf 2.66GHz | | curscal 83% |
cpu | sys 1% | user 14% | | irq 0% | | idle 82% | | cpu027 w 4% | | | steal 0% | guest 0% | curf 2.67GHz | | curscal 83% |
cpu | sys 1% | user 11% | | irq 0% | | idle 80% | | cpu024 w 9% | | | steal 0% | guest 1% | curf 2.79GHz | | curscal 87% |
cpu | sys 0% | user 10% | | irq 0% | | idle 88% | | cpu019 w 1% | | | steal 0% | guest 0% | curf 2.40GHz | | curscal 74% |
cpu | sys 0% | user 3% | | irq 0% | | idle 97% | | cpu000 w 0% | | | steal 0% | guest 0% | curf 2.63GHz | | curscal 82% |
CPL | avg1 13.46 | | avg5 13.93 | | avg15 13.57 | | | csw 75454 | | intr 77146 | | | | numcpu 32 | |
MEM | tot 251.8G | free 53.7G | cache 167.1G | dirty 247.1M | buff 1.7G | slab 4.3G | slrec 3.3G | shmem 72.7M | shrss 0.0M | shswp 0.0M | | vmbal 0.0M | | hptot 0.0M | hpuse 0.0M |
SWP | tot 2.0G | free 1.9G | | | | | | | | | | | vmcom 33.2G | vmlim 127.9G | |
MDD | md1 | busy 0% | | read 0 | write 1 | | KiB/r 0 | KiB/w 24 | | MBr/s 0.0 | MBw/s 0.0 | | avq 0.00 | avio 0.00 ms | |
DSK | sda | busy 1% | | read 0 | write 7 | | KiB/r 0 | KiB/w 5 | | MBr/s 0.0 | MBw/s 0.0 | | avq 1.18 | avio 16.0 ms | |
DSK | sdb | busy 1% | | read 0 | write 7 | | KiB/r 0 | KiB/w 5 | | MBr/s 0.0 | MBw/s 0.0 | | avq 1.18 | avio 16.0 ms | |
NFM | openqa/share | srv openqa.s | read 0K | write 0K | | nread 109.9M | nwrit 0K | | dread 0K | dwrit 0K | | mread 0K | mwrit 0K | | |
NET | transport | tcpi 5288 | tcpo 8616 | | udpi 10 | udpo 21 | tcpao 108 | tcppo 12 | | tcprs 1 | tcpie 0 | tcpor 0 | udpnp 0 | | udpie 0 |
NET | network | ipi 5448 | | ipo 5742 | ipfrw 0 | | deliv 5299 | | | | | | icmpi 1 | icmpo 1 | |
NET | eth3 0% | sp 10 Gbps | | pcki 418 | pcko 5020 | | si 26 Kbps | so 4403 Kbps | | coll 0 | mlti 72 | erri 0 | erro 0 | drpi 0 | drpo 0 |
NET | bond0 0% | sp 20 Gbps | | pcki 2566 | pcko 5044 | | si 188 Kbps | so 4406 Kbps | | coll 0 | mlti 156 | erri 0 | erro 0 | drpi 1 | drpo 0 |
NET | eth2 0% | sp 10 Gbps | | pcki 2148 | pcko 24 | | si 161 Kbps | so 2 Kbps | | coll 0 | mlti 84 | erri 0 | erro 0 | drpi 0 | drpo 0 |
NET | lo ---- | sp 0 Mbps | | pcki 3597 | pcko 3597 | | si 4683 Kbps | so 4683 Kbps | | coll 0 | mlti 0 | erri 0 | erro 0 | drpi 0 | drpo 0 |
NET | br0 ---- | sp 0 Mbps | | pcki 2564 | pcko 2146 | | si 159 Kbps | so 4206 Kbps | | coll 0 | mlti 0 | erri 0 | erro 0 | drpi 0 | drpo 0 |
PID TID RUID EUID THR SYSCPU USRCPU VGROW RGROW RDDSK WRDSK ST EXC S CPUNR CPU CMD 1/23
965 - _openqa- _openqa- 17 0.28s 10.19s 0K 73764K 0K 20060K -- - S 6 105% qemu-system-x8
32562 - _openqa- _openqa- 2 0.03s 8.88s 0K 0K 0K 1596K -- - R 17 89% /usr/bin/isoto
31588 - _openqa- _openqa- 2 0.01s 8.41s 0K 0K 0K 1544K -- - R 12 85% /usr/bin/isoto
31971 - _openqa- _openqa- 11 0.08s 6.19s 0K 0K 0K 2284K -- - S 10 63% qemu-system-x8
21091 - _openqa- _openqa- 2 0.03s 5.14s 15376K 15376K 0K 3932K -- - R 4 52% /usr/bin/isoto
21190 - _openqa- _openqa- 27 0.46s 4.67s 0K 0K 1108K 460K -- - S 10 52% qemu-system-x8
21205 - _openqa- _openqa- 7 0.08s 4.83s -8196K -8K 0K 96K -- - S 3 49% qemu-system-x8
1470 - _openqa- _openqa- 2 0.00s 4.88s 2388K 2432K 0K 116K -- - R 23 49% /usr/bin/isoto
21120 - _openqa- _openqa- 13 0.11s 4.37s 0K 4K 0K 460K -- - S 20 45% qemu-system-x8
21151 - _openqa- _openqa- 2 0.01s 2.61s 0K 0K 0K 788K -- - R 14 26% /usr/bin/isoto
1633 - _openqa- _openqa- 2 0.01s 2.25s 27100K 27100K 0K 312K -- - S 18 23% /usr/bin/isoto
21199 - _openqa- _openqa- 2 0.05s 2.20s 15360K 15360K 0K 3988K -- - S 22 23% /usr/bin/isoto
31590 - _openqa- _openqa- 2 0.01s 2.17s 0K 0K 0K 516K -- - S 9 22% videoencoder
21186 - _openqa- _openqa- 2 0.00s 2.13s 0K 0K 0K 152K -- - S 29 21% videoencoder
21201 - _openqa- _openqa- 2 0.00s 2.03s 0K 0K 0K 184K -- - S 12 20% videoencoder
32564 - _openqa- _openqa- 2 0.01s 2.00s 0K 0K 0K 228K -- - S 2 20% videoencoder
21103 - _openqa- _openqa- 2 0.01s 1.98s 0K 0K 0K 140K -- - S 9 20% videoencoder
21153 - _openqa- _openqa- 2 0.01s 1.98s 0K 0K 0K 88K -- - R 30 20% videoencoder
21157 - _openqa- _openqa- 9 0.22s 1.68s 0K 0K 0K 3912K -- - S 22 19% qemu-system-x8
21096 - _openqa- _openqa- 2 0.02s 1.84s 0K 0K 0K 144K -- - R 15 19% videoencoder
21321 - _openqa- _openqa- 2 0.00s 1.74s 0K 0K 0K 92K -- - S 14 17% videoencoder
21257 - _openqa- _openqa- 2 0.00s 1.67s 0K 0K 0K 0K -- - S 28 17% videoencoder
31967 - _openqa- _openqa- 2 0.01s 1.60s 0K 0K 0K 8K -- - R 6 16% videoencoder
21184 - _openqa- _openqa- 2 0.00s 1.57s 0K 0K 0K 3168K -- - S 30 16% /usr/bin/isoto
961 - _openqa- _openqa- 2 0.01s 1.55s 0K 0K 0K 4K -- - S 14 16% videoencoder
1635 - _openqa- _openqa- 2 0.01s 1.15s 0K 8K 0K 192K -- - S 12 12% videoencoder
1473 - _openqa- _openqa- 2 0.00s 0.93s 0K 0K 0K 32K -- - S 13 9% videoencoder
959 - _openqa- _openqa- 2 0.01s 0.66s 0K 0K 0K 624K -- - S 6 7% /usr/bin/isoto
31965 - _openqa- _openqa- 2 0.00s 0.67s 0K 0K 0K 792K -- - S 12 7% /usr/bin/isoto
21090 - _openqa- _openqa- 2 0.00s 0.45s 0K 0K 0K 604K -- - S 10 5% /usr/bin/isoto
32568 - _openqa- _openqa- 15 0.04s 0.40s -0.3G -10.0M 0K 96K -- - R 1 4% qemu-system-x8
21080 - _openqa- _openqa- 2 0.01s 0.42s 0K 52K 0K 2028K -- - S 20 4% /usr/bin/isoto
21319 - _openqa- _openqa- 2 0.00s 0.42s 0K 0K 0K 488K -- - S 9 4% /usr/bin/isoto
21182 - _openqa- _openqa- 2 0.02s 0.39s 0K 0K 0K 1980K -- - S 6 4% /usr/bin/isoto
1928 - _openqa- _openqa- 1 0.00s 0.40s 14316K 4416K 0K 0K N- - R 24 4% optipng
20804 - root root 1 0.29s 0.00s 0K 0K 0K 0K -- - R 2 3% kworker/u65:0
Updated by coolo over 7 years ago
I can't spot a problem in what atop reports :(
There is not a single value in that sample that would indicate any level of problem. But I guess I need to increase the sample rate :(
Updated by coolo over 7 years ago
Increasing the sample rate at least shows that isotovideo is 100% CPU for 3 seconds
07:36:42.9753 19755 <<< testapi::type_string(string='zypper --no-gpg-check -n ar -f \'http://download.suse.de/ibs/SUSE:/Maintenance:/Test:/SLE-SERVER:/12-SP2:/x86_64/update/\' test-repo-OS_TEST_REPO; echo DRBcO-$?- > /dev/ttyS0', max_interval=250, wait_screen_changes=0)
07:36:46.8803 19917 WARNING: enqueue_screenshot took 2.70 seconds - slow IO? (opencv: 0.01 - encoder: 2.70)
So I think it's safe to answer 'slow IO?' with no :)
Updated by szarate over 7 years ago
@coolo i think this could just be a sum between the time that the enqeue_screenshot took to:
- Scale the image
- Compare the new image to last screenshot.
- Write a screenshot that was not similar
- Writing the new frame
I would add to the enqueue screenshot warning, another variable to actually show the encoding time or at least the time it takes to write_encoder_frame, it should be there somehow
Updated by asmorodskyi over 7 years ago
https://openqa.suse.de/tests/640727#step/sshd/14 - example of this issue
Updated by szarate over 7 years ago
- Due date set to 2016-11-24
- Start date changed from 2016-11-23 to 2016-11-24
due to changes in a related task
Updated by asmorodskyi over 7 years ago
another example of this issue https://openqa.suse.de/tests/654352
Updated by coolo over 7 years ago
the problem on our aarc64 worker is clearly a different one
Updated by coolo over 7 years ago
- Status changed from New to Resolved
- Assignee set to coolo
So we finally understood the problem. What you can see in the atop report is 1.3G dirty buffers - and in that situation flushing files (videoencoder.log) requires the process to wait. So we avoid every IO in this loop - but only async write PPMs to the videoencoder
Updated by okurz over 7 years ago
would you care to reference the corresponding PRs?
Actions