Ubuntu
linux package

Bug #1861359
Comment #62

Comment 62 for bug 1861359

Revision history for this message

Seth Arnold (seth-arnold) wrote on 2020-04-03:

#62

Stefan, while recent kernels seem happier than previous kernels (I think -14 era was terrible), I don't think this problem is fixed yet:

sarnold@millbarge:/tmp$ uname -a
Linux millbarge 5.4.0-21-generic #25-Ubuntu SMP Sat Mar 28 13:10:28 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
sarnold@millbarge:/tmp$ uptime
17:18:02 up 14:59, 8 users, load average: 0.36, 0.27, 0.16
sarnold@millbarge:/tmp$ time journalctl > foo

real 0m47.135s
user 0m36.886s
sys 0m10.180s
sarnold@millbarge:/tmp$ ls -lh /tmp/foo
-rw-rw-r-- 1 sarnold sarnold 841M Apr 3 17:15 /tmp/foo
sarnold@millbarge:/tmp$ wc -l /tmp/foo
4045530 /tmp/foo

During that journalctl run, my mouse could not move for twenty seconds. I left an iovisor tool running to log high-latency __alloc_pages_nodemask() calls (identified by Sultan as a likely cause):

# funcslower-bpfcc Tracing function COMM PID LAT(ms) dp_sync_taskq 716 systemd-udevd 44671 git 46218 z_wr_iss 683 systemd-udevd 51359 systemd-udevd 56585 systemd-udevd 56577 systemd-udevd 72552 systemd-udevd 76964 systemd-udevd 80900 systemd-udevd 88669 kthreadd 2 kthreadd 2 kthreadd 2 updatedb.mloca 106194 kthreadd 2 kthreadd 2 kthreadd 2 kthreadd 2 systemd-udevd 113822 systemd-udevd 113820 systemd-udevd 122017 systemd-udevd 141102 systemd-udevd 144565 systemd-udevd 1156 systemd-udevd 152486 systemd-udevd 152485 systemd-udevd 172807 systemd-udevd 185503 systemd-udevd 189244 systemd-udevd 205973 systemd-udevd 210133 systemd-udevd 209621 systemd-udevd 218768 systemd-udevd 234261 systemd-udevd 235468 systemd-udevd 236826 systemd-udevd 247115 systemd-udevd 247573 systemd-udevd 271288 dav1d-tile dav1d-tile dav1d-tile RemVidParent 283460 dav1d-tile journalctl journalctl journalctl journalctl x-terminal-emu 24851 journalctl kthreadd 2 journalctl journalctl journalctl journalctl journalctl journalctl kthreadd 2 journalctl journalctl journalctl journalctl journalctl journalctl journalctl journalctl journalctl journalctl journalctl journalctl journalctl journalctl journalctl journalctl journalctl kthreadd 2 journalctl journalctl journalctl journalctl kthreadd 2 z_wr_iss_h 684 journalctl kthreadd 2 systemd-udevd 288492 __alloc_pages_nodemask
calls slower than 1 ms... Ctrl+C to quit.
RVAL FUNC
7.72 fffff2d109115040 __alloc_pages_nodemask
1.59 fffff2d10575b800 __alloc_pages_nodemask
4.27 fffff2d10500edc0 __alloc_pages_nodemask
4.90 fffff2d101b4cf40 __alloc_pages_nodemask
4.27 fffff2d10ec12800 __alloc_pages_nodemask
2.48 fffff2d10d3b0500 __alloc_pages_nodemask
2.55 fffff2d106f73380 __alloc_pages_nodemask
2.09 fffff2d105249680 __alloc_pages_nodemask
1.53 fffff2d1017fd440 __alloc_pages_nodemask
3.94 fffff2d102675200 __alloc_pages_nodemask
2.09 fffff2d1015fb5c0 __alloc_pages_nodemask
4.41 fffff2d10d6f96c0 __alloc_pages_nodemask
4.65 fffff2d10d38c3c0 __alloc_pages_nodemask
3.97 fffff2d10d3cc780 __alloc_pages_nodemask
2.44 fffff2d10e1c2680 __alloc_pages_nodemask
1.20 fffff2d10d36ff40 __alloc_pages_nodemask
4.13 fffff2d10d495940 __alloc_pages_nodemask
6.34 fffff2d10d317180 __alloc_pages_nodemask
4.76 fffff2d110e85000 __alloc_pages_nodemask
1.51 fffff2d10f5c8e00 __alloc_pages_nodemask
1.91 fffff2d10e611800 __alloc_pages_nodemask
3.13 fffff2d10e539700 __alloc_pages_nodemask
2.43 fffff2d104487200 __alloc_pages_nodemask
4.82 fffff2d106b84040 __alloc_pages_nodemask
1.28 fffff2d102325c00 __alloc_pages_nodemask
3.07 fffff2d101516500 __alloc_pages_nodemask
4.94 fffff2d1015cbbc0 __alloc_pages_nodemask
1.33 fffff2d1015f4700 __alloc_pages_nodemask
4.46 fffff2d10d321240 __alloc_pages_nodemask
5.12 fffff2d10e7f0b00 __alloc_pages_nodemask
5.36 fffff2d10d4171c0 __alloc_pages_nodemask
5.19 fffff2d10ffac340 __alloc_pages_nodemask
2.95 fffff2d10d377fc0 __alloc_pages_nodemask
2.24 fffff2d10526e500 __alloc_pages_nodemask
1.42 fffff2d101814680 __alloc_pages_nodemask
3.82 fffff2d10d2afa40 __alloc_pages_nodemask
4.94 fffff2d10d0f8440 __alloc_pages_nodemask
1.13 fffff2d1023ee180 __alloc_pages_nodemask
1.46 fffff2d1015a4040 __alloc_pages_nodemask
5.38 fffff2d10d1b3800 __alloc_pages_nodemask
283460 2.05 fffff2d10cdb0b80 __alloc_pages_nodemask
283460 2.80 fffff2d10cdb8840 __alloc_pages_nodemask
283460 2.83 fffff2d10cdb9200 __alloc_pages_nodemask
2.82 fffff2d10cdba200 __alloc_pages_nodemask
283460 4.11 fffff2d10cdbcf00 __alloc_pages_nodemask
286270 1.71 fffff2d10e2668c0 __alloc_pages_nodemask
286270 1.09 fffff2d10ccfac00 __alloc_pages_nodemask
286270 1.11 fffff2d10cce3200 __alloc_pages_nodemask
286270 2.96 fffff2d10cce7380 __alloc_pages_nodemask
1.14 fffff2d1086a2a00 __alloc_pages_nodemask
286270 1.44 fffff2d10ccc41c0 __alloc_pages_nodemask
1.25 fffff2d110c71000 __alloc_pages_nodemask
286270 1.05 fffff2d10ccb1200 __alloc_pages_nodemask
286270 1.65 fffff2d10ccbd700 __alloc_pages_nodemask
286270 3.08 fffff2d102229000 __alloc_pages_nodemask
286270 1.88 fffff2d10cbfd0c0 __alloc_pages_nodemask
286270 1.54 fffff2d109088100 __alloc_pages_nodemask
286270 1.04 fffff2d105db1800 __alloc_pages_nodemask
2.57 fffff2d1092603c0 __alloc_pages_nodemask
286270 3.59 fffff2d109358780 __alloc_pages_nodemask
286270 1.21 fffff2d10ed83980 __alloc_pages_nodemask
286270 3.17 fffff2d10cb6be40 __alloc_pages_nodemask
286270 1.65 fffff2d10cb6de00 __alloc_pages_nodemask
286270 1.00 fffff2d10cb6fdc0 __alloc_pages_nodemask
286270 3.97 fffff2d10cb46700 __alloc_pages_nodemask
286270 1.08 fffff2d10fef7700 __alloc_pages_nodemask
286270 1.11 fffff2d1106ab840 __alloc_pages_nodemask
286270 1.16 fffff2d10cb204c0 __alloc_pages_nodemask
286270 1.22 fffff2d110d71640 __alloc_pages_nodemask
286270 1.10 fffff2d110e4afc0 __alloc_pages_nodemask
286270 1.03 fffff2d10d912580 __alloc_pages_nodemask
286270 1.06 fffff2d109de5a00 __alloc_pages_nodemask
286270 1.05 fffff2d10cad6f40 __alloc_pages_nodemask
286270 1.52 fffff2d10ca206c0 __alloc_pages_nodemask
286270 1.17 fffff2d10927f300 __alloc_pages_nodemask
286270 1.18 fffff2d10ca1a400 __alloc_pages_nodemask
1.77 fffff2d11008d400 __alloc_pages_nodemask
286270 2.98 fffff2d108f41e40 __alloc_pages_nodemask
286270 1.09 fffff2d10c9fe440 __alloc_pages_nodemask
286270 1.53 fffff2d1090532c0 __alloc_pages_nodemask
286270 1.45 fffff2d10c9d4e40 __alloc_pages_nodemask
1.72 fffff2d10fc46040 __alloc_pages_nodemask
1.85 fffff2d10a384cc0 __alloc_pages_nodemask
286270 1.29 fffff2d10c9c0480 __alloc_pages_nodemask
1.35 fffff2d109ffd8c0 __alloc_pages_nodemask
2.55 fffff2d10e30a5c0 __alloc_pages_nodemask

