4 ms·
This isn't explicitly related, but interesting, so I offer it up here. When I read 40ms, it triggered a memory from tracking down a different 40ms latency bug
by jdblair 6y ago
This isn't explicitly related, but interesting, so I offer it up here.
When I read 40ms, it triggered a memory from tracking down a different 40ms latency bug a few years ago. I work on the Netflix app for set top boxes, and a particular pay TV company had a box based on AOSP L. Testing discovered that after enough times switching the app between foreground and background, playback would start to stutter. The vendor doing the integration blamed Netflix - they showed that in the stutter case, the Netflix app was not feeding video data quickly enough for playback. They stopped their analysis at this point, since as far as they were concerned, they had found the issue and we had to fix the Netflix app.
I doubted the app was the issue, as it ran on millions of other devices without showing this behavior. I instrumented the code and measured 40ms of extra delay from the thread scheduler. The 40ms was there, and was outside of our app's context. Literally, I measured it between the return of the thread handler and the next time the handler was called. So I responded, to paraphrase, its not us, its you. Your Android scheduler is broken.
But the onus was on me to prove it by finding the bug. I read the Android code, and learned Android threads are a userspace construct - the Android scheduler uses epoll() as a timer and calls your thread handler based on priority level. I thought, epoll() performance isn't guaranteed, maybe something obscure changed, and this change is adding an additional 40ms in this particular case. So I dove into the kernel, thinking the issue must be somewhere inside epoll().
Lucky for me, another engineer, working for a different vendor on the project, found the smoking gun in this patch in Android M (the next version). It was right there, an extra 40ms explicitly (and mistakenly) added when a thread is created while the app is in the background.
https://android.googlesource.com/platform/system/core/+/4cdce42%5E%21/#F0 https://android.googlesource.com/platform/system/core/+/4cdc...
Fix janky navbar ripples -- incorrect timerslack values
If a thread is created while the parent thread is "Background",
then the default timerslack value gets set to the current
timerslack value of the parent (40ms). The default value is
used when transitioning to "Foreground" -- so the effect is that
the timerslack value becomes 40ms regardless of foreground/background.
This does occur intermittently for systemui when creating its
render thread (pretty often on hammerhead and has been seen on
shamu). If this occurs, then some systemui animations like navbar
ripples can wait for up to 40ms to draw a frame when they intended
to wait 3ms -- jank.
This fix is to explicitly set the foreground timerslack to 50us.
A consequence of setting timerslack behind the process' back is
that any custom values for timerslack get lost whenever the thread
has transition between fg/bg.
--- a/libcutils/sched_policy.c
+++ b/libcutils/sched_policy.c
@@ -50,6 +50,7 @@
// timer slack value in nS enforced when the thread moves to background
#define TIMER_SLACK_BG 40000000
+#define TIMER_SLACK_FG 50000
static pthread_once_t the_once = PTHREAD_ONCE_INIT;
@@ -356,7 +357,8 @@
¶m);
}
- prctl(PR_SET_TIMERSLACK_PID, policy == SP_BACKGROUND ? TIMER_SLACK_BG : 0, tid);
+ prctl(PR_SET_TIMERSLACK_PID,
+ policy == SP_BACKGROUND ? TIMER_SLACK_BG : TIMER_SLACK_FG, tid);
return 0;
- jlgaddis 6y ago> But the onus was on me to prove it by finding the bug. As a network engineer who has had to prove numerous times that "it's not the firewall" or "it's not the network", you have my deepest sympathies. -- Story time: My most memorable instance of this was when I worked at a .edu and was going through yet another iteration of the back-and-forth, "it's not on our side, must be on your side", "no, it's not us, it's your firewall", finger-pointing blame game. This particular issue had been dragging on for a while and, eventually, I got a packet capture from their side (packet captures are, to me, the ultimate source of truth, "the last word"). Yet, even after showing (and explaining) it to them, they continued to insist that their firewall was absolutely, positively, 100% configured properly and, thus, it had to be my firewall which was not properly configured. Finally, I called in a favor from a (Ph.D.) faculty member who "owed me one". After explaining what was going on and, more importantly, showing him the timestamps, he agreed to help me out. He wrote up a wonderful e-mail (which I still have a copy of, somewhere) stating how it just was not possible, literally, that mine was the "offending firewall". He explained how he was able to conclude this with absolute certainty, thanks to the laws of physics and politely suggested that -- unless they had evidence that Checkpoint was able to somehow violate those laws of physics (in which case he would be extremely interested in their proof) -- that perhaps they might wanna take another look at their firewall? I waited anxiously, curious what the response (and latest excuse) would be. A few days passed before, finally, an e-mail appeared in my inbox. I quickly opened it and read the one-line reply: We found the problem, it's working now.