GNOME Bugzilla – Bug 687460
compositor thread blocks for up to 800ms when first unlocking the screen
Last modified: 2021-07-05 14:16:37 UTC
+++ This bug was initially created as a clone of Bug #687362 +++ * Boot a machine with GNOME 3 (I used a mixture of 3.4 and 3.6.1 from Debian experimental, including Shell 3.6.1) * Log in * Wait for I/O to cease * strace the Shell * Wait for the screen to lock (I configured it for a 1 minute timeout) * Unlock the screen It seems to block on quite a few things before it gets back to the main loop, including: * this, after a flurry of ioctls on fd 10 (the DRI device): 1928 1351867338.675470 ioctl(10, 0x400c645f, 0x7fff2df3fc90) = 0 <0.000024> 1928 1351867338.701419 ioctl(10, 0xc00c6466, 0x7fff2df42270) = 0 <0.000036> ^ 25ms with no I/O - CPU busy? * blocking on reading the "noise texture" from the main thread: 1928 1351867338.703321 open("/usr/share/gnome-shell/theme/noise-texture.png", O_RDONLY) = 36 <0.000055> 1928 1351867338.703436 fstat(36, {st_mode=S_IFREG|0644, st_size=79464, ...}) = 0 <0.000022> 1928 1351867338.703536 read(36, "\211PNG\r\n\32\n\0\0\0\rIHDR\0\0\1\0\0\0\1\0\10\6\0\0\0\\r\250"..., 8192) = 8192 <0.008494> 1928 1351867338.712191 read(36, "\265\324\326d2\201\240L,\"\r\200\223\237|\362I\372\321G\37e\243\321\250m\21\24GV\245\341"..., 8192) = 8192 <0.000048> 1928 1351867338.712295 read(36, "|K\210\272\2122Gv\360\340\301/\320\242\f\10\235\314\354 \267\344NGW\346\324-\375\31\245\232"..., 8192) = 8192 <0.000835> 1928 1351867338.713203 read(36, ";\347\262\311d\22\321s\310\225\355\32\325\200\202C\303\361O\10\320\v\2704\300(\275\276\7H\256\345"..., 8192) = 8192 <0.000035> 1928 1351867338.713294 read(36, "D<\314\204\2007\24#\215M%Z\317\fz\314\213H\0375\276\220\331\307/~\361\213\206~?5"..., 8192) = 8192 <0.000073> 1928 1351867338.713472 read(36, ">~\266\251\247m*\"\21\241\334\274\30Y\302\234%\254\203\373\2245\201s.\6A\311X\252\tw"..., 8192) = 8192 <0.000061> 1928 1351867338.713631 read(36, "[\206\315\t\220/p\316e\237~\372i\256\266|\321\2313g\332zIg\r\216\336\31\271_\371\376"..., 8192) = 8192 <0.000030> 1928 1351867338.713714 brk(0x4e14000) = 0x4e14000 <0.000023> 1928 1351867338.713788 read(36, "\276R=\270\333\264\246Bz\236\250\10C\255\10\330*>\24\21Q\267\243t0\30\264\226\226\226\206L"..., 8192) = 8192 <0.000027> 1928 1351867338.713868 read(36, "|Q\317f\263pgg\247\255$\234\256s\256\322\333;\271A\337\34\350\r\307\202\237\216VT\310\275"..., 8192) = 8192 <0.000030> 1928 1351867338.713951 read(36, "\363t}\301\370\346\n\257_\277\336\327\236\23@UNB\16\357\255\306\376r\n\372\f\265\264l\346y"..., 8192) = 5736 <0.000029> 1928 1351867338.714032 read(36, "", 8192) = 0 <0.000022> 1928 1351867338.714097 close(36) = 0 <0.000022> 1928 1351867338.714269 brk(0x4e49000) = 0x4e49000 <0.000030> 1928 1351867338.716949 brk(0x4e89000) = 0x4e89000 <0.000029> * some ioctls that take a while (presumably texture uploads): 1928 1351867338.720678 ioctl(10, 0x40406469, 0x7fff2df3ff40) = 0 <0.008706> nearly 9ms ^ 1928 1351867338.729490 ioctl(10, 0xc010645b, 0x7fff2df3ff60) = 0 <0.000022> 1928 1351867338.729556 ioctl(10, 0xc0106464, 0x7fff2df3ff80) = 0 <0.000048> 1928 1351867338.729669 mmap(NULL, 4194304, PROT_READ|PROT_WRITE, MAP_SHARED, 10, 0x100400000) = 0x7f4844500000 <0.000084> 1928 1351867338.729818 ioctl(10, 0x400c645f, 0x7fff2df3ffc0) = 0 <0.002216> more than 2ms ^ # large gap in the main thread (1928) here - CPU busy? 2246 1351867339.102877 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out) <0.500038> 2246 1351867339.102979 futex(0x2ed1dd0, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000009> 2246 1351867339.103037 futex(0x2ed1f34, FUTEX_WAIT_BITSET_PRIVATE, 13, {704, 403646000}, ffffffff <unfinished ...> 1928 1351867339.133005 brk(0x4ff3000) = 0x4ff3000 <0.000024> * blocking on an IPC (X11?) call, several times: 1928 1351867339.454076 poll([{fd=6, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=6, revents=POLLOUT}]) <0.000025> 1928 1351867339.454157 writev(6, [{"\211\t\2\0\32\0\0\1", 8}, {NULL, 0}, {"", 0}], 3) = 8 <0.000026> 1928 1351867339.454239 poll([{fd=6, events=POLLIN}], 1, -1) = 1 ([{fd=6, revents=POLLIN}]) <0.000064> 1928 1351867339.454369 recvfrom(6, "\1!D\10\0\0\0\0\204\315\4\0i\t\215$\0\0\0\0002}\0\0\0\0\0\0\r\0\0\0", 4096, 0, NULL, NULL) = 32 <0.000023> 1928 1351867339.454465 recvfrom(6, 0x1958994, 4096, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable) <0.000021> 1928 1351867339.454539 recvfrom(6, 0x1958994, 4096, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable) <0.000021> * and we don't get back to polling the main context until here: 1928 1351867339.456357 poll([{fd=23, events=POLLIN}, {fd=19, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN}, {fd=6, events=POLLIN}, {fd=11, events=POLLIN}, {fd=18, events=POLLIN}, {fd=24, events=POLLIN}, {fd=34, events=POLLIN}, {fd=35, events=POLLIN}, {fd=21, events=POLLIN}, {fd=9, events=POLLIN}, {fd=31, events=POLLIN}, {fd=25, events=POLLIN}, {fd=13, events=POLLIN}], 15, 0) = 0 (Timeout) <0.000032> (This is 800ms after the last poll() in the main thread with this many fds.)
One obvious thing that's not right here is that the noise texture isn't loaded until we unlock. As soon as the user locks the screen, we know we're going to need it: so maybe we could load it once the screen has locked, perhaps even in a thread so it won't block the compositor at all? If people who understand Clutter/Cogl (i.e. not me) tell me that that texture has to be uploaded from the compositor thread, I'm quite prepared to believe that, but again, it could perhaps be done while the screen is still locked, at which point blocking the compositor isn't visible?
Highlights from repeating this under sysprof: 33.71% unpack_ARGB8888() in i965_dri 22.26% in blur_pixels() in libgnome-shell 1.12% in string_in_list() 0.80% in g_hash_table_lookup() 0.88% in additional_selector_matches_style() 0.72% in cr_utils_is_white_space()
Created attachment 228125 [details] strace log while unlocking for the first time after login + wait-for-lock (run 5)
Created attachment 228126 [details] sysprof from run 5 Same run as Attachment #228125 [details].
(In reply to comment #2) > Highlights from repeating this under sysprof: > > 33.71% unpack_ARGB8888() in i965_dri > 22.26% in blur_pixels() in libgnome-shell This numbers seem to be associated with the software-rendered text and drop shadows, of which there are plenty in the lock screen. We should probably look at generating these with GLSL.
This isn't so bad when using less enthusiastic profiling: with my patches from Bug #687465, there's one 78ms dispatch and a lot of ~35ms dispatches.
GNOME is going to shut down bugzilla.gnome.org in favor of gitlab.gnome.org. As part of that, we are mass-closing older open tickets in bugzilla.gnome.org which have not seen updates for a longer time (resources are unfortunately quite limited so not every ticket can get handled). If you can still reproduce the situation described in this ticket in a recent and supported software version, then please follow https://wiki.gnome.org/GettingInTouch/BugReportingGuidelines and create a new ticket at https://gitlab.gnome.org/GNOME/gnome-shell/-/issues/ Thank you for your understanding and your help.