This feels better but not yet fixed.

Thanks

Stefan, while recent kernels seem happier than previous kernels (I think -14 era was terrible), I don't think this problem is fixed yet:

sarnold@millbarge:/tmp$ uname -a
Linux millbarge 5.4.0-21-generic #25-Ubuntu SMP Sat Mar 28 13:10:28 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
sarnold@millbarge:/tmp$ uptime
 17:18:02 up 14:59,  8 users,  load average: 0.36, 0.27, 0.16
sarnold@millbarge:/tmp$ time journalctl > foo

real	0m47.135s
user	0m36.886s
sys	0m10.180s
sarnold@millbarge:/tmp$ ls -lh /tmp/foo
-rw-rw-r-- 1 sarnold sarnold 841M Apr  3 17:15 /tmp/foo
sarnold@millbarge:/tmp$ wc -l /tmp/foo
4045530 /tmp/foo

During that journalctl run, my mouse could not move for twenty seconds. I left an iovisor tool running to log high-latency __alloc_pages_nodemask() calls (identified by Sultan as a likely cause):

# funcslower-bpfcc __alloc_pages_nodemask
Tracing function calls slower than 1 ms... Ctrl+C to quit.
COMM           PID    LAT(ms)             RVAL FUNC
dp_sync_taskq  716       7.72 fffff2d109115040 __alloc_pages_nodemask 
systemd-udevd  44671     1.59 fffff2d10575b800 __alloc_pages_nodemask 
git            46218     4.27 fffff2d10500edc0 __alloc_pages_nodemask 
z_wr_iss       683       4.90 fffff2d101b4cf40 __alloc_pages_nodemask 
systemd-udevd  51359     4.27 fffff2d10ec12800 __alloc_pages_nodemask 
systemd-udevd  56585     2.48 fffff2d10d3b0500 __alloc_pages_nodemask 
systemd-udevd  56577     2.55 fffff2d106f73380 __alloc_pages_nodemask 
systemd-udevd  72552     2.09 fffff2d105249680 __alloc_pages_nodemask 
systemd-udevd  76964     1.53 fffff2d1017fd440 __alloc_pages_nodemask 
systemd-udevd  80900     3.94 fffff2d102675200 __alloc_pages_nodemask 
systemd-udevd  88669     2.09 fffff2d1015fb5c0 __alloc_pages_nodemask 
kthreadd       2         4.41 fffff2d10d6f96c0 __alloc_pages_nodemask 
kthreadd       2         4.65 fffff2d10d38c3c0 __alloc_pages_nodemask 
kthreadd       2         3.97 fffff2d10d3cc780 __alloc_pages_nodemask 
updatedb.mloca 106194    2.44 fffff2d10e1c2680 __alloc_pages_nodemask 
kthreadd       2         1.20 fffff2d10d36ff40 __alloc_pages_nodemask 
kthreadd       2         4.13 fffff2d10d495940 __alloc_pages_nodemask 
kthreadd       2         6.34 fffff2d10d317180 __alloc_pages_nodemask 
kthreadd       2         4.76 fffff2d110e85000 __alloc_pages_nodemask 
systemd-udevd  113822    1.51 fffff2d10f5c8e00 __alloc_pages_nodemask 
systemd-udevd  113820    1.91 fffff2d10e611800 __alloc_pages_nodemask 
systemd-udevd  122017    3.13 fffff2d10e539700 __alloc_pages_nodemask 
systemd-udevd  141102    2.43 fffff2d104487200 __alloc_pages_nodemask 
systemd-udevd  144565    4.82 fffff2d106b84040 __alloc_pages_nodemask 
systemd-udevd  1156      1.28 fffff2d102325c00 __alloc_pages_nodemask 
systemd-udevd  152486    3.07 fffff2d101516500 __alloc_pages_nodemask 
systemd-udevd  152485    4.94 fffff2d1015cbbc0 __alloc_pages_nodemask 
systemd-udevd  172807    1.33 fffff2d1015f4700 __alloc_pages_nodemask 
systemd-udevd  185503    4.46 fffff2d10d321240 __alloc_pages_nodemask 
systemd-udevd  189244    5.12 fffff2d10e7f0b00 __alloc_pages_nodemask 
systemd-udevd  205973    5.36 fffff2d10d4171c0 __alloc_pages_nodemask 
systemd-udevd  210133    5.19 fffff2d10ffac340 __alloc_pages_nodemask 
systemd-udevd  209621    2.95 fffff2d10d377fc0 __alloc_pages_nodemask 
systemd-udevd  218768    2.24 fffff2d10526e500 __alloc_pages_nodemask 
systemd-udevd  234261    1.42 fffff2d101814680 __alloc_pages_nodemask 
systemd-udevd  235468    3.82 fffff2d10d2afa40 __alloc_pages_nodemask 
systemd-udevd  236826    4.94 fffff2d10d0f8440 __alloc_pages_nodemask 
systemd-udevd  247115    1.13 fffff2d1023ee180 __alloc_pages_nodemask 
systemd-udevd  247573    1.46 fffff2d1015a4040 __alloc_pages_nodemask 
systemd-udevd  271288    5.38 fffff2d10d1b3800 __alloc_pages_nodemask 
dav1d-tile     283460    2.05 fffff2d10cdb0b80 __alloc_pages_nodemask 
dav1d-tile     283460    2.80 fffff2d10cdb8840 __alloc_pages_nodemask 
dav1d-tile     283460    2.83 fffff2d10cdb9200 __alloc_pages_nodemask 
RemVidParent   283460    2.82 fffff2d10cdba200 __alloc_pages_nodemask 
dav1d-tile     283460    4.11 fffff2d10cdbcf00 __alloc_pages_nodemask 
journalctl     286270    1.71 fffff2d10e2668c0 __alloc_pages_nodemask 
journalctl     286270    1.09 fffff2d10ccfac00 __alloc_pages_nodemask 
journalctl     286270    1.11 fffff2d10cce3200 __alloc_pages_nodemask 
journalctl     286270    2.96 fffff2d10cce7380 __alloc_pages_nodemask 
x-terminal-emu 24851     1.14 fffff2d1086a2a00 __alloc_pages_nodemask 
journalctl     286270    1.44 fffff2d10ccc41c0 __alloc_pages_nodemask 
kthreadd       2         1.25 fffff2d110c71000 __alloc_pages_nodemask 
journalctl     286270    1.05 fffff2d10ccb1200 __alloc_pages_nodemask 
journalctl     286270    1.65 fffff2d10ccbd700 __alloc_pages_nodemask 
journalctl     286270    3.08 fffff2d102229000 __alloc_pages_nodemask 
journalctl     286270    1.88 fffff2d10cbfd0c0 __alloc_pages_nodemask 
journalctl     286270    1.54 fffff2d109088100 __alloc_pages_nodemask 
journalctl     286270    1.04 fffff2d105db1800 __alloc_pages_nodemask 
kthreadd       2         2.57 fffff2d1092603c0 __alloc_pages_nodemask 
journalctl     286270    3.59 fffff2d109358780 __alloc_pages_nodemask 
journalctl     286270    1.21 fffff2d10ed83980 __alloc_pages_nodemask 
journalctl     286270    3.17 fffff2d10cb6be40 __alloc_pages_nodemask 
journalctl     286270    1.65 fffff2d10cb6de00 __alloc_pages_nodemask 
journalctl     286270    1.00 fffff2d10cb6fdc0 __alloc_pages_nodemask 
journalctl     286270    3.97 fffff2d10cb46700 __alloc_pages_nodemask 
journalctl     286270    1.08 fffff2d10fef7700 __alloc_pages_nodemask 
journalctl     286270    1.11 fffff2d1106ab840 __alloc_pages_nodemask 
journalctl     286270    1.16 fffff2d10cb204c0 __alloc_pages_nodemask 
journalctl     286270    1.22 fffff2d110d71640 __alloc_pages_nodemask 
journalctl     286270    1.10 fffff2d110e4afc0 __alloc_pages_nodemask 
journalctl     286270    1.03 fffff2d10d912580 __alloc_pages_nodemask 
journalctl     286270    1.06 fffff2d109de5a00 __alloc_pages_nodemask 
journalctl     286270    1.05 fffff2d10cad6f40 __alloc_pages_nodemask 
journalctl     286270    1.52 fffff2d10ca206c0 __alloc_pages_nodemask 
journalctl     286270    1.17 fffff2d10927f300 __alloc_pages_nodemask 
journalctl     286270    1.18 fffff2d10ca1a400 __alloc_pages_nodemask 
kthreadd       2         1.77 fffff2d11008d400 __alloc_pages_nodemask 
journalctl     286270    2.98 fffff2d108f41e40 __alloc_pages_nodemask 
journalctl     286270    1.09 fffff2d10c9fe440 __alloc_pages_nodemask 
journalctl     286270    1.53 fffff2d1090532c0 __alloc_pages_nodemask 
journalctl     286270    1.45 fffff2d10c9d4e40 __alloc_pages_nodemask 
kthreadd       2         1.72 fffff2d10fc46040 __alloc_pages_nodemask 
z_wr_iss_h     684       1.85 fffff2d10a384cc0 __alloc_pages_nodemask 
journalctl     286270    1.29 fffff2d10c9c0480 __alloc_pages_nodemask 
kthreadd       2         1.35 fffff2d109ffd8c0 __alloc_pages_nodemask 
systemd-udevd  288492    2.55 fffff2d10e30a5c0 __alloc_pages_nodemask

This feels better but not yet fixed.

Thanks

Ubuntulinux package

Comment 62 for bug 1861359

Ubuntu
linux package