Project

General

Profile

Actions

action #14804

closed

encoder still stalls

Added by coolo over 7 years ago. Updated over 7 years ago.

Status:
Resolved
Priority:
Normal
Assignee:
Category:
-
Target version:
-
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

Subtasks 2 (0 open2 closed)

coordination #14972: [tools][epic] Improvements on backend to improve better handling of stallsResolvedokurz2016-11-24

Actions
action #14976: Change the isotovideo backend to write ppm filesResolvedszarate2016-11-24

Actions
Actions #1

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 
Actions #2

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 :(

Actions #3

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 :)

Actions #4

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

Actions #5

Updated by coolo over 7 years ago

yeah, we can hotpatch that on openqaworker2

Actions #7

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

Actions #8

Updated by asmorodskyi over 7 years ago

another example of this issue https://openqa.suse.de/tests/654352

Actions #9

Updated by coolo over 7 years ago

the problem on our aarc64 worker is clearly a different one

Actions #10

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

Actions #11

Updated by okurz over 7 years ago

would you care to reference the corresponding PRs?

Actions

Also available in: Atom PDF