Delay observed in displaying text & highlighting navigation button on loading watchables page

[varumugam123]

This issue is observed while loading https://watchablex1appserver-prod.xidio.com/channelstore-webapp/?from=appsMenu#main on X1 Set Top Box.

There are actually two observations:

• The text appears late On investigation found that the Font resources are downloaded late after it is scheduled on a timer

• The highlighting of the "Featured" button occurs late On this case the text appears on time, but the highlighting initiated by javascript happens only after few seconds.

Please see this recording of the issues : https://goo.gl/photos/Qo9FBsPg7ZJX4SvX6

[varumugam123]

On investigation found the below,

• On occasions when the text display is delayed, we see the Font resources are downloaded lately after it is scheduled after 0 seconds by CSSFontSelector::beginLoadingFontSoon()
• When we see just the highlight display, we observe the javascript changes the style on setTimeOut(, 1)

This led to suspicion around the timer thread, and we came across the changes made in "WebCore/platform/glib/MainThreadSharedTimerGLib.cpp" where the priority of the timer is reduced to (HIGH+40) from (HIGH+30) just for WPE.

#elif PLATFORM(WPE)
    m_timer.setPriority(G_PRIORITY_HIGH + 25);
#endif

We tried restoring the priority back to (HIGH+30) and observed the frequency of issue is very low and with (HIGH+25) the issue never occurs.

[magomez]

After giving a look to this, some comments.

First, the box has to be veery old cause I had to use the rpi1 to reproduce the issue, and just the selected button issue, I wasn't able to reproduce the font issue. Basically, this is just a lack of performance problem, not a rendering bug. The page requires quite some time to load (lots images, lots of rendering). I've monitored the CPU usage since the browser is launched until the button is focused and it's fully loaded, which means that there's no unnecessary delay there, just a lot of work for the processor to perform.

Now, why is this improved by increasing the priority of the shared timer?. Well, this is simple. Both the setTimeout() function that is used to set the selected state to the button and the CSSFontSelector::beginLoadingFontSoon() use the shared timer to schedule their actions. Of course, there are other several actions that are scheduled that use different priorities than the shared timer. By increasing the shared timer priority, you are actually processing before the actions scheduled with it, but delaying others (that should be happening before, maybe). In this case, it seems that isn't any side effect of the change, but there are on other pages, you can be sure.

In the case of page rendering (which I best know), think of the rendering process a 2 steps, the first one which mean executing js and interpreting html+css to render the different elements of the page, and then a second step where those elements are composited to create the final result and the frame is taken to the display. Many of the rendering tasks use the shared timer to schedule their actions (with the current G_PRIORITY_HIGH + 40 priority). Then, at some point, a request to composite the result gets scheduled, with a higher priority than the shared timer (currently G_PRIORITY_HIGH + 30), which gets processed before the rest of the shared timer actions, as the composition needs to be performed before any other action can modify the page again. It works fine with these priorities. Now, if you increase the priority of the shared timer to G_PRIORITY_HIGH + 30, the composition can be delayed by other shared timer actions arriving earlier (as they have the same priority), which will reduce the framerate and can cause rendering issues (compositing being executed in the middle of changes happening in the page). And if you increase the priority of the shared timer to G_PRIORITY_HIGH + 25, the composition may never happen if the js is generating enough events to keep the CPU busy, which means that nothing will be visible on the display.

As a concrete example, test the page http://www.smashcat.org/av/canvas_test/ using these values for the shared timer priority: G_PRIORITY_HIGH + 40, G_PRIORITY_HIGH + 30 and G_PRIORITY_HIGH + 25. Also, use WEBKIT_SHOW_FPS=1 so you can see the number of frames sent to the display on the top left corner (the page reports a fps value, but it's not the real number of frames sent to the display, but the number of times it runs the js function to redraw the image). Basically the page draws an animation as fast as possible using setTimeout(0), so the fps limit is set by the hardware capabilities.

• With G_PRIORITY_HIGH + 40, you can see that you get more or less the same values with fps reported by the page and fps reported by wpe. This means that for every rendering stage a composition stage is executed.

• With G_PRIORITY_HIGH + 30, you see that the fps reported by wpe is reduced, while the fps reported by the page is increased a bit sometimes. This happens because there are so many js events happening that the composition stage gets delayed by them (they have the same priority), so there are times where there's a single composition stage after 2 or 3 rendering stages. This causes that less fps are shown, making the animation choppier.

• With G_PRIORITY_HIGH + 25 you will only get a black screen. This is because wpe is constantly executing js and rendering the animation, and all the events have a higher priority than the composition request, so the composition stage never happens and no frame is visible in the end.

In the page you're testing, the priority changes don't seem to affect the rendering, but if the page had an animation that had to be running while loading, the animation would get less and less fluent with the changes.

[igor-borovkov]

Hi Miguel, is there any historic information about the motivation to use different priorities (those changes seem to be WPE port specific)? The related priority change commit (two years ago) doesn't have much information in the commit message (G_PRIORITY_HIGH + 40).

[magomez]

The priorities where changed several times during the creation of the WPE port. The concrete values are not really important, but what's important is the relation between them (for example, the compositing timer must have a higher priority than the shared one, as mentioned).

The change to G_PRIORITY_HIGH + 40 was done because of 2 reasons: we realized that we were losing fps due to excessive rendering without compositing the result, and the found a couple of rendering issues that were happening because of having the same priority for the shared timer and the compositing timer (the rendering phase has several phases as well, scheduled with the shared timer, and the compositing phase was being executed before all the rendering phases could finish).