[performance] Using --compositor-report=log causes rendering to hiccup/stutter exactly every 5 seconds in unison with disk activity

[Daniel van Vugt]

Using Mir 0.26.1, Unity8 runs better than ever. But when displaying a large continuously rendering window (e.g. eglplasma or egltriangle), the Unity8 shell hiccups and visually stutters exactly every 5 seconds.

According to MIR_CLIENT_PERF_REPORT it's quite major, missing somewhere around 9 frames every 5 seconds. This matches what I see on screen - a large number of frames skipped once every five seconds...

[2017-02-13 16:16:26.761602] perf: : 60.00 FPS, render time 0.41ms, buffer lag 66.31ms (4 buffers)
[2017-02-13 16:16:27.762435] perf: : 60.00 FPS, render time 0.39ms, buffer lag 66.32ms (4 buffers)
[2017-02-13 16:16:28.763269] perf: : 51.00 FPS, render time 0.39ms, buffer lag 78.10ms (4 buffers)
[2017-02-13 16:16:29.764068] perf: : 60.00 FPS, render time 0.39ms, buffer lag 66.32ms (4 buffers)
[2017-02-13 16:16:30.764939] perf: : 60.00 FPS, render time 0.38ms, buffer lag 66.33ms (4 buffers)
[2017-02-13 16:16:31.765773] perf: : 60.00 FPS, render time 0.39ms, buffer lag 66.32ms (4 buffers)
[2017-02-13 16:16:32.766603] perf: : 60.00 FPS, render time 0.39ms, buffer lag 66.32ms (4 buffers)
[2017-02-13 16:16:33.767437] perf: : 51.00 FPS, render time 0.38ms, buffer lag 78.10ms (4 buffers)
[2017-02-13 16:16:34.768274] perf: : 60.00 FPS, render time 0.39ms, buffer lag 66.32ms (4 buffers)
[2017-02-13 16:16:35.769109] perf: : 60.00 FPS, render time 0.39ms, buffer lag 66.32ms (4 buffers)
[2017-02-13 16:16:36.769943] perf: : 60.00 FPS, render time 0.39ms, buffer lag 66.32ms (4 buffers)
[2017-02-13 16:16:37.770780] perf: : 60.00 FPS, render time 0.39ms, buffer lag 66.32ms (4 buffers)
[2017-02-13 16:16:38.771629] perf: : 51.00 FPS, render time 0.40ms, buffer lag 78.09ms (4 buffers)
[2017-02-13 16:16:39.772446] perf: : 60.00 FPS, render time 0.39ms, buffer lag 66.32ms (4 buffers)
[2017-02-13 16:16:40.773279] perf: : 60.00 FPS, render time 0.39ms, buffer lag 66.32ms (4 buffers)
[2017-02-13 16:16:41.774111] perf: : 60.00 FPS, render time 0.39ms, buffer lag 66.32ms (4 buffers)
[2017-02-13 16:16:42.774944] perf: : 60.00 FPS, render time 0.39ms, buffer lag 66.32ms (4 buffers)
[2017-02-13 16:16:43.775796] perf: : 51.00 FPS, render time 0.38ms, buffer lag 78.10ms (4 buffers)
[2017-02-13 16:16:44.776615] perf: : 60.00 FPS, render time 0.36ms, buffer lag 66.35ms (4 buffers)
[2017-02-13 16:16:45.777448] perf: : 60.00 FPS, render time 0.39ms, buffer lag 66.33ms (4 buffers)
[2017-02-13 16:16:46.778282] perf: : 60.00 FPS, render time 0.39ms, buffer lag 66.33ms (4 buffers)
[2017-02-13 16:16:47.779135] perf: : 60.00 FPS, render time 0.39ms, buffer lag 66.32ms (4 buffers)
[2017-02-13 16:16:48.779969] perf: : 51.00 FPS, render time 0.39ms, buffer lag 78.09ms (4 buffers)
[2017-02-13 16:16:49.780801] perf: : 60.00 FPS, render time 0.39ms, buffer lag 66.32ms (4 buffers)
[2017-02-13 16:16:50.781639] perf: : 60.00 FPS, render time 0.39ms, buffer lag 66.32ms (4 buffers)

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Daniel van Vugt (vanvugt)]

TODO: Check if these are related:

plugins/Utils/constants.cpp: m_indicatorValueTimeout = 5000;
qml/Tutorial/TutorialContent.qml: interval: 5000

[Daniel van Vugt (vanvugt)]

OK, the issue is not TutorialContent.qml because modifying that makes no difference.

However I now notice my harddisk LED lights up every time the rendering stutters. So you know what that means :)

[Daniel van Vugt (vanvugt)]

Strangely iotop is showing unity-system-compositor's "Mir/Comp" thread is one of the top disk writers. If that's the problem then USC holding on to bypass frames too long would explain it.

[Daniel van Vugt (vanvugt)]

  TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND
  265 be/3 root 0.00 K 28.00 K 0.00 % 2.21 % [jbd2/sda2-8]
19799 be/4 dan 0.00 K 8.00 K 0.00 % 0.83 % upstart --user
21082 be/4 root 0.00 K 0.00 K 0.00 % 0.37 % [kworker/u16:5]
16506 be/4 root 0.00 K 0.00 K 0.00 % 0.34 % [kworker/u16:1]
12778 be/4 root 0.00 K 8.00 K 0.00 % 0.00 % unity-syst~[Mir/Comp]

[Daniel van Vugt (vanvugt)]

  TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND
  265 be/3 root 0.00 K 440.00 K 0.00 % 2.73 % [jbd2/sda2-8]
12778 be/4 root 0.00 K 56.00 K 0.00 % 1.79 % unity-syst~[Mir/Comp]
21082 be/4 root 0.00 K 0.00 K 0.00 % 0.45 % [kworker/u16:5]
19677 be/4 root 0.00 K 0.00 K 0.00 % 0.20 % [kworker/u16:3]
21111 be/4 root 0.00 K 0.00 K 0.00 % 0.18 % [kworker/u16:0]
 1078 be/4 root 0.00 K 8.00 K 0.00 % 0.08 % accounts-daemon
 1230 be/4 syslog 0.00 K 16.00 K 0.00 % 0.00 % rsyslogd -~ain Q:Reg]
19799 be/4 dan 0.00 K 88.00 K 0.00 % 0.00 % upstart --user
20013 be/4 dan 0.00 K 4.00 K 0.00 % 0.00 % unity8 --m~full-shell

[Daniel van Vugt (vanvugt)]

User error. And truth is stranger than fiction as always...

Unity8 was freezing every 5 seconds because that's the ext3/ext4 journal commit interval.

Unity8 was not doing the IO directly, but since it's being bypassed through USC, is very time-sensitive. Fullscreen bypass holds buffers back from the client for the duration of a frame. So the freeze was USC periodically failing to return Unity8 a buffer in time. The problem with USC as shown above was in its Mir compositor thread. I had configured it to use --compositor-report=log, which although it writes very little text, is subject to the ext3/ext4 journaling rules which force a commit/sync every 5 seconds by default.

So the delay was USC's compositor thread writing to its log, which only once every 5 seconds is a slow operation. Whenever the hiccup occurred, that held back a bypass buffer from Unity8 a bit too long.

To add to the problem, Mir's Mesa-KMS driver does not allow more than one frame to be pre-rendered so as to keep visual lag down. So it sometimes didn't have a fresh U8 frame ready in time and would skip a whole frame. There's no catch-up in the Mir Mesa-KMS driver, although I've coincidentally been thinking about implementing it. But doesn't matter; as soon as I turned off --compositor-report=log the bug was solved.

[Michał Sawicz (saviq)]

Syncing task from Mir.