1432019 - Improve scrolling on Android by dispatching vsync notifications on the UI thread

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: General, enhancement, P3)

Description

[Mark]

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_2) AppleWebKit/604.4.7 (KHTML, like Gecko) Version/11.0.2 Safari/604.4.7

Steps to reproduce:

Paint skipping seems to make Android scrolling janky. Particularly for slow finger drags. 

I disabled paint skipping on a few of my phones and it seems to make scrolling smoother and doesn't seem to have any downside on phones ranging from a slow Moto G2 (Snapdragon 410?) up to a pretty fast Sony Xperia X Compact (Snapdragon 625?)

Janky scrolling seems to be one of the big complaints about Firefox Android. Disabling paint skipping does seem to improve matters somewhat.

Comment 1

[Kartikaya Gupta (email:[e-mail])]

I don't see how disabling paint skipping could possibly improve jankiness of scroll. But I'm happy to punt this decision to the Android UX team. If they feel the experience is better with paint skipping off, it's a simple pref change. No APZ code changes are involved here, it's purely a Fennec decision/change. Moving back to the android product.

Comment 2

[Mark]

I got the idea from here 

https://www.reddit.com/r/firefox/comments/6t8hpy/improve_scrolling_on_mobile/

and I've seen it in other forums, so I don't think I'm the only one.

It makes a difference for me on some sites, eg

www.arstechnica.com

if I do a moderate speed drag up the page, perhaps 1 cm per second, I can see the difference on Sony Xperia X Compact and a BQ Aquaris X5. With paint skipping enabled there is stutter and jank at some drag speeds. Like missing frames. There seems to be a critical drag speed where it becomes most visible. I don't see much difference on my ancient Moto E2. I don't think it's an fps issue per se, Firefox reports 60 fps in both cases. YMMV but I can see it. I fooled around with OMTP but it didn't make a difference.

Anything you can do to improve scrolling is probably worth a look? Particularly a quick win like this? Scrolling still seems to be the number one complaint about Firefox for Android. Chromium is butter smooth, Firefox is ... tolerable?

Comment 3

[Mark]

I see it here too

https://4archive.org/board/g/thread/62193963/is-there-truly-a-reason-for-firefox-to-run-like-hot-garbage-on

if I try and read the text during a slow/moderate vertical drag, I see the text is noticeably easier to read with paint skipping disabled. With it enabled the text moves in small jumps.

On a lot of pages it does not seem to make a difference but on some it does.

Comment 4

[Jan Henning [:JanH]]

I tried it a little, but couldn't really tell a difference. Ideally we'd find some measurement that allows us to verify whether this is really having any effect or not. And of course it would be nice to know that turning this off doesn't regress performance in some other area...

Comment 5

[James Willcox (:snorp) ([e-mail]) (he/him)]

I don't think we should make a change until we have a test that verifies that this improves things.

Comment 6

[Mark]

What does paint skipping do on Fennec? I don’t really see any difference in the number of paints on a couple of simple web pages.

On Fennec if I scroll mozilla.org from top to bottom I get 25 paints in the Performance profile whether apz.paint_skipping.enabled is true or false. Same on a few other simple sites.

On Mac desktop I do see a big difference, mozilla.org has many many more paints if skipping is disabled.

I still see this scroll jank on Fennec if skipping is enabled & I drag scroll at a particular speed, on a couple of phones of varying performance., I don’t really understand what it means. It irritates me ;). It’s not a simple fps issue, I see a decent fps in the profiler so I am stumped and just fiddling.

thanks

Comment 7

[Mark]

I’ve dug some more into this and I think I have steps to reproduce and a theory and even video. This is a long post. Sorry. Last person to suffer my long posts was Jeff on bug 1422090, but that turned out OK, maybe this one will?? Usual caveat, I know nothing about browsers and this is just me and my Mk I eyeballs guessing. Thanks for your time.

TL;DR version

With a fast phone CPU on a straightforward page like www.mozilla.org, Fennec drag scrolling should be butter smooth. But it’s not. There is jank. I think I see two issues causing jank (there are probably more) and my wild guess is they are both related to how the viewport moves within the displayport.  

I see

1. seriously janky drag scrolling for ONLY the topmost and bottommost “screenfuls” of content. Fixed by disabling paint skipping

2. slightly janky drag scrolling as the direction of a drag scroll reverses. Not fixed by disabling paint skipping.

So with paint skipping enabled I see janky drag scrolling for ~1 screenful of content at the top and bottom of the document. The middle part of a document is OK, much less janky.  I think something funny is going on in situations where the viewport is moving but the displayport is stationary due to it hitting the top or bottom of the document.  Disabling paint skipping substantially solves this problem. 

I also think there is a similar related issue causing janky scrolling as the drag scroll direction reverses during the scroll (scrolling up/down/up/down without removing finger from screen), and I wonder if it has similar roots - the displayport not moving in the way that the viewport expects. This issue is not improved by disabling paint skipping.

I see this on four different phones running Nougat and Oreo & Fennec Nightly/Beta/Stable. I don’t see this problem on Nightly Mac Desktop. 

I managed to get various screen recordings showing the differences between paint skipping on/off which I will upload if I can (they are rather a large files) and I will admit the effect is a bit hard to see.

These jank issues are always a bit subjective. My screen recordings may be a bit meh. But I hope you take some time to really check this one out. I think I’ve shown with bug 1457702 and bug 1401526 that I have an eye for scroll jank & a forensic approach to debugging it. Maybe I can make it 3 for 3???

Steps to reproduce

Get a phone with a fairly fast CPU. Mine scores ~1400 on Geekbench 4.1 single core and has 720x1280 px screen. I think the effect exists on slower phones too, but it’s harder to see because “normal” drag scrolling tends to get a bit choppy. So, maybe a Snapdragon 7xx or 8xx CPU.

Fennec any version, I’m using Nightly 2018-08-09. You could use Beta or Stable.

Maybe this only affects phones with low-ish screen resolutions, I have only tried on phones with 720x1080 px resolution.

Settings > General > Full screen browsing OFF (to avoid bug 1457702)

apz.paint_skipping.enabled TRUE (default value)

Navigate to www.mozilla.org and make sure you’ve scrolled right to the top of the page.

Put your finger near the bottom of the screen and do a brisk drag scroll upwards. Perhaps 1-2 inches/second. I see distinct janking on the scroll, the content can jump by up to perhaps 1/4 inch at a time. 

Put your finger near the bottom and drag up the next “screenful” of content. At some point during the second screenful, the janking mostly disappears and scrolling gets much smoother.

If necessary close the blue floating navbar which says “download Firefox for Android” or whatever. It just gets in the way.

You may have to experiment with drag speeds to really see it well.

Set apz.paint_skipping.enabled FALSE

Scroll back to the top of the screen and repeat the drag scroll. It’s much smoother for the top screenful, similar to the rest of the document.

I see it on most other web pages as well, mozilla.org is easy to see. Also arstechnica.com; gsmarena.com, www.github.com/servo/webrender/issues. 

Set apz.paint_skipping.enabled TRUE (default value)

You can noodle about on the first screenful, drag scroll briskly up/down/up/down to see the jank. Now scroll down a couple of screenfuls and drag up/down/up/down, it’s distinctly smoother. If I enable and disable paint skipping and briskly scroll up and down, I see a clear difference for the “uppermost screenful” of the document. Put your finger next to the “Firefox for Android” green lozenge and drag up/down/up/down while watching how the green lozenge moves relative to your finger. It janks by perhaps 1/3 of its height. If you disable paint skipping the jank on the green lozenge is much less.

See the screen recording A and B if I can upload them. Screen recording C shows the difference in jank between uppermost screenful of content and other screenfuls of content, the effect is less obvious but it’s there.

You might also be able to see issue (2), the residual jank as the scroll direction reverses. Particularly in the central portion of a document. What I see:- when the scroll direction reverses, sometimes there are two or three distinct janks where the content jumps in the new scroll direction. Subsequent drag scrolling in the same direction is smooth. Subtle, but I think it’s there.

Set layers.acceleration.draw-fps TRUE

do the brisk drag scroll up and down. Fennec reports 60 fps during both the janky scrolls and the smooth scrolls and the build and fill times look reasonable. So I don’t think the jank is caused by the CPU choking (?)

Set layers.acceleration.draw-fps FALSE to get rid of the fps info.

Set apz.minimap.enabled TRUE to get the map of the viewport and displayport on the screen. Set apz.paint_skipping.enabled TRUE (default value).

Repeat the drag scroll tests. I think that the drag scroll is janky only when the displayport is at the very top (or bottom) of the document. For approx the "uppermost screenful" of drag scrolling, the viewport moves within the displayport, but the displayport is stationary at the top of the document. As soon as the displayport moves away from the top of the document, the jank reduces substantially.

Now set apz.y_skate_size_multiplier and apz.y_stationary_size_multiplier to large values, e.g. 5. The displayport gets larger. 

Repeat the drag scroll tests on mozilla.org. The janky drag scrolling now exists for several screenfuls of content. Again the jank reduces once the (enlarged) displayport starts moving away from the top of the document.

You can see the same effect at the bottom of the document, again when the displayport hits the bottom of the document and stops moving, the drag scrolling gets janky.

Thoughts & notes

Wild guess might be that the logic which moves the viewport within the displayport is behaving funny? Perhaps the viewport-moving logic assumes the displayport is moving when in fact it’s not when it’s at the top/bottom of the page? Or maybe your logic which sends PAINT_COMPOSITE_ONLY messages during the paint skipping drag scrolls is getting lost / out of sync? Likewise when the drag direction reverses, IIUC there is some kind of displayport strategy which decides when to start the displayport moving in the new direction. Perhaps this is affecting the viewport logic?

Fennec seems to report 60 fps throughout the janky period so perhaps the paint skipping logic is repeatedly updating the viewport position but with the same value each time, effectively the screen contents get updated at 60 fps but with repeated instances of the same scroll position????

I looked in WebIDE performance captures but I didn’t see anything exciting, just a bunch of DOM scroll events @ ~60 fps whether paint skipping was enabled or disabled.

I think if the page is very short and so the minimap is quite large, I can see the minimap viewport janking during that period while the displayport is stationary. But I might be imagining it.

I’ve seen this effect on the following phones

Sony Xperia X Compact with Oreo (Snapdragon 650 / Geekbench 4.1 single core ~1400)
Sony Xperia XA with Oreo (Helio P20 / Geekbench 4.1 single core ~800)
BQ Aquaris X5 with Nougat (Snapdragon 412 / Geekbench 4.1 single core ~500)
Alcatel OneTouch 6039Y with Marshmallow (Snapdragon 410 / Geekbench 4.1 single core ~400)

All have fairly low res screens ~720x1080, the issue might be different on very high res screens, I don’t know how viewport size and movement is affected.

It’s getting hard to see on the slower BQ & Alcatel because scrolling is bit choppy at the best of times. But now I’ve got my Mk I eyeball trained I can tell in a blind test whether paint skipping is on or off on any of these phones by comparing drag scrolling the top vs the middle of mozilla.org. How sad I am :) :) :) 

I see the same effect with add ons disabled.

I see the same effect on the Focus + GeckoView nightly channel (but of course I don’t have so many diagnostic tools to play with).

I see the same effect with Javascript disabled on either Fennec or Focus + GeckoView

Comment 8

[Mark]

Attachment: A - drag scroll mozilla paint skip on off.mp4

Attachment A drag scrolling the uppermost part of www.mozilla.org with paint skipping enabled and disabled. Look carefully at the green lozenge "Firefox for Android". I hope you can see that in the first part of the video (paint skipping enabled) there is much more scroll jank than the second part of the video (paint skipping disabled). Sony Xperia X Compact with Oreo (Snapdragon 650 / Geekbench 4.1 single core ~1400).

Comment 9

[Mark]

Attachment: B - drag scroll gsmarena paint skip on off.mp4

Attachment B drag scrolling the uppermost part of www.gsmarena.org with paint skipping enabled and disabled. Look carefully at the "Galaxy Note 9 Hands on review" text and image. I hope you can see that in the first part of the video (paint skipping enabled) there is much more scroll jank than the second part of the video (paint skipping disabled). Sony Xperia X Compact with Oreo (Snapdragon 650 / Geekbench 4.1 single core ~1400).

Comment 10

[Mark]

Attachment: C - drag scroll gsmarena different areas.mp4

Attachment C drag scrolling the www.gsmarena.com uppermost screenful vs lower screenful with paint skipping enabled.  I hope you can see that in the first part of the video (uppermost screenful) there is much more scroll jank than the second part of the video (subsequent screenful). Sony Xperia X Compact with Oreo (Snapdragon 650 / Geekbench 4.1 single core ~1400).

Comment 11

[Mark]

Final comment on the three attached videos. Try watching them at half speed in VLC or similar. It makes it easier to see the jank. Sorry for so many posts :)

Comment 12

[Kartikaya Gupta (email:[e-mail])]

Thanks for the detailed comment. I still can't reproduce this on my xperia xz1 compact which is annoying. However I would be interested to know if setting layout.frame_rate to 0 in about:config fixes the paint-skipping jank for you.

Comment 13

[Mark]

Yes it does.

I checked on my Xperia, BQ & Alcatel (see comment 7 for details). It fixes the "first screen" jank on all three

So I can fix either by disabling paint skipping or by setting layout.frame_rate to 0:-

mozilla.org   &  gsmarena.org   &   www.bbc.co.uk/news

   apz.paint_skipping.enabled   layout.frame_rate
i         TRUE                       -1           ->    jank on first screenful
ii        FALSE                      -1           ->    no jank on first screenful
iii       TRUE                        0           ->    no jank on first screenful    
iv        FALSE                       0           ->    no jank on first screenful

I killed & relaunched Firefox between each test

Re your XZ1 Compact I can't explain it, our phones our substantially similar. Yours has a somewhat faster CPU, perhaps that's it.

Or perhaps I am going maaaaaaad :)

Comment 14

[Mark]

I blew the dust off my excruciatingly slow Moto E 2 (Android 6.0) and I see the same problem and the same improvement. 

But here I think that layout.frame_rate = 0 gives less jank than apz.paint_skipping.enabled = FALSE. On my other phones I can't really see a difference between these two cases, but on the Moto I think I can:- layout.frame_rate = 0 is better.

With the various hacky fixes for bug 1401526, bug 1457702 and this bug, scrolling on my Moto is really lovely, as good with Chrome on the same hardware.

Comment 15

[Mark]

layout.frame_rate = 0 also seems to fix issue 2 from comment 7 - the jank on scroll reversal

layout.frame_rate = -1 : big jank when drag scrolling first and last "screenfuls" of content. Lesser jank when reversing direction of drag scroll on middle "screenfuls" of document

layout.frame_rate = 0 : both jank issues seem fixed

On my Sony Xperia X Compact.

Comment 16

[Mark]

I see exactly the same janky behaviour in Focus + GeckoView and in Fenix so I think it's a GeckoView issue. 

(Obviously I can't try the frame rate fix on these browsers because I have no access to about:config).

Comment 17

[Kartikaya Gupta (email:[e-mail])]

Interesting, so maybe the composite request from APZ is getting lost. That would explain the observed behavior.

I made a build with extra logging at https://treeherder.mozilla.org/#/jobs?repo=try&revision=1f9d64747ead238c1ba720f96fb6be7d19637a20 - could you run that and collect the ansroid logcat output while reproducing the jank?

Comment 18

[Mark]

This is great

With layout.frame_rate -1 (default) I see a minimum of 1 and a maximum of ~3 "bug1432019: faking vsync" messages per group of janks. I tried mozilla.org and bbc.co.uk/news.

With layout.frame_rate 0 I never see the "faking vsync" messages.

It doesn't matter how I set apz.paint_skipping.enabled, i.e. with layout.frame_rate = -1 and apz.paint_skipping.enabled = FALSE I get no jank but I still see the "faking vsync" messages.

I don't see one message per individual jank, I see 1-3 "faking vsync" messages per long drag scroll.

So for example when drag scrolling up the first page of mozilla.org I move the content perhaps 3 inches in a single drag and I see the content jank in ~10 distinct steps. I see a minimum of 1 and a maximum of ~3 "faking vsync" messages but not ~10.

If I continue to drag in the same direction screen by screen I often don't see any more "faking vsync" messages until I reverse the drag scroll direction and then I see 1-3 more. But this doesn't always seem to be the case.

Looking at the time stamps I often see a "faking vsync" message, a gap of many frames, then two messages on consecutive frames (16 ms apart):-

08-13 10:10:01.552 27613 27670 I Gecko   : bug1432019: faking vsync
08-13 10:10:01.957 27613 27670 I Gecko   : bug1432019: faking vsync
08-13 10:10:01.973 27613 27670 I Gecko   : bug1432019: faking vsync

So there seems to be a good correlation between a group of janks (when drag scrolling the first screenful or reversing drag scroll direction on subsequent screenfuls) and 1-3 "faking vsync" messages.

It's easy to see if you     grep faking    to isolate the messages.

logs to follow

Comment 19

[Mark]

Attachment: log_framerate_default.txt

layout.frame_rate = -1 (Default value) drag scrolling mozilla.org up and down first fews screenfuls. 

Plenty of "faking vsync" messages

Comment 20

[Mark]

Attachment: log_framerate_zero.txt

layout.frame_rate = 0 drag scrolling mozilla.org up and down first few screenfuls.

No "faking vsync" messages.

(NB Fennec was quit & relaunched between tests)

Comment 21

[Mark]

I also often see a single "faking sync" message towards the end of a fling when the flywheel effect is slowing down, maybe half a second before the page comes to rest. 

I often see a single scroll jank around the same time which was another bug I was going to file, but perhaps it has the same vsync cause

big fling -> release finger -> watch content flywheel -> single small jank -> page comes to rest

I don't see the jank every fling, I don't see the "faking sync" message every fling, and I am not sure the two are well correlated.

Comment 22

[Mark]

I read your notes from the Try. 

I disabled Javascript to unload the main thread as much as possible. No obvious difference to the jank or to the frequency of "faking sync" messages when scrolling www.mozilla.org.

So I don't think the main thread should be very busy, mozilla.org is a fairly simple page with no JS running... 

[remember, I have no idea what I'm talking about :) ]

Comment 23

[Mark]

I looked at my much slower BQ phone and the correlation between "faking sync" and jank is not strong at all. The BQ shows many "faking sync" messages on every scroll or fling whereas my much faster Sony only shows a few around the time of the jank. But overall the BQ is no more janky than the Sony.

On a typical 1 second fling the BQ shows ~20 "faking sync" messages, the Sony shows 0-1. But the BQ fling is smooth, comparable to the Sony. Similarly the BQ shows ~20 messages on the uppermost screenful drag scroll vs ~1-3 on the Sony. But the jank is very much the same on both phones.  Note, the BQ is faking vsync on ~half the frames on the fling or drag! But subjectively its dragging & flinging is no worse than the Sony.

Kats, maybe your Xperia XZ1 Compact (~1800 Geekbench) is fast enough to avoid any of these "faking sync" issues and the jank (?????)

So I'm confused. Perhaps some "faking sync" calls force a composite & others don't? 

Happy to dig in more if you want. Cheers



Below here is all notes, you don't need to read if you don't want to

The number of "faking vsync" messages does seem to depend on the CPU speed of the device. One of my (in)famous tables

Scrolling the first screenful of mozilla.org
                    Geekbench single core       number of "faking sync" messages
Xperia X Compact         ~1400                         1-3
Xperia XA1                ~800                         4-5
BQ Aquaris X5             ~500                         ~20


Moderate fling lasting about 1 second on mozilla.org, all JS images previously fired
                    Geekbench single core       number of "faking sync" messages
Xperia X Compact         ~1400                         0 or 1
Xperia XA1                ~800                         0-2
BQ Aquaris X5             ~500                         ~20

But the janking is very much the same on all three devices:- bad drag scrolls on first & last screenful; some jank on scroll direction reversal; pretty good jank-free flings


The BQ sometimes gives "faking vsync" messages in adjacent frames, sometimes two in the same frame (if I can believe the logcat timestamps):-

08-14 11:52:08.281  9866  9920 I Gecko   : bug1432019: faking vsync
08-14 11:52:08.282  9866  9920 I Gecko   : bug1432019: faking vsync
08-14 11:52:08.285  9866  9920 I Gecko   : bug1432019: faking vsync
08-14 11:52:08.297  9866  9920 I Gecko   : bug1432019: faking vsync     <---- !!
08-14 11:52:08.297  9866  9920 I Gecko   : bug1432019: faking vsync     <---- !!
08-14 11:52:08.330  9866  9920 I Gecko   : bug1432019: faking vsync
08-14 11:52:08.347  9866  9920 I Gecko   : bug1432019: faking vsync
08-14 11:52:08.363  9866  9920 I Gecko   : bug1432019: faking vsync
08-14 11:52:08.380  9866  9920 I Gecko   : bug1432019: faking vsync     <---- !!
08-14 11:52:08.380  9866  9920 I Gecko   : bug1432019: faking vsync     <---- !!

Comment 24

[Kartikaya Gupta (email:[e-mail])]

Hmm. Looking at the code I think there's an assumption in the vsync scheduler that only one composite request will arrive per vsync interval. If we get more than that, the mNeedsComposite counter can increment and trigger the "faking vsync" codepath. But I'm not sure id that would result in the observed jank or if it's a red herring. Here's another build for you to try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=87d6da1dbe539a96302e952412318c7691f245f9

Please collect the output again; I expect no (or much fewer) instances of the "faking vsync" output. Not sure if it will help with jank, but it might.

Comment 25

[Kartikaya Gupta (email:[e-mail])]

Another thing to try on the previous logging build is adding a new pref "gfx.vsync.compositor.unobserve-count" with a large value (around 1000 or so) and seeing if that impacts the "faking vsync" messages. If my theory from comment 24 is right it shouldn't really impact the number of faked vsyncs. The default value for that pref is 10 (https://searchfox.org/mozilla-central/rev/2466b82b729765fb0a3ab62f812c1a96a7362478/gfx/thebes/gfxPrefs.h#518)

Comment 26

[Mark]

When you say "previous logging build" do you mean the one from an hour ago (...45f9) or the one from two days ago (...7a20)?

I've been running with layout.frame_rate 60 today and it completely fixes my drag scroll jank so I think we are on the right track, it's the hardware vsync listener (or absence thereof?)

I still sometimes have a single jank on a fling, often when an image animates into view from e.g. a gray placeholder but it might be an unrelated issue? One thing at a time.

Will check out your new tests tomorrow. Cheers

Comment 27

[Kartikaya Gupta (email:[e-mail])]

Previous logging build being the one from two days ago (...7a20).

The thing is if the hardware vsync listener was broken it would show up as much more severe breakage; it must be broken in some code paths only and that's what I'm trying to pin down. Thanks for your patience with doing all these experiments!

Comment 28

[Mark]

TL;DR

build 7a20 with gfx.vsync.compositor.unobserve-count 1000 - no change to number of "faking vsync” messages or jank. Checked on Sony Xperia X Compact and BQ Aquaris.

build 4f59 reduces the number of "faking vsync” messages to near zero. I now never ever see a “faking vsync” message when I have drag scroll jank. A few “faking vsync” messages on a fling, particularly on the slower BQ. Build 4f59 does NOT improve the jank.

[I checked, the logging is working, I see some “faking vsyncs” when Fennec launches and “resuming” when I move from portrait to landscape ;)]

On BQ still seeing multiple faking vsyncs in one frame, typically on first flinging down a document, see log extracts below.

As for my patience, I enjoy it, it’s very interesting. I really want to make Fennec scrolling perfect. Glad you do too! 

layout.frame_rate 60 still working extremely well for me!

Notes:- 

build 4f59 on (faster) Sony I never see “faking vsync” messages when doing the janky drag scrolling. I see 0-2 "faking vsync" messages when I fling from top to bottom of the whole document, but then I can fling back and forth the same document over and over and I don't see any more. The 0-2 messages on a fling don’t seem particularly correlated with fling jank but I can’t really tell.

build 4f59 on (much slower) BQ the picture is almost the same:- zero “faking vsync” on drag scrolls; 5-10 on first flinging a document top to bottom.

The only difference with the BQ is there are a few more “faking vsync” messages when doing a fling down a page. Perhap 10 first time I fling down mozilla.org, but then only zero to 4 more when I fling up and down. Mostly zero.

On the BQ the faking vsync messages often come in groups of 2-6 in the same frame, see logs below where at 07:55:36.28x there are 5 in 5 milliseconds. This typically happens when first flinging down a document. Which is a little odd, it looks like your new code is supposed to lock out multiple "faking vsyncs" in a frame. We could still have a red herring??

08-15 07:55:32.823 26084 26174 I Gecko   : bug1432019: faking vsync
08-15 07:55:33.994 26084 26174 I Gecko   : bug1432019: faking vsync
08-15 07:55:34.030 26084 26174 I Gecko   : bug1432019: faking vsync
08-15 07:55:34.532 26084 26174 I Gecko   : bug1432019: faking vsync
08-15 07:55:34.533 26084 26174 I Gecko   : bug1432019: faking vsync
08-15 07:55:34.534 26084 26174 I Gecko   : bug1432019: faking vsync
08-15 07:55:34.534 26084 26174 I Gecko   : bug1432019: faking vsync
08-15 07:55:34.585 26084 26174 I Gecko   : bug1432019: faking vsync
08-15 07:55:34.590 26084 26174 I Gecko   : bug1432019: faking vsync
08-15 07:55:36.287 26084 26174 I Gecko   : bug1432019: faking vsync    <-- !!
08-15 07:55:36.288 26084 26174 I Gecko   : bug1432019: faking vsync    <-- !!
08-15 07:55:36.289 26084 26174 I Gecko   : bug1432019: faking vsync    <-- !!
08-15 07:55:36.290 26084 26174 I Gecko   : bug1432019: faking vsync    <-- !!
08-15 07:55:36.291 26084 26174 I Gecko   : bug1432019: faking vsync    <-- !!

08-15 07:59:27.913 26084 26174 I Gecko   : bug1432019: faking vsync
08-15 07:59:33.517 26084 26174 I Gecko   : bug1432019: faking vsync
08-15 07:59:33.517 26084 26174 I Gecko   : bug1432019: faking vsync
08-15 07:59:33.520 26084 26174 I Gecko   : bug1432019: faking vsync
08-15 07:59:41.280 26084 26174 I Gecko   : bug1432019: faking vsync
08-15 07:59:41.281 26084 26174 I Gecko   : bug1432019: faking vsync
08-15 07:59:42.179 26084 26174 I Gecko   : bug1432019: faking vsync    <-- !!
08-15 07:59:42.180 26084 26174 I Gecko   : bug1432019: faking vsync    <-- !!
08-15 07:59:42.180 26084 26174 I Gecko   : bug1432019: faking vsync    <-- !!
08-15 07:59:44.902 26084 26174 I Gecko   : bug1432019: faking vsync
08-15 07:59:44.902 26084 26174 I Gecko   : bug1432019: faking vsync

Comment 29

[Mark]

Just to be clear, I used layout.frame_rate -1 for these tests.

Comment 30

[Mark]

On the slower BQ, even with layout.frame_rate 60 , I still see "faking vsync" messages when flinging. And still see several in the same frame.

Not sure if that's expected... does the faking vsync codepath get called when I have layout.frame_rate 60  ?????

e.g. fling mozilla.org on BQ Aquaris (slow phone) with layout.frame_rate 60 on build 4f59 from comment 24

08-15 13:53:32.966 31405 31460 I Gecko   : bug1432019: faking vsync
08-15 13:53:33.037 31405 31460 I Gecko   : bug1432019: faking vsync
08-15 13:53:33.083 31405 31460 I Gecko   : bug1432019: faking vsync
08-15 13:53:33.089 31405 31460 I Gecko   : bug1432019: faking vsync
08-15 13:53:33.096 31405 31460 I Gecko   : bug1432019: faking vsync
08-15 13:53:33.097 31405 31460 I Gecko   : bug1432019: faking vsync
08-15 13:53:38.833 31405 31460 I Gecko   : bug1432019: faking vsync

I don't see this on the faster Sony.

Comment 31

[Mark]

I filed bug 1483605.

I think it's a different bug from what we're looing at but I am not sure. Worth keeping them separate for now?

It does make it hard to see the wood for the trees though.

Comment 32

[Mark]

I think the faking vsync stuff is a red herring. I have a Brand New Theory ;) So don't put any effort in for now, I am doing some very tedious frame by frame video analysis. It's driving me nuts. cheers

Comment 33

[Kartikaya Gupta (email:[e-mail])]

I was coming to the same conclusion. There *is* a bug with the mNeedsComposite counter and the faking vsync, but it's going to cause over-compositing, and is unrelated to the jank. I suspect the jank might be a result of the vsync messages getting bunched up and then getting processed all at once. I can make another try build with logging to see if this is the case but I can let you do your analysis first.

Comment 34

[Mark]

What is TXN?  layers.acceleration.draw-fps TRUE shows an FPS meter with TXN and other stuff. 

When I drag scroll up/down/up/down on the first screenful of a document TXN <3. That's where I see jank. If I drag up and down a few times TXN gets stuck at 0.

When I drag scroll up/down/up/down later screenfuls TXN goes up to ~30. No jank there.

On a big fling TXN can go up to 100 or more.

Why is TXN so low on that first screenful? Same on the last screenful.

I turned on touch pointer in Android > Settings > System > Developer options > Pointer Location

My frame by frame shows that on the first screenful:-

a) Gecko is correctly presenting frames to the GPU - because the numbers in the FPS meter change every single frame

b) the touch pointer is moving smoothly from frame to frame say 20 px / frame

BUT 

c) sometimes the scroll position of the document does not change frame to frame even though the FPS numbers update and the touch pointer moves. That's the jank. It can happen quite often.

The jank happens in the same region as the low TXN values. The jank & low TXN values happen when the displayport is "against its end stops" at the top or bottom of the document. If I enlarge the displayport the low TXN / janky region extends further into the document.

Changing paint skipping or layout.frame_rate doesn't affect TXN but improves the jank.


So I think the jank is related to the low TXN. But I don't know what TXN is :)

I think bug 1483605 might be related, the jank there might be the transition from "low TXN" to "high TXN" region.

Maybe?

Comment 35

[Mark]

Attachment: scroll jank fennec aug 2018 reduced.pdf

FWIW here is some frame by frame analysis of Fennec janking on www.mozilla.org. I'll upload the videos sometime!

Hope it makes sense

Comment 36

[Mark]

Attachment: Fennec default missing frames.mp4

Video to accompany previous pdf analaysis in attachment 9001646 [details]

Comment 37

[Kartikaya Gupta (email:[e-mail])]

(In reply to Mark from comment #34)
> What is TXN?  layers.acceleration.draw-fps TRUE shows an FPS meter with TXN
> and other stuff. 

TXN refers to the number of transactions sent from the main thread to the compositor. Generally this will be zero while doing async scrolling within the displayport area (and assuming there's no paints happening for other reasons like JS animations etc) and be non-zero when the displayport is moving.

> When I drag scroll up/down/up/down on the first screenful of a document TXN
> <3. That's where I see jank. If I drag up and down a few times TXN gets
> stuck at 0.

The TXN numbers here seem reasonable; the first screenful will be sending over the displayport and then while scrolling within that displayport area there's no more transactions so you see a value of zero.

> When I drag scroll up/down/up/down later screenfuls TXN goes up to ~30. No
> jank there.

Yeah as the displayport moves the main thread will be sending over painted content and/or other info to the compositor.

> a) Gecko is correctly presenting frames to the GPU - because the numbers in
> the FPS meter change every single frame
> 
> b) the touch pointer is moving smoothly from frame to frame say 20 px / frame
> 
> BUT 
> 
> c) sometimes the scroll position of the document does not change frame to
> frame even though the FPS numbers update and the touch pointer moves. That's
> the jank. It can happen quite often.

Ah, this is interesting. It implies that even though we're getting a vsync/composite at the right time, the sampled APZ scroll position is not correct. This, in turn, might be because of an incorrect timestamp getting passed to the APZ sampling function.

I'll make another try build with more logging.

Comment 38

[Mark]

Do you think this bug should get a better title? Up to you.

Comment 39

[Mark]

I filed bug 1484187. It would make my analysis easier.

Comment 40

[Mark]

Attachment: fling jank pop in fennec aug 2018 reduced.pdf

I checked and the same thing happens on flings with images popping in (I think it's Javascript but am not sure). Presumably the same cause - something to do with timestamps?? Example here is consecutive frames left to right, you can see one frame doesn't move as far as the others. But it doesn't move zero distance either so it's not a lost frame or lost scroll message????

It leads to jank during flings when an image is popping in from (e.g.) a gray placeholder. I remember filing a bug on this a while ago but can't find it.  Attached example is from bbc.co.uk/news but I can see it on mozilla.org as well.

I wonder if this issue is the main cause of jank on Fennec & Focus + GeckoView??? IMHO they are pretty janky ATM.

Comment 41

[Mark]

> I remember filing a bug on this a while ago but can't find it. 
I found it: I think bug 1432021 is the same as comment 40 here.

Comment 42

[Mark]

Hi Kats, if you want to pick up on this again I am happy to do some tests. Comment 37 should give you a recap - a Try with timestamp logging around the APZ sample code?? Cheers Mark

Comment 43

[Kartikaya Gupta (email:[e-mail])]

Sorry, I lost track of this when I went on leave. Here's a build with the logging:

https://treeherder.mozilla.org/#/jobs?repo=try&bugfiler=&group_state=expanded&revision=362962a4da16becafe1576325aaf701051f66ed2

Hopefully we can take a look at the numbers it spews out and see if we're missing samples.

Comment 44

[Mark]

I don’t fully understand the numbers. When there is jank, sometimes APZSampling doesn’t increment in ~16 ms intervals. Often the scroll offset (7: numbers) get stuck, that’s the jank. But sometimes the scroll offset numbers get stuck even when the APZSampling number is incrementing properly. But when the scrolling is butter smooth both APZSampling and scroll offset numbers increment in very sensible ways.

Hope it makes some sense to you, I am intrigued



This is a very janky scroll at the top section of the page (mozilla.org) 

Here the APZSampling numbers go eg 2289843.959074 / 2289860.674439 / 2289866.932251 / 2289894.006418 / 2289902.179908 which is a time offset of 17 / 6 / 28 / 8 ms. And the effective scroll offset doesn’t increment for a while, it sticks at 7:42.5 and then a long run of 7:50.0

10-10 16:41:36.774 10256 10368 I Gecko   : APZSampling at 2289612.029335 -> sampleTime 2289626.935636 7:5.500000 3:0.000000
10-10 16:41:36.789 10256 10368 I Gecko   : APZSampling at 2289627.500012 -> sampleTime 2289643.580168 7:8.000000 3:0.000000
10-10 16:41:36.805 10256 10368 I Gecko   : APZSampling at 2289643.406418 -> sampleTime 2289659.746105 7:10.500000 3:0.000000
10-10 16:41:36.822 10256 10368 I Gecko   : APZSampling at 2289660.261887 -> sampleTime 2289676.493136 7:13.000000 3:0.000000
10-10 16:41:36.839 10256 10368 I Gecko   : APZSampling at 2289677.205429 -> sampleTime 2289693.206417 7:16.000000 3:0.000000
10-10 16:41:36.855 10256 10368 I Gecko   : APZSampling at 2289693.602824 -> sampleTime 2289709.911990 7:19.000000 3:0.000000
10-10 16:41:36.872 10256 10368 I Gecko   : APZSampling at 2289710.188293 -> sampleTime 2289726.478657 7:19.000000 3:0.000000
10-10 16:41:36.889 10256 10368 I Gecko   : APZSampling at 2289726.972251 -> sampleTime 2289743.355584 7:25.000000 3:0.000000
10-10 16:41:36.906 10256 10368 I Gecko   : APZSampling at 2289743.834074 -> sampleTime 2289760.104334 7:25.000000 3:0.000000
10-10 16:41:36.923 10256 10368 I Gecko   : APZSampling at 2289760.656783 -> sampleTime 2289776.939074 7:28.000000 3:0.000000
10-10 16:41:36.939 10256 10368 I Gecko   : APZSampling at 2289777.144126 -> sampleTime 2289793.568397 7:31.000000 3:0.000000
10-10 16:41:36.956 10256 10368 I Gecko   : APZSampling at 2289793.813554 -> sampleTime 2289810.190011 7:36.500000 3:0.000000
10-10 16:41:36.973 10256 10368 I Gecko   : APZSampling at 2289810.800741 -> sampleTime 2289827.062147 7:36.500000 3:0.000000
10-10 16:41:36.989 10256 10368 I Gecko   : APZSampling at 2289827.142564 -> sampleTime 2289843.583865 7:39.500000 3:0.000000
10-10 16:41:37.006 10256 10368 I Gecko   : APZSampling at 2289843.959074 -> sampleTime 2289860.257615 7:42.500000 3:0.000000
10-10 16:41:37.023 10256 10368 I Gecko   : APZSampling at 2289860.674439 -> sampleTime 2289876.985792 7:50.000000 3:0.000000
10-10 16:41:37.029 10256 10368 I Gecko   : APZSampling at 2289866.932251 -> sampleTime 2289883.364490 7:50.000000 3:0.000000
10-10 16:41:37.056 10256 10368 I Gecko   : APZSampling at 2289894.006418 -> sampleTime 2289910.194855 7:50.000000 3:0.000000
10-10 16:41:37.064 10256 10368 I Gecko   : APZSampling at 2289902.179908 -> sampleTime 2289918.471469 7:50.000000 3:0.000000
10-10 16:41:37.090 10256 10368 I Gecko   : APZSampling at 2289927.683866 -> sampleTime 2289943.995011 7:50.000000 3:0.000000
10-10 16:41:37.123 10256 10368 I Gecko   : APZSampling at 2289960.967303 -> sampleTime 2289977.312251 7:50.000000 3:0.000000
10-10 16:41:37.139 10256 10368 I Gecko   : APZSampling at 2289977.389231 -> sampleTime 2289993.822511 7:50.000000 3:0.000000
10-10 16:41:37.156 10256 10368 I Gecko   : APZSampling at 2289994.467095 -> sampleTime 2290010.682251 7:50.000000 3:0.000000
10-10 16:41:37.173 10256 10368 I Gecko   : APZSampling at 2290011.158345 -> sampleTime 2290027.578865 7:50.000000 3:0.000000
10-10 16:41:37.190 10256 10368 I Gecko   : APZSampling at 2290027.674960 -> sampleTime 2290043.954647 7:50.000000 3:0.000000
10-10 16:41:37.206 10256 10368 I Gecko   : APZSampling at 2290044.530116 -> sampleTime 2290060.816782 7:50.000000 3:0.000000
10-10 16:41:37.223 10256 10368 I Gecko   : APZSampling at 2290061.095220 -> sampleTime 2290077.539282 7:50.000000 3:0.000000
10-10 16:41:37.240 10256 10368 I Gecko   : APZSampling at 2290077.809074 -> sampleTime 2290093.996834 7:50.000000 3:0.000000
10-10 16:41:37.256 10256 10368 I Gecko   : APZSampling at 2290094.528345 -> sampleTime 2290110.961209 7:50.000000 3:0.000000
10-10 16:41:37.273 10256 10368 I Gecko   : APZSampling at 2290111.392303 -> sampleTime 2290127.674021 7:50.000000 3:0.000000
10-10 16:41:37.290 10256 10368 I Gecko   : APZSampling at 2290127.938345 -> sampleTime 2290144.127928 7:50.000000 3:0.000000
10-10 16:41:37.307 10256 10368 I Gecko   : APZSampling at 2290144.815064 -> sampleTime 2290161.061157 7:55.500000 3:0.000000
10-10 16:41:37.323 10256 10368 I Gecko   : APZSampling at 2290161.373189 -> sampleTime 2290177.806990 7:55.500000 3:0.000000
10-10 16:41:37.340 10256 10368 I Gecko   : APZSampling at 2290177.891522 -> sampleTime 2290194.323917 7:59.500000 3:0.000000
10-10 16:41:37.357 10256 10368 I Gecko   : APZSampling at 2290194.917564 -> sampleTime 2290211.212824 7:63.000000 3:0.000000
10-10 16:41:37.373 10256 10368 I Gecko   : APZSampling at 2290211.640428 -> sampleTime 2290227.914803 7:66.500000 3:0.000000
10-10 16:41:37.390 10256 10368 I Gecko   : APZSampling at 2290228.320793 -> sampleTime 2290244.615428 7:69.500000 3:0.000000
10-10 16:41:37.407 10256 10368 I Gecko   : APZSampling at 2290245.031262 -> sampleTime 2290261.327928 7:72.500000 3:0.000000
10-10 16:41:37.424 10256 10368 I Gecko   : APZSampling at 2290261.847564 -> sampleTime 2290278.020271 7:75.500000 3:0.000000
10-10 16:41:37.440 10256 10368 I Gecko   : APZSampling at 2290278.429074 -> sampleTime 2290294.725167 7:79.000000 3:0.000000
10-10 16:41:37.457 10256 10368 I Gecko   : APZSampling at 2290295.139335 -> sampleTime 2290311.426001 7:87.000000 3:0.000000
10-10 16:41:37.474 10256 10368 I Gecko   : APZSampling at 2290311.851314 -> sampleTime 2290328.150167 7:87.000000 3:0.000000
10-10 16:41:37.491 10256 10368 I Gecko   : APZSampling at 2290329.037147 -> sampleTime 2290344.876626 7:93.000000 3:0.000000
10-10 16:41:37.507 10256 10368 I Gecko   : APZSampling at 2290345.276366 -> sampleTime 2290361.581053 7:93.000000 3:0.000000
10-10 16:41:37.524 10256 10368 I Gecko   : APZSampling at 2290362.126626 -> sampleTime 2290378.411105 7:96.500000 3:0.000000
10-10 16:41:37.540 10256 10368 I Gecko   : APZSampling at 2290378.492095 -> sampleTime 2290394.926626 7:100.500000 3:0.000000
10-10 16:41:37.557 10256 10368 I Gecko   : APZSampling at 2290395.637668 -> sampleTime 2290411.642615 7:108.000000 3:0.000000
10-10 16:41:37.575 10256 10368 I Gecko   : APZSampling at 2290412.827512 -> sampleTime 2290428.131990 7:111.500000 3:0.000000
10-10 16:41:37.592 10256 10368 I Gecko   : APZSampling at 2290429.693970 -> sampleTime 2290445.761053 7:115.000000 3:0.000000
10-10 16:41:37.607 10256 10368 I Gecko   : APZSampling at 2290445.368814 -> sampleTime 2290461.581626 7:115.000000 3:0.000000
10-10 16:41:37.624 10256 10368 I Gecko   : APZSampling at 2290462.216887 -> sampleTime 2290478.497146 7:118.500000 3:0.000000
10-10 16:41:37.641 10256 10368 I Gecko   : APZSampling at 2290479.033814 -> sampleTime 2290495.369334 7:122.500000 3:0.000000
10-10 16:41:37.658 10256 10368 I Gecko   : APZSampling at 2290495.872407 -> sampleTime 2290511.847563 7:130.500000 3:0.000000
10-10 16:41:37.674 10256 10368 I Gecko   : APZSampling at 2290512.343137 -> sampleTime 2290528.681157 7:130.500000 3:0.000000
10-10 16:41:37.691 10256 10368 I Gecko   : APZSampling at 2290528.837772 -> sampleTime 2290545.047823 7:138.500000 3:0.000000
10-10 16:41:37.707 10256 10368 I Gecko   : APZSampling at 2290545.616209 -> sampleTime 2290561.952250 7:138.500000 3:0.000000
10-10 16:41:37.724 10256 10368 I Gecko   : APZSampling at 2290562.466209 -> sampleTime 2290578.759594 7:142.500000 3:0.000000
10-10 16:41:37.741 10256 10368 I Gecko   : APZSampling at 2290579.136730 -> sampleTime 2290595.426938 7:146.500000 3:0.000000
10-10 16:41:37.758 10256 10368 I Gecko   : APZSampling at 2290595.841209 -> sampleTime 2290612.101365 7:151.500000 3:0.000000
10-10 16:41:37.775 10256 10368 I Gecko   : APZSampling at 2290613.148657 -> sampleTime 2290628.869021 7:159.500000 3:0.000000
10-10 16:41:37.791 10256 10368 I Gecko   : APZSampling at 2290629.181157 -> sampleTime 2290645.364750 7:159.500000 3:0.000000
10-10 16:41:37.808 10256 10368 I Gecko   : APZSampling at 2290645.979334 -> sampleTime 2290662.236990 7:163.500000 3:0.000000
10-10 16:41:37.824 10256 10368 I Gecko   : APZSampling at 2290662.517147 -> sampleTime 2290678.959855 7:167.500000 3:0.000000
10-10 16:41:37.841 10256 10368 I Gecko   : APZSampling at 2290679.335949 -> sampleTime 2290695.472719 7:171.500000 3:0.000000
10-10 16:41:37.858 10256 10368 I Gecko   : APZSampling at 2290696.057616 -> sampleTime 2290712.371365 7:176.000000 3:0.000000
10-10 16:41:37.875 10256 10368 I Gecko   : APZSampling at 2290712.881470 -> sampleTime 2290729.112563 7:180.000000 3:0.000000
10-10 16:41:37.891 10256 10368 I Gecko   : APZSampling at 2290729.523137 -> sampleTime 2290745.798969 7:184.000000 3:0.000000
10-10 16:41:37.908 10256 10368 I Gecko   : APZSampling at 2290746.244751 -> sampleTime 2290762.530532 7:188.000000 3:0.000000
10-10 16:41:37.925 10256 10368 I Gecko   : APZSampling at 2290762.921105 -> sampleTime 2290779.222615 7:192.000000 3:0.000000
10-10 16:41:37.941 10256 10368 I Gecko   : APZSampling at 2290779.492616 -> sampleTime 2290795.934230 7:196.000000 3:0.000000
10-10 16:41:37.958 10256 10368 I Gecko   : APZSampling at 2290796.405897 -> sampleTime 2290812.936417 7:204.000000 3:0.000000
10-10 16:41:37.966 10256 10368 I Gecko   : APZSampling at 2290804.098397 -> sampleTime 2290814.193396 7:204.000000 3:0.000000
10-10 16:41:37.992 10256 10368 I Gecko   : APZSampling at 2290829.750845 -> sampleTime 2290846.032980 7:207.000000 3:0.000000
10-10 16:41:38.008 10256 10368 I Gecko   : APZSampling at 2290846.467251 -> sampleTime 2290862.758084 7:210.500000 3:0.000000
10-10 16:41:38.025 10256 10368 I Gecko   : APZSampling at 2290863.206886 -> sampleTime 2290879.495427 7:214.000000 3:0.000000
10-10 16:41:38.042 10256 10368 I Gecko   : APZSampling at 2290880.086261 -> sampleTime 2290896.372302 7:218.000000 3:0.000000
10-10 16:41:38.059 10256 10368 I Gecko   : APZSampling at 2290896.700168 -> sampleTime 2290912.890219 7:222.000000 3:0.000000
10-10 16:41:38.075 10256 10368 I Gecko   : APZSampling at 2290913.298397 -> sampleTime 2290929.589959 7:225.500000 3:0.000000
10-10 16:41:38.092 10256 10368 I Gecko   : APZSampling at 2290930.001001 -> sampleTime 2290946.291469 7:228.500000 3:0.000000
10-10 16:41:38.109 10256 10368 I Gecko   : APZSampling at 2290946.763397 -> sampleTime 2290962.998865 7:231.500000 3:0.000000
10-10 16:41:38.125 10256 10368 I Gecko   : APZSampling at 2290963.267980 -> sampleTime 2290979.704698 7:234.500000 3:0.000000
10-10 16:41:38.143 10256 10368 I Gecko   : APZSampling at 2290980.481678 -> sampleTime 2290996.927511 7:240.000000 3:0.000000
10-10 16:41:38.149 10256 10368 I Gecko   : APZSampling at 2290987.545116 -> sampleTime 2290997.393865 7:240.000000 3:0.000000
10-10 16:41:38.175 10256 10368 I Gecko   : APZSampling at 2291013.550584 -> sampleTime 2291029.861417 7:243.000000 3:0.000000
10-10 16:41:38.192 10256 10368 I Gecko   : APZSampling at 2291030.346209 -> sampleTime 2291046.543500 7:245.000000 3:0.000000
10-10 16:41:38.209 10256 10368 I Gecko   : APZSampling at 2291046.952303 -> sampleTime 2291063.332042 7:247.000000 3:0.000000
10-10 16:41:38.225 10256 10368 I Gecko   : APZSampling at 2291063.544959 -> sampleTime 2291079.983292 7:249.000000 3:0.000000
10-10 16:41:38.242 10256 10368 I Gecko   : APZSampling at 2291080.540480 -> sampleTime 2291096.537042 7:250.000000 3:0.000000
10-10 16:41:38.259 10256 10368 I Gecko   : APZSampling at 2291097.124699 -> sampleTime 2291113.412354 7:250.000000 3:0.000000
10-10 16:41:38.703 10256 10368 I Gecko   : APZSampling at 2291540.906626 -> sampleTime 2291557.319386 7:250.000000 3:0.000000
10-10 16:41:39.118 10256 10368 I Gecko   : APZSampling at 2291956.499751 -> sampleTime 2291973.076208 7:250.000000 3:0.000000


This is a much less janky scroll in the middle of the page (mozilla.org), I truncated off the first quarter inch of movement which is still janky, but this is a smooth drag after that initial jank period is over. It looked butter smooth to my (Mk1) eyeball. Here APZSampling increments smoothly by ~16 ms/sample and the scroll offset seems to change smoothly too, by a ~2 px (?) / sample.

10-10 16:42:50.326 10256 10368 I Gecko   : APZSampling at 2363164.442015 -> sampleTime 2363179.178994 7:1203.598877 3:0.000000
10-10 16:42:50.343 10256 10368 I Gecko   : APZSampling at 2363181.482640 -> sampleTime 2363195.875869 7:1205.598877 3:0.000000
10-10 16:42:50.360 10256 10368 I Gecko   : APZSampling at 2363198.581598 -> sampleTime 2363212.823004 7:1207.598877 3:0.000000
10-10 16:42:50.379 10256 10368 I Gecko   : APZSampling at 2363217.093890 -> sampleTime 2363229.427171 7:1209.598877 3:0.000000
10-10 16:42:50.394 10256 10368 I Gecko   : APZSampling at 2363232.439776 -> sampleTime 2363246.086494 7:1211.098877 3:0.000000
10-10 16:42:50.410 10256 10368 I Gecko   : APZSampling at 2363247.920869 -> sampleTime 2363264.434983 7:1213.098877 3:0.000000
10-10 16:42:50.428 10256 10368 I Gecko   : APZSampling at 2363266.294828 -> sampleTime 2363266.014775 7:1214.598877 3:0.000000
10-10 16:42:50.444 10256 10368 I Gecko   : APZSampling at 2363281.673630 -> sampleTime 2363296.070348 7:1215.598877 3:0.000000
10-10 16:42:50.461 10256 10368 I Gecko   : APZSampling at 2363299.123578 -> sampleTime 2363312.732431 7:1217.098877 3:0.000000
10-10 16:42:50.479 10256 10368 I Gecko   : APZSampling at 2363316.846286 -> sampleTime 2363329.761702 7:1218.598877 3:0.000000
10-10 16:42:50.496 10256 10368 I Gecko   : APZSampling at 2363333.697171 -> sampleTime 2363347.392379 7:1220.098877 3:0.000000
10-10 16:42:50.512 10256 10368 I Gecko   : APZSampling at 2363350.020192 -> sampleTime 2363363.205035 7:1221.598877 3:0.000000
10-10 16:42:50.528 10256 10368 I Gecko   : APZSampling at 2363366.572067 -> sampleTime 2363379.666754 7:1223.598877 3:0.000000
10-10 16:42:50.546 10256 10368 I Gecko   : APZSampling at 2363383.740140 -> sampleTime 2363396.521702 7:1225.598877 3:0.000000
10-10 16:42:50.562 10256 10368 I Gecko   : APZSampling at 2363399.865557 -> sampleTime 2363413.323525 7:1227.598877 3:0.000000
10-10 16:42:50.579 10256 10368 I Gecko   : APZSampling at 2363417.607953 -> sampleTime 2363429.800244 7:1229.598877 3:0.000000
10-10 16:42:50.596 10256 10368 I Gecko   : APZSampling at 2363433.830036 -> sampleTime 2363446.726962 7:1231.598877 3:0.000000
10-10 16:42:50.613 10256 10368 I Gecko   : APZSampling at 2363450.683786 -> sampleTime 2363463.534566 7:1233.598877 3:0.000000
10-10 16:42:50.629 10256 10368 I Gecko   : APZSampling at 2363467.585244 -> sampleTime 2363481.467119 7:1235.598877 3:0.000000
10-10 16:42:50.645 10256 10368 I Gecko   : APZSampling at 2363482.967275 -> sampleTime 2363496.918525 7:1237.598877 3:0.000000
10-10 16:42:50.662 10256 10368 I Gecko   : APZSampling at 2363500.233057 -> sampleTime 2363513.473056 7:1239.598877 3:0.000000
10-10 16:42:50.679 10256 10368 I Gecko   : APZSampling at 2363517.569202 -> sampleTime 2363530.326181 7:1241.598877 3:0.000000
10-10 16:42:50.694 10256 10368 I Gecko   : APZSampling at 2363532.584827 -> sampleTime 2363546.799723 7:1243.598877 3:0.000000
10-10 16:42:50.712 10256 10368 I Gecko   : APZSampling at 2363550.030088 -> sampleTime 2363563.585868 7:1246.098877 3:0.000000
10-10 16:42:50.730 10256 10368 I Gecko   : APZSampling at 2363567.767588 -> sampleTime 2363580.417118 7:1248.598877 3:0.000000
10-10 16:42:50.746 10256 10368 I Gecko   : APZSampling at 2363584.005869 -> sampleTime 2363597.127118 7:1251.098877 3:0.000000
10-10 16:42:50.763 10256 10368 I Gecko   : APZSampling at 2363600.961077 -> sampleTime 2363613.744618 7:1253.598877 3:0.000000
10-10 16:42:50.783 10256 10368 I Gecko   : APZSampling at 2363620.998838 -> sampleTime 2363630.643056 7:1256.098877 3:0.000000
10-10 16:42:50.796 10256 10368 I Gecko   : APZSampling at 2363633.775505 -> sampleTime 2363648.897014 7:1258.598877 3:0.000000
10-10 16:42:50.812 10256 10368 I Gecko   : APZSampling at 2363650.410869 -> sampleTime 2363663.801077 7:1260.598877 3:0.000000
10-10 16:42:50.830 10256 10368 I Gecko   : APZSampling at 2363667.803369 -> sampleTime 2363680.535400 7:1263.098877 3:0.000000
10-10 16:42:50.846 10256 10368 I Gecko   : APZSampling at 2363683.845921 -> sampleTime 2363697.156493 7:1265.598877 3:0.000000
10-10 16:42:50.862 10256 10368 I Gecko   : APZSampling at 2363700.430661 -> sampleTime 2363713.916962 7:1268.598877 3:0.000000
10-10 16:42:50.880 10256 10368 I Gecko   : APZSampling at 2363718.219411 -> sampleTime 2363730.569670 7:1271.598877 3:0.000000
10-10 16:42:50.896 10256 10368 I Gecko   : APZSampling at 2363734.378786 -> sampleTime 2363747.569827 7:1274.598877 3:0.000000
10-10 16:42:50.912 10256 10368 I Gecko   : APZSampling at 2363750.364827 -> sampleTime 2363764.135400 7:1275.098877 3:0.000000
10-10 16:42:50.929 10256 10368 I Gecko   : APZSampling at 2363767.180921 -> sampleTime 2363780.950920 7:1275.098877 3:0.000000
10-10 16:42:50.946 10256 10368 I Gecko   : APZSampling at 2363783.771077 -> sampleTime 2363797.627275 7:1275.098877 3:0.000000
10-10 16:42:50.962 10256 10368 I Gecko   : APZSampling at 2363800.439098 -> sampleTime 2363814.144775 7:1275.098877 3:0.000000
10-10 16:42:50.979 10256 10368 I Gecko   : APZSampling at 2363817.423629 -> sampleTime 2363830.910139 7:1275.098877 3:0.000000
10-10 16:42:50.995 10256 10368 I Gecko   : APZSampling at 2363833.561338 -> sampleTime 2363848.289566 7:1275.098877 3:0.000000
10-10 16:42:51.013 10256 10368 I Gecko   : APZSampling at 2363851.262796 -> sampleTime 2363864.729202 7:1275.098877 3:0.000000
10-10 16:42:51.029 10256 10368 I Gecko   : APZSampling at 2363867.425713 -> sampleTime 2363881.145035 7:1275.098877 3:0.000000
10-10 16:42:51.046 10256 10368 I Gecko   : APZSampling at 2363883.704567 -> sampleTime 2363898.519879 7:1275.098877 3:0.000000
10-10 16:42:51.370 10256 10368 I Gecko   : APZSampling at 2364208.291025 -> sampleTime 2364224.698629 7:1275.098877 3:0.000000
10-10 16:42:51.786 10256 10368 I Gecko   : APZSampling at 2364624.164462 -> sampleTime 2364640.737274 7:1275.098877 3:0.000000

Comment 45

[Mark]

My bad: the very long run of fixed scroll offset (7:50.000000 in comment 44) is the toolbar hiding itself as I scroll. If I disable Full-screen browsing so the toolbar is always visible that issue goes away. But I still see lots of duplicate scroll offset positions during jank on the first screen:-

New example drag scrolling top part of mozilla.org, toolbar does not auto hide, lots of duplicate scroll offsets

10-10 17:24:27.585  4858  4979 I Gecko   : APZSampling at 402410.312398 -> sampleTime 402426.880314 5:2.500000 3:0.000000
10-10 17:24:27.601  4858  4979 I Gecko   : APZSampling at 402426.605471 -> sampleTime 402442.711148 5:5.500000 3:0.000000
10-10 17:24:27.617  4858  4979 I Gecko   : APZSampling at 402442.594482 -> sampleTime 402459.016460 5:5.500000 3:0.000000
10-10 17:24:27.634  4858  4979 I Gecko   : APZSampling at 402459.689013 -> sampleTime 402475.899898 5:11.500000 3:0.000000
10-10 17:24:27.651  4858  4979 I Gecko   : APZSampling at 402476.162867 -> sampleTime 402492.381669 5:14.500000 3:0.000000
10-10 17:24:27.666  4858  4979 I Gecko   : APZSampling at 402491.827398 -> sampleTime 402508.190314 5:14.500000 3:0.000000
10-10 17:24:27.685  4858  4979 I Gecko   : APZSampling at 402509.951253 -> sampleTime 402525.953648 5:20.500000 3:0.000000
10-10 17:24:27.700  4858  4979 I Gecko   : APZSampling at 402525.275367 -> sampleTime 402541.643752 5:20.500000 3:0.000000
10-10 17:24:27.717  4858  4979 I Gecko   : APZSampling at 402542.057659 -> sampleTime 402558.285991 5:24.000000 3:0.000000
10-10 17:24:27.733  4858  4979 I Gecko   : APZSampling at 402558.767242 -> sampleTime 402574.997346 5:26.500000 3:0.000000
10-10 17:24:27.750  4858  4979 I Gecko   : APZSampling at 402575.711148 -> sampleTime 402591.701043 5:30.000000 3:0.000000
10-10 17:24:27.767  4858  4979 I Gecko   : APZSampling at 402592.463700 -> sampleTime 402608.614377 5:34.000000 3:0.000000
10-10 17:24:27.784  4858  4979 I Gecko   : APZSampling at 402609.507971 -> sampleTime 402625.361825 5:42.000000 3:0.000000
10-10 17:24:27.801  4858  4979 I Gecko   : APZSampling at 402626.282138 -> sampleTime 402642.206200 5:45.500000 3:0.000000
10-10 17:24:27.817  4858  4979 I Gecko   : APZSampling at 402642.728805 -> sampleTime 402658.972554 5:45.500000 3:0.000000
10-10 17:24:27.834  4858  4979 I Gecko   : APZSampling at 402659.542919 -> sampleTime 402675.760679 5:48.500000 3:0.000000
10-10 17:24:27.851  4858  4979 I Gecko   : APZSampling at 402676.706096 -> sampleTime 402692.492241 5:56.500000 3:0.000000
10-10 17:24:27.868  4858  4979 I Gecko   : APZSampling at 402692.886617 -> sampleTime 402709.172346 5:61.000000 3:0.000000
10-10 17:24:27.884  4858  4979 I Gecko   : APZSampling at 402709.656721 -> sampleTime 402725.946096 5:61.000000 3:0.000000
10-10 17:24:27.901  4858  4979 I Gecko   : APZSampling at 402726.775107 -> sampleTime 402742.713023 5:70.000000 3:0.000000
10-10 17:24:27.918  4858  4979 I Gecko   : APZSampling at 402743.191825 -> sampleTime 402759.475939 5:70.000000 3:0.000000
10-10 17:24:27.935  4858  4979 I Gecko   : APZSampling at 402760.109742 -> sampleTime 402776.503127 5:79.000000 3:0.000000
10-10 17:24:27.956  4858  4979 I Gecko   : APZSampling at 402781.285419 -> sampleTime 402793.215366 5:84.000000 3:0.000000
10-10 17:24:27.968  4858  4979 I Gecko   : APZSampling at 402793.642763 -> sampleTime 402809.965106 5:84.000000 3:0.000000
10-10 17:24:27.985  4858  4979 I Gecko   : APZSampling at 402810.548804 -> sampleTime 402826.645470 5:93.500000 3:0.000000
10-10 17:24:28.002  4858  4979 I Gecko   : APZSampling at 402827.084013 -> sampleTime 402842.656929 5:98.000000 3:0.000000
10-10 17:24:28.013  4858  4979 I Gecko   : APZSampling at 402838.739638 -> sampleTime 402855.252970 5:98.000000 3:0.000000
10-10 17:24:28.021  4858  4979 I Gecko   : APZSampling at 402846.219221 -> sampleTime 402859.664741 5:102.500000 3:0.000000
10-10 17:24:28.036  4858  4979 I Gecko   : APZSampling at 402861.021461 -> sampleTime 402876.032762 5:108.000000 3:0.000000
10-10 17:24:28.051  4858  4979 I Gecko   : APZSampling at 402876.649065 -> sampleTime 402892.636668 5:108.000000 3:0.000000
10-10 17:24:28.068  4858  4979 I Gecko   : APZSampling at 402893.249690 -> sampleTime 402909.512918 5:112.000000 3:0.000000
10-10 17:24:28.085  4858  4979 I Gecko   : APZSampling at 402910.062346 -> sampleTime 402926.288543 5:116.000000 3:0.000000
10-10 17:24:28.102  4858  4979 I Gecko   : APZSampling at 402926.968232 -> sampleTime 402943.189220 5:120.000000 3:0.000000
10-10 17:24:28.119  4858  4979 I Gecko   : APZSampling at 402944.607034 -> sampleTime 402960.526773 5:124.500000 3:0.000000
10-10 17:24:28.136  4858  4979 I Gecko   : APZSampling at 402961.407502 -> sampleTime 402976.920470 5:134.000000 3:0.000000
10-10 17:24:28.152  4858  4979 I Gecko   : APZSampling at 402977.420106 -> sampleTime 402993.427866 5:134.000000 3:0.000000
10-10 17:24:28.169  4858  4979 I Gecko   : APZSampling at 402994.043440 -> sampleTime 403010.022241 5:142.000000 3:0.000000
10-10 17:24:28.185  4858  4979 I Gecko   : APZSampling at 403010.598127 -> sampleTime 403027.077814 5:146.000000 3:0.000000
10-10 17:24:28.203  4858  4979 I Gecko   : APZSampling at 403027.440784 -> sampleTime 403043.742970 5:150.500000 3:0.000000
10-10 17:24:28.219  4858  4979 I Gecko   : APZSampling at 403044.000263 -> sampleTime 403060.239168 5:155.500000 3:0.000000
10-10 17:24:28.235  4858  4979 I Gecko   : APZSampling at 403060.833440 -> sampleTime 403077.153960 5:155.500000 3:0.000000
10-10 17:24:28.254  4858  4979 I Gecko   : APZSampling at 403079.369117 -> sampleTime 403094.207970 5:163.500000 3:0.000000
10-10 17:24:28.269  4858  4979 I Gecko   : APZSampling at 403094.143336 -> sampleTime 403109.971147 5:168.000000 3:0.000000
10-10 17:24:28.286  4858  4979 I Gecko   : APZSampling at 403110.792554 -> sampleTime 403127.287762 5:172.000000 3:0.000000
10-10 17:24:28.291  4858  4979 I Gecko   : APZSampling at 403116.640836 -> sampleTime 403127.892710 5:172.000000 3:0.000000

No change to the scrolling middle of page example.

Comment 46

[Mark]

On the fling inertia scroll with JavaScript images popping in, there is a jank and there seems to be a stumble around APZSampling timestamp 1193966.097565 ??? This is bbc.co.uk/news.

10-10 17:37:39.019  4858  4979 I Gecko   : APZSampling at 1193844.139649 -> sampleTime 1193859.996523 26:315.220276 3:0.000000
10-10 17:37:39.035  4858  4979 I Gecko   : APZSampling at 1193860.677930 -> sampleTime 1193876.699648 26:355.570221 3:0.000000
10-10 17:37:39.052  4858  4979 I Gecko   : APZSampling at 1193877.575221 -> sampleTime 1193893.854075 26:394.239288 3:0.000000
10-10 17:37:39.069  4858  4979 I Gecko   : APZSampling at 1193894.423138 -> sampleTime 1193910.677200 26:432.631165 3:0.000000
10-10 17:37:39.086  4858  4979 I Gecko   : APZSampling at 1193911.064961 -> sampleTime 1193927.413554 26:469.043701 3:0.000000
10-10 17:37:39.103  4858  4979 I Gecko   : APZSampling at 1193928.699805 -> sampleTime 1193944.877617 26:503.776886 3:0.000000
10-10 17:37:39.124  4858  4979 I Gecko   : APZSampling at 1193949.486315 -> sampleTime 1193960.912512 26:538.625061 3:0.000000
10-10 17:37:39.135  4858  4979 I Gecko   : APZSampling at 1193960.738711 -> sampleTime 1193974.696992 26:569.158691 3:0.000000
10-10 17:37:39.141  4858  4979 I Gecko   : APZSampling at 1193966.097565 -> sampleTime 1193977.079179 26:594.419250 3:0.000000
10-10 17:37:39.152  4858  4979 I Gecko   : APZSampling at 1193977.727982 -> sampleTime 1193994.064127 26:598.723389 3:0.000000
10-10 17:37:39.163  4858  4979 I Gecko   : APZSampling at 1193988.626888 -> sampleTime 1194005.056471 26:628.252197 3:0.000000
10-10 17:37:39.170  4858  4979 I Gecko   : APZSampling at 1193995.598971 -> sampleTime 1194010.726731 26:646.646973 3:0.000000
10-10 17:37:39.192  4858  4979 I Gecko   : APZSampling at 1194017.667513 -> sampleTime 1194027.682773 26:655.958008 3:0.000000
10-10 17:37:39.205  4858  4979 I Gecko   : APZSampling at 1194030.348711 -> sampleTime 1194044.116367 26:682.731201 3:0.000000
10-10 17:37:39.221  4858  4979 I Gecko   : APZSampling at 1194046.310117 -> sampleTime 1194060.795481 26:707.475220 3:0.000000
10-10 17:37:39.238  4858  4979 I Gecko   : APZSampling at 1194063.441940 -> sampleTime 1194077.443346 26:731.335205 3:0.000000

Comment 47

[Kartikaya Gupta (email:[e-mail])]

The data from comment 45 is showing that we're on the right track here. vsync and sampling is pretty consistent at 60fps but the scroll position is not smooth at all. This is basically what you observed before in your videos and described in the PDF, but now I know which part of the code to focus more on. I'll add more logging to narrow down where in the path from touch input to scroll adjustment the smoothness is disappearing.

Comment 48

[Kartikaya Gupta (email:[e-mail])]

Here's another build: https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&revision=68dc3f9a84951863c9ac8257136e10c88f371ec8

If you can do roughly what you did for comment 45 we can narrow down where the un-smoothness is coming from.

Comment 49

[Mark]

Very janky drag scroll from the top of the page, toolbar not auto-hiding:-

10-12 13:59:47.106 11813 11813 I Gecko   : APZ untransformed 906 -> 906 using APZ offsets 0.000000 0.000000 0.000000 0.000000
10-12 13:59:47.204 11813 11813 I Gecko   : APZ untransformed 905 -> 905 using APZ offsets 0.000000 0.000000 0.000000 0.000000
10-12 13:59:47.221 11813 11813 I Gecko   : APZ untransformed 900 -> 900 using APZ offsets 0.000000 0.000000 0.000000 0.000000
10-12 13:59:47.238 11813 11813 I Gecko   : APZ untransformed 896 -> 896 using APZ offsets 0.000000 0.000000 0.000000 0.000000
10-12 13:59:47.254 11813 11813 I Gecko   : APZ untransformed 888 -> 888 using APZ offsets 0.000000 0.000000 0.000000 0.000000
10-12 13:59:47.271 11813 11813 I Gecko   : APZ untransformed 881 -> 881 using APZ offsets 0.000000 0.000000 0.000000 0.000000
10-12 13:59:47.288 11813 11813 I Gecko   : APZ untransformed 873 -> 881 using APZ offsets 0.000000 0.000000 0.000000 0.000000
10-12 13:59:47.288 11813 11921 I Gecko   : APZSampling at 131166.720783 -> sampleTime 131183.299533 6:4.000000 3:0.000000
10-12 13:59:47.304 11813 11921 I Gecko   : APZSampling at 131182.818179 -> sampleTime 131199.122449 6:4.000000 3:0.000000
10-12 13:59:47.304 11813 11813 I Gecko   : APZ untransformed 865 -> 873 using APZ offsets 0.000000 4.000000 4.000000 4.000000
10-12 13:59:47.321 11813 11813 I Gecko   : APZ untransformed 857 -> 865 using APZ offsets 0.000000 8.000000 4.000000 8.000000
10-12 13:59:47.323 11813 11921 I Gecko   : APZSampling at 131201.618908 -> sampleTime 131217.285262 6:12.000000 3:0.000000
10-12 13:59:47.336 11813 11921 I Gecko   : APZSampling at 131215.089429 -> sampleTime 131231.529689 6:12.000000 3:0.000000
10-12 13:59:47.337 11813 11813 I Gecko   : APZ untransformed 851 -> 857 using APZ offsets 0.000000 12.000000 12.000000 12.000000
10-12 13:59:47.353 11813 11921 I Gecko   : APZSampling at 131232.123700 -> sampleTime 131248.390939 6:19.000000 3:0.000000
10-12 13:59:47.353 11813 11813 I Gecko   : APZ untransformed 843 -> 851 using APZ offsets 0.000000 15.000000 12.000000 15.000000
10-12 13:59:47.370 11813 11921 I Gecko   : APZSampling at 131248.800054 -> sampleTime 131265.081824 6:23.500000 3:0.000000
10-12 13:59:47.370 11813 11813 I Gecko   : APZ untransformed 834 -> 843 using APZ offsets 0.000000 19.000000 23.500000 19.000000
10-12 13:59:47.387 11813 11921 I Gecko   : APZSampling at 131265.760262 -> sampleTime 131281.988387 6:23.500000 3:0.000000
10-12 13:59:47.387 11813 11813 I Gecko   : APZ untransformed 824 -> 834 using APZ offsets 0.000000 23.500000 23.500000 23.500000
10-12 13:59:47.403 11813 11921 I Gecko   : APZSampling at 131282.202398 -> sampleTime 131298.479428 6:28.500000 3:0.000000
10-12 13:59:47.404 11813 11813 I Gecko   : APZ untransformed 814 -> 824 using APZ offsets 0.000000 28.500000 28.500000 28.500000
10-12 13:59:47.420 11813 11813 I Gecko   : APZ untransformed 804 -> 814 using APZ offsets 0.000000 33.500000 28.500000 33.500000
10-12 13:59:47.420 11813 11921 I Gecko   : APZSampling at 131298.982814 -> sampleTime 131315.266876 6:38.500000 3:0.000000
10-12 13:59:47.437 11813 11813 I Gecko   : APZ untransformed 794 -> 804 using APZ offsets 0.000000 38.500000 38.500000 38.500000
10-12 13:59:47.437 11813 11921 I Gecko   : APZSampling at 131315.674012 -> sampleTime 131332.008647 6:43.500000 3:0.000000
10-12 13:59:47.453 11813 11921 I Gecko   : APZSampling at 131332.045262 -> sampleTime 131348.500574 6:43.500000 3:0.000000
10-12 13:59:47.454 11813 11813 I Gecko   : APZ untransformed 782 -> 794 using APZ offsets 0.000000 43.500000 43.500000 43.500000
10-12 13:59:47.470 11813 11921 I Gecko   : APZSampling at 131349.045835 -> sampleTime 131365.333439 6:49.500000 3:0.000000
10-12 13:59:47.470 11813 11813 I Gecko   : APZ untransformed 771 -> 782 using APZ offsets 0.000000 49.500000 49.500000 49.500000
10-12 13:59:47.487 11813 11921 I Gecko   : APZSampling at 131365.872085 -> sampleTime 131382.156928 6:55.000000 3:0.000000
10-12 13:59:47.487 11813 11813 I Gecko   : APZ untransformed 759 -> 771 using APZ offsets 0.000000 55.000000 55.000000 55.000000
10-12 13:59:47.504 11813 11921 I Gecko   : APZSampling at 131382.526096 -> sampleTime 131398.879324 6:61.000000 3:0.000000
10-12 13:59:47.505 11813 11813 I Gecko   : APZ untransformed 745 -> 759 using APZ offsets 0.000000 61.000000 61.000000 61.000000
10-12 13:59:47.520 11813 11921 I Gecko   : APZSampling at 131399.324481 -> sampleTime 131415.616876 6:68.000000 3:0.000000
10-12 13:59:47.521 11813 11813 I Gecko   : APZ untransformed 731 -> 745 using APZ offsets 0.000000 68.000000 68.000000 68.000000
10-12 13:59:47.537 11813 11921 I Gecko   : APZSampling at 131415.930679 -> sampleTime 131432.219480 6:75.000000 3:0.000000
10-12 13:59:47.538 11813 11813 I Gecko   : APZ untransformed 719 -> 731 using APZ offsets 0.000000 75.000000 75.000000 75.000000
10-12 13:59:47.554 11813 11921 I Gecko   : APZSampling at 131432.734585 -> sampleTime 131448.972501 6:81.000000 3:0.000000
10-12 13:59:47.554 11813 11813 I Gecko   : APZ untransformed 705 -> 719 using APZ offsets 0.000000 81.000000 81.000000 81.000000
10-12 13:59:47.571 11813 11921 I Gecko   : APZSampling at 131449.355106 -> sampleTime 131465.642449 6:88.000000 3:0.000000
10-12 13:59:47.571 11813 11813 I Gecko   : APZ untransformed 691 -> 705 using APZ offsets 0.000000 88.000000 88.000000 88.000000
10-12 13:59:47.587 11813 11813 I Gecko   : APZ untransformed 677 -> 691 using APZ offsets 0.000000 95.000000 88.000000 95.000000
10-12 13:59:47.587 11813 11921 I Gecko   : APZSampling at 131466.011044 -> sampleTime 131482.296460 6:102.000000 3:0.000000
10-12 13:59:47.604 11813 11921 I Gecko   : APZSampling at 131482.789377 -> sampleTime 131499.016512 6:102.000000 3:0.000000
10-12 13:59:47.604 11813 11813 I Gecko   : APZ untransformed 662 -> 677 using APZ offsets 0.000000 102.000000 102.000000 102.000000
10-12 13:59:47.621 11813 11921 I Gecko   : APZSampling at 131499.617294 -> sampleTime 131515.767449 6:109.500000 3:0.000000
10-12 13:59:47.621 11813 11813 I Gecko   : APZ untransformed 647 -> 662 using APZ offsets 0.000000 109.500000 109.500000 109.500000
10-12 13:59:47.638 11813 11813 I Gecko   : APZ untransformed 632 -> 647 using APZ offsets 0.000000 117.000000 124.500000 117.000000
10-12 13:59:47.638 11813 11921 I Gecko   : APZSampling at 131516.290575 -> sampleTime 131532.508022 6:124.500000 3:0.000000
10-12 13:59:47.653 11813 11813 I Gecko   : APZ untransformed 617 -> 632 using APZ offsets 0.000000 124.500000 124.500000 124.500000
10-12 13:59:47.654 11813 11921 I Gecko   : APZSampling at 131533.175210 -> sampleTime 131548.840678 6:132.000000 3:0.000000
10-12 13:59:47.671 11813 11813 I Gecko   : APZ untransformed 601 -> 617 using APZ offsets 0.000000 132.000000 132.000000 132.000000
10-12 13:59:47.672 11813 11921 I Gecko   : APZSampling at 131550.956721 -> sampleTime 131565.581043 6:140.000000 3:0.000000
10-12 13:59:47.687 11813 11921 I Gecko   : APZSampling at 131565.873387 -> sampleTime 131582.156824 6:140.000000 3:0.000000
10-12 13:59:47.687 11813 11813 I Gecko   : APZ untransformed 587 -> 601 using APZ offsets 0.000000 140.000000 140.000000 140.000000
10-12 13:59:47.704 11813 11921 I Gecko   : APZSampling at 131582.714429 -> sampleTime 131598.833439 6:154.000000 3:0.000000
10-12 13:59:47.704 11813 11813 I Gecko   : APZ untransformed 573 -> 587 using APZ offsets 0.000000 147.000000 154.000000 147.000000
10-12 13:59:47.718 11813 11921 I Gecko   : APZSampling at 131596.815939 -> sampleTime 131612.932189 6:154.000000 3:0.000000
10-12 13:59:47.721 11813 11813 I Gecko   : APZ untransformed 558 -> 573 using APZ offsets 147.000000 154.000000 154.000000 154.000000
10-12 13:59:47.737 11813 11813 I Gecko   : APZ untransformed 544 -> 558 using APZ offsets 147.000000 161.500000 154.000000 161.500000
10-12 13:59:47.738 11813 11921 I Gecko   : APZSampling at 131616.922450 -> sampleTime 131632.601772 6:168.500000 3:0.000000
10-12 13:59:47.754 11813 11813 I Gecko   : APZ untransformed 529 -> 544 using APZ offsets 147.000000 168.500000 168.500000 168.500000
10-12 13:59:47.754 11813 11921 I Gecko   : APZSampling at 131633.039637 -> sampleTime 131649.162866 6:176.000000 3:0.000000
10-12 13:59:47.771 11813 11921 I Gecko   : APZSampling at 131649.724429 -> sampleTime 131666.045262 6:176.000000 3:0.000000
10-12 13:59:47.772 11813 11813 I Gecko   : APZ untransformed 514 -> 529 using APZ offsets 147.000000 176.000000 176.000000 176.000000
10-12 13:59:47.787 11813 11813 I Gecko   : APZ untransformed 500 -> 514 using APZ offsets 147.000000 183.500000 176.000000 183.500000
10-12 13:59:47.789 11813 11921 I Gecko   : APZSampling at 131667.991773 -> sampleTime 131683.497293 6:190.500000 3:0.000000
10-12 13:59:47.804 11813 11921 I Gecko   : APZSampling at 131682.798387 -> sampleTime 131699.131824 6:190.500000 3:0.000000
10-12 13:59:47.805 11813 11813 I Gecko   : APZ untransformed 484 -> 500 using APZ offsets 147.000000 190.500000 190.500000 190.500000
10-12 13:59:47.821 11813 11813 I Gecko   : APZ untransformed 469 -> 484 using APZ offsets 147.000000 198.500000 190.500000 198.500000
10-12 13:59:47.821 11813 11921 I Gecko   : APZSampling at 131699.741356 -> sampleTime 131715.969949 6:206.000000 3:0.000000
10-12 13:59:47.838 11813 11921 I Gecko   : APZSampling at 131716.435054 -> sampleTime 131732.685470 6:206.000000 3:0.000000
10-12 13:59:47.838 11813 11813 I Gecko   : APZ untransformed 455 -> 469 using APZ offsets 147.000000 206.000000 206.000000 206.000000
10-12 13:59:47.854 11813 11921 I Gecko   : APZSampling at 131732.948335 -> sampleTime 131749.128334 6:213.000000 3:0.000000
10-12 13:59:47.855 11813 11813 I Gecko   : APZ untransformed 441 -> 455 using APZ offsets 147.000000 213.000000 213.000000 213.000000
10-12 13:59:47.871 11813 11813 I Gecko   : APZ untransformed 427 -> 441 using APZ offsets 147.000000 220.000000 213.000000 220.000000
10-12 13:59:47.871 11813 11921 I Gecko   : APZSampling at 131749.787606 -> sampleTime 131766.190522 6:227.000000 3:0.000000
10-12 13:59:47.887 11813 11813 I Gecko   : APZ untransformed 413 -> 427 using APZ offsets 147.000000 227.000000 227.000000 227.000000
10-12 13:59:47.888 11813 11921 I Gecko   : APZSampling at 131766.499429 -> sampleTime 131782.783543 6:234.000000 3:0.000000
10-12 13:59:47.904 11813 11813 I Gecko   : APZ untransformed 399 -> 413 using APZ offsets 147.000000 234.000000 234.000000 234.000000
10-12 13:59:47.904 11813 11921 I Gecko   : APZSampling at 131783.338595 -> sampleTime 131799.573178 6:241.000000 3:0.000000
10-12 13:59:47.921 11813 11813 I Gecko   : APZ untransformed 385 -> 399 using APZ offsets 147.000000 241.000000 241.000000 241.000000
10-12 13:59:47.921 11813 11921 I Gecko   : APZSampling at 131800.013491 -> sampleTime 131816.310314 6:248.000000 3:0.000000
10-12 13:59:47.938 11813 11813 I Gecko   : APZ untransformed 371 -> 385 using APZ offsets 147.000000 248.000000 248.000000 248.000000
10-12 13:59:47.938 11813 11921 I Gecko   : APZSampling at 131816.679168 -> sampleTime 131833.097084 6:255.000000 3:0.000000
10-12 13:59:47.954 11813 11813 I Gecko   : APZ untransformed 359 -> 371 using APZ offsets 147.000000 255.000000 255.000000 255.000000
10-12 13:59:47.955 11813 11921 I Gecko   : APZSampling at 131833.341616 -> sampleTime 131849.656511 6:261.000000 3:0.000000
10-12 13:59:47.960 11813 11921 I Gecko   : APZSampling at 131839.148700 -> sampleTime 131849.818386 6:261.000000 3:0.000000
10-12 13:59:47.971 11813 11813 I Gecko   : APZ untransformed 347 -> 359 using APZ offsets 147.000000 261.000000 261.000000 261.000000
10-12 13:59:47.987 11813 11921 I Gecko   : APZSampling at 131866.170939 -> sampleTime 131882.615939 6:267.000000 3:0.000000
10-12 13:59:47.988 11813 11813 I Gecko   : APZ untransformed 335 -> 347 using APZ offsets 147.000000 267.000000 267.000000 267.000000
10-12 13:59:48.007 11813 11813 I Gecko   : APZ untransformed 323 -> 335 using APZ offsets 147.000000 273.000000 267.000000 273.000000
10-12 13:59:48.009 11813 11921 I Gecko   : APZSampling at 131887.489741 -> sampleTime 131902.915418 6:279.000000 3:0.000000
10-12 13:59:48.021 11813 11921 I Gecko   : APZSampling at 131900.315262 -> sampleTime 131916.626355 6:279.000000 3:0.000000
10-12 13:59:48.022 11813 11813 I Gecko   : APZ untransformed 311 -> 323 using APZ offsets 147.000000 279.000000 279.000000 279.000000
10-12 13:59:48.038 11813 11813 I Gecko   : APZ untransformed 299 -> 311 using APZ offsets 147.000000 285.000000 279.000000 285.000000
10-12 13:59:48.038 11813 11921 I Gecko   : APZSampling at 131916.718335 -> sampleTime 131932.882501 6:291.000000 3:0.000000
10-12 13:59:48.055 11813 11813 I Gecko   : APZ untransformed 287 -> 299 using APZ offsets 147.000000 291.000000 291.000000 291.000000
10-12 13:59:48.055 11813 11921 I Gecko   : APZSampling at 131933.682450 -> sampleTime 131949.983699 6:297.000000 3:0.000000
10-12 13:59:48.071 11813 11921 I Gecko   : APZSampling at 131950.194637 -> sampleTime 131966.482918 6:303.500000 3:0.000000
10-12 13:59:48.072 11813 11813 I Gecko   : APZ untransformed 274 -> 287 using APZ offsets 147.000000 297.000000 303.500000 297.000000
10-12 13:59:48.088 11813 11813 I Gecko   : APZ untransformed 262 -> 274 using APZ offsets 147.000000 303.500000 303.500000 303.500000
10-12 13:59:48.090 11813 11921 I Gecko   : APZSampling at 131966.954116 -> sampleTime 131983.201564 6:309.500000 3:0.000000
10-12 13:59:48.105 11813 11921 I Gecko   : APZSampling at 131983.848335 -> sampleTime 132000.031355 6:309.500000 3:0.000000
10-12 13:59:48.105 11813 11813 I Gecko   : APZ untransformed 250 -> 262 using APZ offsets 147.000000 309.500000 309.500000 309.500000
10-12 13:59:48.121 11813 11921 I Gecko   : APZSampling at 131999.959793 -> sampleTime 132016.263803 6:315.500000 3:0.000000
10-12 13:59:48.121 11813 11813 I Gecko   : APZ untransformed 236 -> 250 using APZ offsets 147.000000 315.500000 315.500000 315.500000
10-12 13:59:48.138 11813 11813 I Gecko   : APZ untransformed 225 -> 236 using APZ offsets 147.000000 322.500000 315.500000 322.500000
10-12 13:59:48.138 11813 11921 I Gecko   : APZSampling at 132016.922502 -> sampleTime 132033.116824 6:328.000000 3:0.000000
10-12 13:59:48.155 11813 11813 I Gecko   : APZ untransformed 214 -> 225 using APZ offsets 147.000000 328.000000 328.000000 328.000000
10-12 13:59:48.155 11813 11921 I Gecko   : APZSampling at 132033.719064 -> sampleTime 132050.007188 6:333.500000 3:0.000000
10-12 13:59:48.172 11813 11813 I Gecko   : APZ untransformed 203 -> 214 using APZ offsets 147.000000 333.500000 333.500000 333.500000
10-12 13:59:48.172 11813 11921 I Gecko   : APZSampling at 132050.517866 -> sampleTime 132066.818022 6:339.000000 3:0.000000
10-12 13:59:48.188 11813 11813 I Gecko   : APZ untransformed 192 -> 203 using APZ offsets 147.000000 339.000000 339.000000 339.000000
10-12 13:59:48.188 11813 11921 I Gecko   : APZSampling at 132067.238439 -> sampleTime 132083.351303 6:344.500000 3:0.000000
10-12 13:59:48.205 11813 11921 I Gecko   : APZSampling at 132083.967033 -> sampleTime 132100.152918 6:344.500000 3:0.000000
10-12 13:59:48.205 11813 11813 I Gecko   : APZ untransformed 182 -> 192 using APZ offsets 147.000000 344.500000 344.500000 344.500000
10-12 13:59:48.222 11813 11921 I Gecko   : APZSampling at 132100.627866 -> sampleTime 132116.853438 6:349.500000 3:0.000000
10-12 13:59:48.222 11813 11813 I Gecko   : APZ untransformed 172 -> 182 using APZ offsets 147.000000 349.500000 349.500000 349.500000
10-12 13:59:48.238 11813 11921 I Gecko   : APZSampling at 132116.871408 -> sampleTime 132133.219741 6:354.500000 3:0.000000
10-12 13:59:48.239 11813 11813 I Gecko   : APZ untransformed 164 -> 172 using APZ offsets 147.000000 354.500000 354.500000 354.500000
10-12 13:59:48.255 11813 11921 I Gecko   : APZSampling at 132134.009793 -> sampleTime 132150.157136 6:358.500000 3:0.000000
10-12 13:59:48.255 11813 11813 I Gecko   : APZ untransformed 157 -> 164 using APZ offsets 147.000000 358.500000 358.500000 358.500000
10-12 13:59:48.272 11813 11921 I Gecko   : APZSampling at 132150.674272 -> sampleTime 132166.975522 6:362.000000 3:0.000000
10-12 13:59:48.272 11813 11813 I Gecko   : APZ untransformed 151 -> 157 using APZ offsets 147.000000 362.000000 362.000000 362.000000
10-12 13:59:48.289 11813 11813 I Gecko   : APZ untransformed 146 -> 151 using APZ offsets 147.000000 365.000000 362.000000 365.000000
10-12 13:59:48.289 11813 11921 I Gecko   : APZSampling at 132168.315522 -> sampleTime 132184.325626 6:367.500000 3:0.000000
10-12 13:59:48.294 11813 11921 I Gecko   : APZSampling at 132172.687554 -> sampleTime 132184.594897 6:367.500000 3:0.000000
10-12 13:59:48.305 11813 11813 I Gecko   : APZ untransformed 142 -> 146 using APZ offsets 147.000000 367.500000 367.500000 367.500000
10-12 13:59:48.314 11813 11813 I Gecko   : APZ untransformed 142 -> 142 using APZ offsets 147.000000 369.500000 367.500000 369.500000
10-12 13:59:48.315 11813 11813 I Gecko   : APZ untransformed 142 -> 142 using APZ offsets 147.000000 369.500000 367.500000 369.500000
10-12 13:59:48.322 11813 11921 I Gecko   : APZSampling at 132200.863127 -> sampleTime 132217.068282 6:369.500000 3:0.000000
10-12 13:59:48.339 11813 11921 I Gecko   : APZSampling at 132217.352137 -> sampleTime 132233.618178 6:369.500000 3:0.000000
10-12 13:59:48.782 11813 11921 I Gecko   : APZSampling at 132660.408387 -> sampleTime 132676.891719 6:369.500000 3:0.000000
10-12 13:59:49.197 11813 11921 I Gecko   : APZSampling at 133076.058647 -> sampleTime 133092.469688 6:369.500000 3:0.000000

Comment 50

[Mark]

Very smooth drag scroll in the middle of the page, as usual I've truncated off the first 1/2 inch or so of janky movement, then it's really smooth. Again toolbar not auto-hiding:-

10-12 14:01:35.406 11813 11813 I Gecko   : APZ untransformed 882 -> 890 using APZ offsets 1601.000000 1607.243164 1607.243164 1607.243164
10-12 14:01:35.407 11813 11921 I Gecko   : APZSampling at 239286.299648 -> sampleTime 239300.915637 6:1611.243164 3:0.000000
10-12 14:01:35.422 11813 11813 I Gecko   : APZ untransformed 874 -> 882 using APZ offsets 1601.000000 1611.243164 1611.243164 1611.243164
10-12 14:01:35.423 11813 11921 I Gecko   : APZSampling at 239302.225429 -> sampleTime 239316.872564 6:1615.243164 3:0.000000
10-12 14:01:35.438 11813 11813 I Gecko   : APZ untransformed 866 -> 874 using APZ offsets 1601.000000 1615.243164 1615.243164 1615.243164
10-12 14:01:35.441 11813 11921 I Gecko   : APZSampling at 239319.259388 -> sampleTime 239333.394231 6:1619.243164 3:0.000000
10-12 14:01:35.455 11813 11813 I Gecko   : APZ untransformed 860 -> 866 using APZ offsets 1601.000000 1619.243164 1619.243164 1619.243164
10-12 14:01:35.458 11813 11921 I Gecko   : APZSampling at 239336.363190 -> sampleTime 239350.257200 6:1622.243164 3:0.000000
10-12 14:01:35.472 11813 11813 I Gecko   : APZ untransformed 854 -> 860 using APZ offsets 1601.000000 1622.243164 1622.243164 1622.243164
10-12 14:01:35.473 11813 11921 I Gecko   : APZSampling at 239352.056054 -> sampleTime 239366.981262 6:1625.243164 3:0.000000
10-12 14:01:35.488 11813 11813 I Gecko   : APZ untransformed 848 -> 854 using APZ offsets 1601.000000 1625.243164 1625.243164 1625.243164
10-12 14:01:35.490 11813 11921 I Gecko   : APZSampling at 239369.231888 -> sampleTime 239383.510585 6:1628.243164 3:0.000000
10-12 14:01:35.505 11813 11813 I Gecko   : APZ untransformed 842 -> 848 using APZ offsets 1601.000000 1628.243164 1628.243164 1628.243164
10-12 14:01:35.507 11813 11921 I Gecko   : APZSampling at 239386.052877 -> sampleTime 239400.458866 6:1631.243164 3:0.000000
10-12 14:01:35.522 11813 11813 I Gecko   : APZ untransformed 836 -> 842 using APZ offsets 1601.000000 1631.243164 1631.243164 1631.243164
10-12 14:01:35.525 11813 11921 I Gecko   : APZSampling at 239403.804232 -> sampleTime 239417.083085 6:1634.243164 3:0.000000
10-12 14:01:35.538 11813 11813 I Gecko   : APZ untransformed 828 -> 836 using APZ offsets 1601.000000 1634.243164 1634.243164 1634.243164
10-12 14:01:35.540 11813 11921 I Gecko   : APZSampling at 239418.660117 -> sampleTime 239433.618137 6:1638.243164 3:0.000000
10-12 14:01:35.555 11813 11813 I Gecko   : APZ untransformed 822 -> 828 using APZ offsets 1601.000000 1638.243164 1638.243164 1638.243164
10-12 14:01:35.558 11813 11921 I Gecko   : APZSampling at 239436.432825 -> sampleTime 239450.591575 6:1641.243164 3:0.000000
10-12 14:01:35.572 11813 11813 I Gecko   : APZ untransformed 815 -> 822 using APZ offsets 1601.000000 1641.243164 1641.243164 1641.243164
10-12 14:01:35.574 11813 11921 I Gecko   : APZSampling at 239453.079179 -> sampleTime 239467.176627 6:1644.743164 3:0.000000
10-12 14:01:35.589 11813 11813 I Gecko   : APZ untransformed 809 -> 815 using APZ offsets 1601.000000 1644.743164 1644.743164 1644.743164
10-12 14:01:35.591 11813 11921 I Gecko   : APZSampling at 239469.954388 -> sampleTime 239483.911627 6:1647.743164 3:0.000000
10-12 14:01:35.605 11813 11813 I Gecko   : APZ untransformed 803 -> 809 using APZ offsets 1601.000000 1647.743164 1647.743164 1647.743164
10-12 14:01:35.608 11813 11921 I Gecko   : APZSampling at 239486.735638 -> sampleTime 239500.969752 6:1650.743164 3:0.000000
10-12 14:01:35.622 11813 11813 I Gecko   : APZ untransformed 797 -> 803 using APZ offsets 1601.000000 1650.743164 1650.743164 1650.743164
10-12 14:01:35.625 11813 11921 I Gecko   : APZSampling at 239503.508138 -> sampleTime 239517.296783 6:1653.743164 3:0.000000
10-12 14:01:35.639 11813 11813 I Gecko   : APZ untransformed 789 -> 797 using APZ offsets 1601.000000 1653.743164 1653.743164 1653.743164
10-12 14:01:35.642 11813 11921 I Gecko   : APZSampling at 239520.815846 -> sampleTime 239533.921991 6:1657.743164 3:0.000000
10-12 14:01:35.657 11813 11813 I Gecko   : APZ untransformed 781 -> 789 using APZ offsets 1651.000000 1657.743164 1657.743164 1657.743164
10-12 14:01:35.657 11813 11921 I Gecko   : APZSampling at 239535.975638 -> sampleTime 239550.749960 6:1661.743164 3:0.000000
10-12 14:01:35.672 11813 11813 I Gecko   : APZ untransformed 773 -> 781 using APZ offsets 1651.000000 1661.743164 1661.743164 1661.743164
10-12 14:01:35.675 11813 11921 I Gecko   : APZSampling at 239553.453815 -> sampleTime 239567.328293 6:1665.743164 3:0.000000
10-12 14:01:35.689 11813 11813 I Gecko   : APZ untransformed 765 -> 773 using APZ offsets 1651.000000 1665.743164 1665.743164 1665.743164
10-12 14:01:35.691 11813 11921 I Gecko   : APZSampling at 239569.481731 -> sampleTime 239583.915116 6:1669.743164 3:0.000000
10-12 14:01:35.705 11813 11813 I Gecko   : APZ untransformed 757 -> 765 using APZ offsets 1651.000000 1669.743164 1669.743164 1669.743164
10-12 14:01:35.708 11813 11921 I Gecko   : APZSampling at 239587.246731 -> sampleTime 239601.106887 6:1673.743164 3:0.000000
10-12 14:01:35.722 11813 11813 I Gecko   : APZ untransformed 748 -> 757 using APZ offsets 1651.000000 1673.743164 1673.743164 1673.743164
10-12 14:01:35.725 11813 11921 I Gecko   : APZSampling at 239603.883763 -> sampleTime 239617.481939 6:1678.243164 3:0.000000
10-12 14:01:35.739 11813 11813 I Gecko   : APZ untransformed 738 -> 748 using APZ offsets 1651.000000 1678.243164 1678.243164 1678.243164
10-12 14:01:35.741 11813 11921 I Gecko   : APZSampling at 239620.018815 -> sampleTime 239634.169491 6:1683.243164 3:0.000000
10-12 14:01:35.756 11813 11813 I Gecko   : APZ untransformed 728 -> 738 using APZ offsets 1651.000000 1683.243164 1683.243164 1683.243164
10-12 14:01:35.758 11813 11921 I Gecko   : APZSampling at 239636.642825 -> sampleTime 239651.152460 6:1688.243164 3:0.000000
10-12 14:01:35.773 11813 11813 I Gecko   : APZ untransformed 720 -> 720 using APZ offsets 1651.000000 1692.243164 1688.243164 1692.243164
10-12 14:01:35.775 11813 11921 I Gecko   : APZSampling at 239653.455377 -> sampleTime 239667.573450 6:1692.243164 3:0.000000
10-12 14:01:35.789 11813 11813 I Gecko   : APZ untransformed 712 -> 720 using APZ offsets 1651.000000 1692.243164 1692.243164 1692.243164
10-12 14:01:35.791 11813 11921 I Gecko   : APZSampling at 239669.696888 -> sampleTime 239684.090116 6:1696.243164 3:0.000000
10-12 14:01:35.806 11813 11813 I Gecko   : APZ untransformed 703 -> 712 using APZ offsets 1651.000000 1696.243164 1696.243164 1696.243164
10-12 14:01:35.812 11813 11921 I Gecko   : APZSampling at 239690.532617 -> sampleTime 239701.309856 6:1700.743164 3:0.000000
10-12 14:01:35.822 11813 11813 I Gecko   : APZ untransformed 693 -> 703 using APZ offsets 1651.000000 1700.743164 1700.743164 1700.743164
10-12 14:01:35.826 11813 11921 I Gecko   : APZSampling at 239705.313450 -> sampleTime 239717.626991 6:1705.743164 3:0.000000
10-12 14:01:35.839 11813 11813 I Gecko   : APZ untransformed 684 -> 693 using APZ offsets 1651.000000 1705.743164 1705.743164 1705.743164
10-12 14:01:35.842 11813 11921 I Gecko   : APZSampling at 239720.414023 -> sampleTime 239734.376679 6:1710.243164 3:0.000000
10-12 14:01:35.856 11813 11813 I Gecko   : APZ untransformed 675 -> 684 using APZ offsets 1651.000000 1710.243164 1710.243164 1710.243164
10-12 14:01:35.858 11813 11921 I Gecko   : APZSampling at 239736.768763 -> sampleTime 239750.727356 6:1714.743164 3:0.000000
10-12 14:01:35.872 11813 11813 I Gecko   : APZ untransformed 667 -> 675 using APZ offsets 1651.000000 1714.743164 1714.743164 1714.743164
10-12 14:01:35.876 11813 11921 I Gecko   : APZSampling at 239754.467669 -> sampleTime 239767.769231 6:1718.743164 3:0.000000
10-12 14:01:35.889 11813 11813 I Gecko   : APZ untransformed 659 -> 667 using APZ offsets 1651.000000 1718.743164 1718.743164 1718.743164
10-12 14:01:35.891 11813 11921 I Gecko   : APZSampling at 239769.700898 -> sampleTime 239784.454960 6:1722.743164 3:0.000000
10-12 14:01:35.906 11813 11813 I Gecko   : APZ untransformed 650 -> 659 using APZ offsets 1651.000000 1722.743164 1722.743164 1722.743164
10-12 14:01:35.908 11813 11921 I Gecko   : APZSampling at 239787.206888 -> sampleTime 239801.125064 6:1727.243164 3:0.000000
10-12 14:01:35.923 11813 11813 I Gecko   : APZ untransformed 641 -> 650 using APZ offsets 1651.000000 1727.243164 1727.243164 1727.243164
10-12 14:01:35.926 11813 11921 I Gecko   : APZSampling at 239804.582044 -> sampleTime 239817.859335 6:1731.743164 3:0.000000
10-12 14:01:35.939 11813 11813 I Gecko   : APZ untransformed 633 -> 641 using APZ offsets 1651.000000 1731.743164 1731.743164 1731.743164
10-12 14:01:35.943 11813 11921 I Gecko   : APZSampling at 239821.456106 -> sampleTime 239834.305377 6:1735.743164 3:0.000000
10-12 14:01:35.956 11813 11813 I Gecko   : APZ untransformed 625 -> 641 using APZ offsets 1651.000000 1731.743164 1735.743164 1731.743164
10-12 14:01:35.962 11813 11921 I Gecko   : APZSampling at 239840.556575 -> sampleTime 239850.964179 6:1739.743164 3:0.000000
10-12 14:01:35.972 11813 11813 I Gecko   : APZ untransformed 617 -> 625 using APZ offsets 1732.000000 1739.743164 1739.743164 1739.743164
10-12 14:01:35.974 11813 11921 I Gecko   : APZSampling at 239853.275429 -> sampleTime 239867.921731 6:1743.743164 3:0.000000
10-12 14:01:35.989 11813 11813 I Gecko   : APZ untransformed 608 -> 617 using APZ offsets 1732.000000 1743.743164 1743.743164 1743.743164
10-12 14:01:35.991 11813 11921 I Gecko   : APZSampling at 239869.548711 -> sampleTime 239884.628658 6:1748.243164 3:0.000000
10-12 14:01:36.006 11813 11813 I Gecko   : APZ untransformed 598 -> 608 using APZ offsets 1732.000000 1748.243164 1748.243164 1748.243164
10-12 14:01:36.008 11813 11921 I Gecko   : APZSampling at 239886.782252 -> sampleTime 239901.092043 6:1753.243164 3:0.000000
10-12 14:01:36.022 11813 11813 I Gecko   : APZ untransformed 590 -> 598 using APZ offsets 1732.000000 1753.243164 1753.243164 1753.243164
10-12 14:01:36.025 11813 11921 I Gecko   : APZSampling at 239904.085273 -> sampleTime 239917.490533 6:1757.243164 3:0.000000
10-12 14:01:36.039 11813 11813 I Gecko   : APZ untransformed 582 -> 590 using APZ offsets 1732.000000 1757.243164 1757.243164 1757.243164
10-12 14:01:36.042 11813 11921 I Gecko   : APZSampling at 239921.119023 -> sampleTime 239934.441106 6:1761.243164 3:0.000000
10-12 14:01:36.056 11813 11813 I Gecko   : APZ untransformed 574 -> 582 using APZ offsets 1732.000000 1761.243164 1761.243164 1761.243164
10-12 14:01:36.059 11813 11921 I Gecko   : APZSampling at 239938.199804 -> sampleTime 239951.357251 6:1765.243164 3:0.000000
10-12 14:01:36.073 11813 11813 I Gecko   : APZ untransformed 566 -> 574 using APZ offsets 1732.000000 1765.243164 1765.243164 1765.243164
10-12 14:01:36.075 11813 11921 I Gecko   : APZSampling at 239954.229752 -> sampleTime 239968.133449 6:1769.243164 3:0.000000
10-12 14:01:36.089 11813 11813 I Gecko   : APZ untransformed 557 -> 566 using APZ offsets 1732.000000 1769.243164 1769.243164 1769.243164
10-12 14:01:36.093 11813 11921 I Gecko   : APZSampling at 239971.903658 -> sampleTime 239984.580012 6:1773.743164 3:0.000000
10-12 14:01:36.106 11813 11813 I Gecko   : APZ untransformed 547 -> 557 using APZ offsets 1732.000000 1773.743164 1773.743164 1773.743164
10-12 14:01:36.110 11813 11921 I Gecko   : APZSampling at 239989.060273 -> sampleTime 240001.288085 6:1778.743164 3:0.000000
10-12 14:01:36.123 11813 11813 I Gecko   : APZ untransformed 538 -> 547 using APZ offsets 1732.000000 1778.743164 1778.743164 1778.743164
10-12 14:01:36.126 11813 11921 I Gecko   : APZSampling at 240004.936367 -> sampleTime 240018.134074 6:1783.243164 3:0.000000
10-12 14:01:36.140 11813 11813 I Gecko   : APZ untransformed 528 -> 538 using APZ offsets 1732.000000 1783.243164 1783.243164 1783.243164
10-12 14:01:36.143 11813 11921 I Gecko   : APZSampling at 240021.860221 -> sampleTime 240034.920949 6:1788.243164 3:0.000000
10-12 14:01:36.156 11813 11813 I Gecko   : APZ untransformed 519 -> 528 using APZ offsets 1732.000000 1788.243164 1788.243164 1788.243164
10-12 14:01:36.158 11813 11921 I Gecko   : APZSampling at 240036.830221 -> sampleTime 240051.030689 6:1792.743164 3:0.000000
10-12 14:01:36.173 11813 11813 I Gecko   : APZ untransformed 509 -> 519 using APZ offsets 1732.000000 1792.743164 1792.743164 1792.743164
10-12 14:01:36.175 11813 11921 I Gecko   : APZSampling at 240054.247408 -> sampleTime 240068.317408 6:1797.743164 3:0.000000
10-12 14:01:36.190 11813 11813 I Gecko   : APZ untransformed 499 -> 509 using APZ offsets 1732.000000 1797.743164 1797.743164 1797.743164
10-12 14:01:36.193 11813 11921 I Gecko   : APZSampling at 240071.292617 -> sampleTime 240084.999543 6:1802.743164 3:0.000000
10-12 14:01:36.206 11813 11813 I Gecko   : APZ untransformed 489 -> 499 using APZ offsets 1732.000000 1802.743164 1802.743164 1802.743164
10-12 14:01:36.210 11813 11921 I Gecko   : APZSampling at 240088.350638 -> sampleTime 240101.654231 6:1807.743164 3:0.000000
10-12 14:01:36.223 11813 11813 I Gecko   : APZ untransformed 480 -> 489 using APZ offsets 1732.000000 1807.743164 1807.743164 1807.743164
10-12 14:01:36.226 11813 11921 I Gecko   : APZSampling at 240104.530117 -> sampleTime 240118.410064 6:1812.243164 3:0.000000
10-12 14:01:36.240 11813 11813 I Gecko   : APZ untransformed 470 -> 480 using APZ offsets 1732.000000 1812.243164 1812.243164 1812.243164
10-12 14:01:36.242 11813 11921 I Gecko   : APZSampling at 240120.920690 -> sampleTime 240135.102095 6:1817.243164 3:0.000000
10-12 14:01:36.256 11813 11813 I Gecko   : APZ untransformed 460 -> 470 using APZ offsets 1732.000000 1817.243164 1817.243164 1817.243164
10-12 14:01:36.259 11813 11921 I Gecko   : APZSampling at 240137.447929 -> sampleTime 240151.611783 6:1822.243164 3:0.000000
10-12 14:01:36.273 11813 11813 I Gecko   : APZ untransformed 450 -> 460 using APZ offsets 1732.000000 1822.243164 1822.243164 1822.243164
10-12 14:01:36.276 11813 11921 I Gecko   : APZSampling at 240154.595585 -> sampleTime 240168.485533 6:1827.243164 3:0.000000
10-12 14:01:36.289 11813 11813 I Gecko   : APZ untransformed 441 -> 450 using APZ offsets 1732.000000 1827.243164 1827.243164 1827.243164
10-12 14:01:36.292 11813 11921 I Gecko   : APZSampling at 240170.589283 -> sampleTime 240184.859751 6:1831.743164 3:0.000000
10-12 14:01:36.307 11813 11813 I Gecko   : APZ untransformed 431 -> 441 using APZ offsets 1732.000000 1831.743164 1831.743164 1831.743164
10-12 14:01:36.309 11813 11921 I Gecko   : APZSampling at 240187.861575 -> sampleTime 240201.845116 6:1836.743164 3:0.000000
10-12 14:01:36.323 11813 11813 I Gecko   : APZ untransformed 421 -> 431 using APZ offsets 1732.000000 1836.743164 1836.743164 1836.743164
10-12 14:01:36.326 11813 11921 I Gecko   : APZSampling at 240204.959023 -> sampleTime 240218.603814 6:1841.743164 3:0.000000
10-12 14:01:36.340 11813 11813 I Gecko   : APZ untransformed 411 -> 421 using APZ offsets 1732.000000 1841.743164 1841.743164 1841.743164
10-12 14:01:36.341 11813 11921 I Gecko   : APZSampling at 240220.188919 -> sampleTime 240235.346731 6:1846.743164 3:0.000000
10-12 14:01:36.356 11813 11813 I Gecko   : APZ untransformed 401 -> 411 using APZ offsets 1732.000000 1846.743164 1846.743164 1846.743164
10-12 14:01:36.360 11813 11921 I Gecko   : APZSampling at 240238.386887 -> sampleTime 240251.433241 6:1851.743164 3:0.000000
10-12 14:01:36.373 11813 11813 I Gecko   : APZ untransformed 391 -> 401 using APZ offsets 1732.000000 1851.743164 1851.743164 1851.743164
10-12 14:01:36.377 11813 11921 I Gecko   : APZSampling at 240255.901367 -> sampleTime 240268.563814 6:1856.743164 3:0.000000
10-12 14:01:36.390 11813 11813 I Gecko   : APZ untransformed 381 -> 391 using APZ offsets 1732.000000 1856.743164 1856.743164 1856.743164
10-12 14:01:36.393 11813 11921 I Gecko   : APZSampling at 240271.660742 -> sampleTime 240285.499543 6:1861.743164 3:0.000000
10-12 14:01:36.407 11813 11813 I Gecko   : APZ untransformed 370 -> 381 using APZ offsets 1732.000000 1861.743164 1861.743164 1861.743164
10-12 14:01:36.411 11813 11921 I Gecko   : APZSampling at 240289.702773 -> sampleTime 240301.793918 6:1867.243164 3:0.000000
10-12 14:01:36.423 11813 11813 I Gecko   : APZ untransformed 360 -> 370 using APZ offsets 1732.000000 1867.243164 1867.243164 1867.243164
10-12 14:01:36.429 11813 11921 I Gecko   : APZSampling at 240308.097721 -> sampleTime 240318.680741 6:1872.243164 3:0.000000
10-12 14:01:36.440 11813 11813 I Gecko   : APZ untransformed 350 -> 360 using APZ offsets 1862.000000 1872.243164 1872.243164 1872.243164
10-12 14:01:36.443 11813 11921 I Gecko   : APZSampling at 240321.960794 -> sampleTime 240335.135376 6:1877.243164 3:0.000000
10-12 14:01:36.457 11813 11813 I Gecko   : APZ untransformed 340 -> 350 using APZ offsets 1862.000000 1877.243164 1877.243164 1877.243164
10-12 14:01:36.460 11813 11921 I Gecko   : APZSampling at 240339.167044 -> sampleTime 240351.900845 6:1882.243164 3:0.000000
10-12 14:01:36.474 11813 11813 I Gecko   : APZ untransformed 329 -> 340 using APZ offsets 1862.000000 1882.243164 1882.243164 1882.243164
10-12 14:01:36.477 11813 11921 I Gecko   : APZSampling at 240355.093450 -> sampleTime 240368.861991 6:1887.743164 3:0.000000
10-12 14:01:36.490 11813 11813 I Gecko   : APZ untransformed 317 -> 329 using APZ offsets 1862.000000 1887.743164 1887.743164 1887.743164
10-12 14:01:36.492 11813 11921 I Gecko   : APZSampling at 240370.457825 -> sampleTime 240385.600845 6:1893.743164 3:0.000000
10-12 14:01:36.507 11813 11813 I Gecko   : APZ untransformed 307 -> 317 using APZ offsets 1862.000000 1893.743164 1893.743164 1893.743164
10-12 14:01:36.509 11813 11921 I Gecko   : APZSampling at 240387.836627 -> sampleTime 240402.029022 6:1898.743164 3:0.000000
10-12 14:01:36.523 11813 11813 I Gecko   : APZ untransformed 297 -> 307 using APZ offsets 1862.000000 1898.743164 1898.743164 1898.743164
10-12 14:01:36.526 11813 11921 I Gecko   : APZSampling at 240405.319752 -> sampleTime 240418.734335 6:1903.743164 3:0.000000
10-12 14:01:36.540 11813 11813 I Gecko   : APZ untransformed 287 -> 297 using APZ offsets 1862.000000 1903.743164 1903.743164 1903.743164
10-12 14:01:36.542 11813 11921 I Gecko   : APZSampling at 240420.733450 -> sampleTime 240435.318501 6:1908.743164 3:0.000000
10-12 14:01:36.557 11813 11813 I Gecko   : APZ untransformed 277 -> 287 using APZ offsets 1862.000000 1908.743164 1908.743164 1908.743164
10-12 14:01:36.559 11813 11921 I Gecko   : APZSampling at 240438.080898 -> sampleTime 240452.333814 6:1913.743164 3:0.000000
10-12 14:01:36.574 11813 11813 I Gecko   : APZ untransformed 267 -> 277 using APZ offsets 1862.000000 1913.743164 1913.743164 1913.743164
10-12 14:01:36.576 11813 11921 I Gecko   : APZSampling at 240454.581887 -> sampleTime 240469.046939 6:1918.743164 3:0.000000
10-12 14:01:36.590 11813 11813 I Gecko   : APZ untransformed 257 -> 267 using APZ offsets 1862.000000 1918.743164 1918.743164 1918.743164
10-12 14:01:36.593 11813 11921 I Gecko   : APZSampling at 240471.484648 -> sampleTime 240485.370845 6:1923.743164 3:0.000000
10-12 14:01:36.607 11813 11813 I Gecko   : APZ untransformed 247 -> 257 using APZ offsets 1862.000000 1923.743164 1923.743164 1923.743164
10-12 14:01:36.610 11813 11921 I Gecko   : APZSampling at 240488.751627 -> sampleTime 240502.129960 6:1928.743164 3:0.000000
10-12 14:01:36.624 11813 11813 I Gecko   : APZ untransformed 236 -> 247 using APZ offsets 1862.000000 1928.743164 1928.743164 1928.743164
10-12 14:01:36.626 11813 11921 I Gecko   : APZSampling at 240504.416314 -> sampleTime 240518.885376 6:1934.243164 3:0.000000
10-12 14:01:36.641 11813 11813 I Gecko   : APZ untransformed 226 -> 236 using APZ offsets 1862.000000 1934.243164 1934.243164 1934.243164
10-12 14:01:36.643 11813 11921 I Gecko   : APZSampling at 240521.361992 -> sampleTime 240535.851366 6:1939.243164 3:0.000000
10-12 14:01:36.657 11813 11813 I Gecko   : APZ untransformed 216 -> 226 using APZ offsets 1862.000000 1939.243164 1939.243164 1939.243164
10-12 14:01:36.660 11813 11921 I Gecko   : APZSampling at 240538.476367 -> sampleTime 240552.204855 6:1944.243164 3:0.000000
10-12 14:01:36.674 11813 11813 I Gecko   : APZ untransformed 206 -> 216 using APZ offsets 1862.000000 1944.243164 1944.243164 1944.243164
10-12 14:01:36.677 11813 11921 I Gecko   : APZSampling at 240556.198866 -> sampleTime 240569.258657 6:1949.243164 3:0.000000
10-12 14:01:36.691 11813 11813 I Gecko   : APZ untransformed 196 -> 206 using APZ offsets 1862.000000 1949.243164 1949.243164 1949.243164
10-12 14:01:36.694 11813 11921 I Gecko   : APZSampling at 240572.901366 -> sampleTime 240585.957824 6:1954.243164 3:0.000000
10-12 14:01:36.707 11813 11813 I Gecko   : APZ untransformed 185 -> 196 using APZ offsets 1862.000000 1954.243164 1954.243164 1954.243164
10-12 14:01:36.711 11813 11921 I Gecko   : APZSampling at 240589.578919 -> sampleTime 240602.652095 6:1959.743164 3:0.000000
10-12 14:01:36.724 11813 11813 I Gecko   : APZ untransformed 175 -> 185 using APZ offsets 1862.000000 1959.743164 1959.743164 1959.743164
10-12 14:01:36.727 11813 11921 I Gecko   : APZSampling at 240605.729544 -> sampleTime 240619.367668 6:1964.743164 3:0.000000
10-12 14:01:36.741 11813 11813 I Gecko   : APZ untransformed 166 -> 175 using APZ offsets 1862.000000 1964.743164 1964.743164 1964.743164
10-12 14:01:36.744 11813 11921 I Gecko   : APZSampling at 240622.552981 -> sampleTime 240635.633501 6:1969.243164 3:0.000000
10-12 14:01:36.757 11813 11813 I Gecko   : APZ untransformed 158 -> 166 using APZ offsets 1862.000000 1969.243164 1969.243164 1969.243164
10-12 14:01:36.759 11813 11921 I Gecko   : APZSampling at 240637.949283 -> sampleTime 240652.200532 6:1973.243164 3:0.000000
10-12 14:01:36.774 11813 11813 I Gecko   : APZ untransformed 150 -> 158 using APZ offsets 1862.000000 1973.243164 1973.243164 1973.243164
10-12 14:01:36.777 11813 11921 I Gecko   : APZSampling at 240655.418971 -> sampleTime 240669.419439 6:1977.243164 3:0.000000
10-12 14:01:36.791 11813 11813 I Gecko   : APZ untransformed 142 -> 150 using APZ offsets 1862.000000 1977.243164 1977.243164 1977.243164
10-12 14:01:36.794 11813 11921 I Gecko   : APZSampling at 240672.259648 -> sampleTime 240686.100949 6:1981.243164 3:0.000000
10-12 14:01:36.807 11813 11813 I Gecko   : APZ untransformed 134 -> 142 using APZ offsets 1862.000000 1981.243164 1981.243164 1981.243164
10-12 14:01:36.811 11813 11921 I Gecko   : APZSampling at 240689.144387 -> sampleTime 240702.593866 6:1985.243164 3:0.000000
10-12 14:01:36.824 11813 11813 I Gecko   : APZ untransformed 127 -> 134 using APZ offsets 1862.000000 1985.243164 1985.243164 1985.243164
10-12 14:01:36.827 11813 11921 I Gecko   : APZSampling at 240705.507512 -> sampleTime 240719.390168 6:1988.743164 3:0.000000
10-12 14:01:36.841 11813 11813 I Gecko   : APZ untransformed 122 -> 127 using APZ offsets 1862.000000 1988.743164 1988.743164 1988.743164
10-12 14:01:36.848 11813 11921 I Gecko   : APZSampling at 240726.422356 -> sampleTime 240736.331626 6:1991.243164 3:0.000000
10-12 14:01:36.857 11813 11813 I Gecko   : APZ untransformed 118 -> 122 using APZ offsets 1985.500000 1991.243164 1991.243164 1991.243164
10-12 14:01:36.860 11813 11921 I Gecko   : APZSampling at 240739.014752 -> sampleTime 240752.682303 6:1993.243164 3:0.000000
10-12 14:01:36.874 11813 11813 I Gecko   : APZ untransformed 116 -> 118 using APZ offsets 1985.500000 1993.243164 1993.243164 1993.243164
10-12 14:01:36.876 11813 11921 I Gecko   : APZSampling at 240755.288398 -> sampleTime 240769.757355 6:1994.243164 3:0.000000
10-12 14:01:36.891 11813 11813 I Gecko   : APZ untransformed 114 -> 116 using APZ offsets 1985.500000 1994.243164 1994.243164 1994.243164
10-12 14:01:36.893 11813 11921 I Gecko   : APZSampling at 240772.110741 -> sampleTime 240786.426782 6:1995.243164 3:0.000000
10-12 14:01:36.900 11813 11813 I Gecko   : APZ untransformed 114 -> 114 using APZ offsets 1985.500000 1995.243164 1995.243164 1995.243164

Comment 51

[Mark]

Fling with one or two janks as JS images pop in during the fling (mozilla.org) (much harder to catch the janks on this, they don't always occur). I think the jank happens when I see the "APZ untransformed" log messages appear during the fling, but I am not at all sure, I need chameleon eyes to watch the fling and my laptop screen.

10-12 14:08:23.462 11813 11813 I Gecko   : APZ untransformed 862 -> 862 using APZ offsets 0.000000 0.000000 0.000000 0.000000
10-12 14:08:23.490 11813 11813 I Gecko   : APZ untransformed 855 -> 855 using APZ offsets 0.000000 0.000000 0.000000 0.000000
10-12 14:08:23.506 11813 11813 I Gecko   : APZ untransformed 831 -> 831 using APZ offsets 0.000000 0.000000 0.000000 0.000000
10-12 14:08:23.523 11813 11813 I Gecko   : APZ untransformed 792 -> 831 using APZ offsets 0.000000 0.000000 0.000000 0.000000
10-12 14:08:23.523 11813 11921 I Gecko   : APZSampling at 647402.105690 -> sampleTime 647418.679231 46:19.500000 3:0.000000
10-12 14:08:23.540 11813 11921 I Gecko   : APZSampling at 647418.581107 -> sampleTime 647434.857200 46:19.500000 3:0.000000
10-12 14:08:23.541 11813 11813 I Gecko   : APZ untransformed 745 -> 792 using APZ offsets 0.000000 19.500000 19.500000 19.500000
10-12 14:08:23.557 11813 11813 I Gecko   : APZ untransformed 696 -> 745 using APZ offsets 0.000000 43.000000 19.500000 43.000000
10-12 14:08:23.560 11813 11921 I Gecko   : APZSampling at 647438.308034 -> sampleTime 647454.476263 46:67.500000 3:0.000000
10-12 14:08:23.573 11813 11921 I Gecko   : APZSampling at 647452.219076 -> sampleTime 647468.447825 46:67.500000 3:0.000000
10-12 14:08:23.574 11813 11813 I Gecko   : APZ untransformed 635 -> 696 using APZ offsets 0.000000 67.500000 67.500000 67.500000
10-12 14:08:23.590 11813 11921 I Gecko   : APZSampling at 647468.688034 -> sampleTime 647485.056471 46:98.000000 3:0.000000
10-12 14:08:23.590 11813 11813 I Gecko   : APZ untransformed 570 -> 635 using APZ offsets 0.000000 98.000000 98.000000 98.000000
10-12 14:08:23.607 11813 11921 I Gecko   : APZSampling at 647485.449336 -> sampleTime 647501.526159 46:130.500000 3:0.000000
10-12 14:08:23.607 11813 11813 I Gecko   : APZ untransformed 501 -> 570 using APZ offsets 0.000000 130.500000 130.500000 130.500000
10-12 14:08:23.623 11813 11813 I Gecko   : APZ untransformed 429 -> 501 using APZ offsets 0.000000 165.000000 130.500000 165.000000
10-12 14:08:23.624 11813 11921 I Gecko   : APZSampling at 647502.581368 -> sampleTime 647518.496679 46:201.000000 3:0.000000
10-12 14:08:23.625 11813 11813 I Gecko   : APZ untransformed 429 -> 501 using APZ offsets 0.000000 165.000000 201.000000 165.000000
10-12 14:08:23.629 11813 11921 I Gecko   : APZSampling at 647508.095430 -> sampleTime 647524.625429 46:201.000000 3:0.000000
10-12 14:08:23.640 11813 11921 I Gecko   : APZSampling at 647518.815013 -> sampleTime 647535.214700 46:248.554504 3:0.000000
10-12 14:08:23.657 11813 11921 I Gecko   : APZSampling at 647535.437982 -> sampleTime 647551.851419 46:272.750031 3:0.000000
10-12 14:08:23.673 11813 11921 I Gecko   : APZSampling at 647552.249961 -> sampleTime 647568.313711 46:310.300110 3:0.000000
10-12 14:08:23.690 11813 11921 I Gecko   : APZSampling at 647568.609597 -> sampleTime 647585.024648 46:346.750366 3:0.000000
10-12 14:08:23.706 11813 11921 I Gecko   : APZSampling at 647585.178347 -> sampleTime 647601.574283 46:382.884521 3:0.000000
10-12 14:08:23.731 11813 11921 I Gecko   : APZSampling at 647609.638555 -> sampleTime 647618.349648 46:417.508728 3:0.000000
10-12 14:08:23.740 11813 11921 I Gecko   : APZSampling at 647618.561680 -> sampleTime 647634.948346 46:451.446777 3:0.000000
10-12 14:08:23.756 11813 11921 I Gecko   : APZSampling at 647635.015951 -> sampleTime 647650.105377 46:483.689667 3:0.000000
10-12 14:08:23.761 11813 11921 I Gecko   : APZSampling at 647639.715847 -> sampleTime 647651.767617 46:511.970306 3:0.000000
10-12 14:08:23.780 11813 11921 I Gecko   : APZSampling at 647658.963242 -> sampleTime 647668.540950 46:514.987061 3:0.000000
10-12 14:08:23.801 11813 11921 I Gecko   : APZSampling at 647679.331524 -> sampleTime 647685.241315 46:544.878052 3:0.000000
10-12 14:08:23.810 11813 11921 I Gecko   : APZSampling at 647688.817617 -> sampleTime 647701.884492 46:573.126099 3:0.000000
10-12 14:08:23.827 11813 11921 I Gecko   : APZSampling at 647706.020430 -> sampleTime 647718.703919 46:599.983032 3:0.000000
10-12 14:08:23.846 11813 11921 I Gecko   : APZSampling at 647724.890795 -> sampleTime 647735.277461 46:625.788940 3:0.000000
10-12 14:08:23.861 11813 11921 I Gecko   : APZSampling at 647739.841315 -> sampleTime 647752.821367 46:649.876099 3:0.000000
10-12 14:08:23.877 11813 11921 I Gecko   : APZSampling at 647756.129076 -> sampleTime 647768.949648 46:674.082275 3:0.000000
10-12 14:08:23.894 11813 11921 I Gecko   : APZSampling at 647772.861784 -> sampleTime 647785.506627 46:695.173218 3:0.000000
10-12 14:08:23.911 11813 11921 I Gecko   : APZSampling at 647789.464649 -> sampleTime 647802.264283 46:715.678223 3:0.000000
10-12 14:08:23.932 11813 11921 I Gecko   : APZSampling at 647811.067513 -> sampleTime 647818.799283 46:735.412476 3:0.000000
10-12 14:08:23.944 11813 11921 I Gecko   : APZSampling at 647822.905586 -> sampleTime 647835.604700 46:753.781311 3:0.000000
10-12 14:08:23.960 11813 11921 I Gecko   : APZSampling at 647838.630013 -> sampleTime 647852.317148 46:771.501831 3:0.000000
10-12 14:08:23.983 11813 11921 I Gecko   : APZSampling at 647862.092617 -> sampleTime 647868.808658 46:788.211731 3:0.000000
10-12 14:08:24.001 11813 11921 I Gecko   : APZSampling at 647879.348034 -> sampleTime 647885.627825 46:803.775146 3:0.000000
10-12 14:08:24.009 11813 11921 I Gecko   : APZSampling at 647888.246107 -> sampleTime 647902.330950 46:818.847168 3:0.000000
10-12 14:08:24.027 11813 11921 I Gecko   : APZSampling at 647906.197513 -> sampleTime 647918.957200 46:833.007080 3:0.000000
10-12 14:08:24.045 11813 11921 I Gecko   : APZSampling at 647924.243711 -> sampleTime 647936.342825 46:846.331726 3:0.000000
10-12 14:08:24.066 11813 11921 I Gecko   : APZSampling at 647945.057201 -> sampleTime 647952.500846 46:859.537903 3:0.000000
10-12 14:08:24.080 11813 11921 I Gecko   : APZSampling at 647959.030013 -> sampleTime 647969.041419 46:871.120972 3:0.000000
10-12 14:08:24.094 11813 11921 I Gecko   : APZSampling at 647972.246055 -> sampleTime 647985.978190 46:882.367920 3:0.000000
10-12 14:08:24.110 11813 11921 I Gecko   : APZSampling at 647988.809180 -> sampleTime 648003.012617 46:893.272034 3:0.000000
10-12 14:08:24.128 11813 11921 I Gecko   : APZSampling at 648006.906680 -> sampleTime 648019.251210 46:903.593628 3:0.000000
10-12 14:08:24.146 11813 11921 I Gecko   : APZSampling at 648024.906628 -> sampleTime 648036.141054 46:912.921082 3:0.000000
10-12 14:08:24.161 11813 11921 I Gecko   : APZSampling at 648039.790742 -> sampleTime 648052.834127 46:922.078979 3:0.000000
10-12 14:08:24.178 11813 11921 I Gecko   : APZSampling at 648057.066159 -> sampleTime 648069.380898 46:930.607483 3:0.000000
10-12 14:08:24.195 11813 11921 I Gecko   : APZSampling at 648073.517930 -> sampleTime 648086.062721 46:938.611267 3:0.000000
10-12 14:08:24.212 11813 11921 I Gecko   : APZSampling at 648090.425169 -> sampleTime 648102.925065 46:946.189697 3:0.000000
10-12 14:08:24.229 11813 11921 I Gecko   : APZSampling at 648108.022669 -> sampleTime 648119.462460 46:953.413025 3:0.000000
10-12 14:08:24.248 11813 11921 I Gecko   : APZSampling at 648126.424909 -> sampleTime 648136.318502 46:960.095276 3:0.000000
10-12 14:08:24.263 11813 11921 I Gecko   : APZSampling at 648142.166784 -> sampleTime 648152.900533 46:966.467529 3:0.000000
10-12 14:08:24.280 11813 11921 I Gecko   : APZSampling at 648158.592096 -> sampleTime 648169.598346 46:972.365417 3:0.000000
10-12 14:08:24.298 11813 11921 I Gecko   : APZSampling at 648176.953711 -> sampleTime 648186.482773 46:977.932190 3:0.000000
10-12 14:08:24.309 11813 11921 I Gecko   : APZSampling at 648188.254023 -> sampleTime 648202.988398 46:983.186462 3:0.000000
10-12 14:08:24.327 11813 11921 I Gecko   : APZSampling at 648205.578607 -> sampleTime 648219.994492 46:988.000305 3:0.000000
10-12 14:08:24.343 11813 11921 I Gecko   : APZSampling at 648221.959596 -> sampleTime 648236.342877 46:992.602539 3:0.000000
10-12 14:08:24.361 11813 11921 I Gecko   : APZSampling at 648239.656159 -> sampleTime 648253.111939 46:996.723206 3:0.000000
10-12 14:08:24.379 11813 11921 I Gecko   : APZSampling at 648257.334128 -> sampleTime 648269.950064 46:1000.653137 3:0.000000
10-12 14:08:24.395 11813 11921 I Gecko   : APZSampling at 648273.463034 -> sampleTime 648286.600169 46:1004.281372 3:0.000000
10-12 14:08:24.412 11813 11921 I Gecko   : APZSampling at 648290.842044 -> sampleTime 648303.815325 46:1007.596313 3:0.000000
10-12 14:08:24.429 11813 11921 I Gecko   : APZSampling at 648307.693346 -> sampleTime 648319.894023 46:1010.738220 3:0.000000
10-12 14:08:24.445 11813 11921 I Gecko   : APZSampling at 648323.656888 -> sampleTime 648336.767304 46:1013.405762 3:0.000000
10-12 14:08:24.463 11813 11921 I Gecko   : APZSampling at 648342.043763 -> sampleTime 648353.559804 46:1015.965759 3:0.000000
10-12 14:08:24.479 11813 11921 I Gecko   : APZSampling at 648358.057773 -> sampleTime 648370.042252 46:1018.252441 3:0.000000
10-12 14:08:24.495 11813 11921 I Gecko   : APZSampling at 648374.181419 -> sampleTime 648386.960377 46:1020.262024 3:0.000000
10-12 14:08:24.512 11813 11921 I Gecko   : APZSampling at 648390.495742 -> sampleTime 648403.312200 46:1022.102417 3:0.000000
10-12 14:08:24.531 11813 11921 I Gecko   : APZSampling at 648409.840430 -> sampleTime 648420.232669 46:1023.643372 3:0.000000
10-12 14:08:24.545 11813 11921 I Gecko   : APZSampling at 648423.704961 -> sampleTime 648436.919023 46:1025.031250 3:0.000000
10-12 14:08:24.561 11813 11921 I Gecko   : APZSampling at 648440.296263 -> sampleTime 648455.091939 46:1026.189209 3:0.000000
10-12 14:08:24.580 11813 11921 I Gecko   : APZSampling at 648458.278346 -> sampleTime 648470.145064 46:1027.210571 3:0.000000
10-12 14:08:24.595 11813 11921 I Gecko   : APZSampling at 648473.884753 -> sampleTime 648487.166054 46:1027.888306 3:0.000000
10-12 14:08:24.612 11813 11921 I Gecko   : APZSampling at 648491.202773 -> sampleTime 648504.051262 46:1028.458740 3:0.000000
10-12 14:08:24.629 11813 11921 I Gecko   : APZSampling at 648507.337513 -> sampleTime 648520.260116 46:1028.833496 3:0.000000
10-12 14:08:24.645 11813 11921 I Gecko   : APZSampling at 648524.153034 -> sampleTime 648537.000116 46:1028.833496 3:0.000000
10-12 14:08:24.885 11813 11813 I Gecko   : APZ untransformed 882 -> 882 using APZ offsets 1028.000000 1028.833496 1028.833496 1028.833496
10-12 14:08:24.909 11813 11813 I Gecko   : APZ untransformed 880 -> 880 using APZ offsets 1028.000000 1028.833496 1028.833496 1028.833496
10-12 14:08:24.926 11813 11813 I Gecko   : APZ untransformed 867 -> 867 using APZ offsets 1028.000000 1028.833496 1028.833496 1028.833496
10-12 14:08:24.943 11813 11813 I Gecko   : APZ untransformed 833 -> 833 using APZ offsets 1028.000000 1028.833496 1028.833496 1028.833496
10-12 14:08:24.959 11813 11813 I Gecko   : APZ untransformed 780 -> 833 using APZ offsets 1028.000000 1028.833496 1028.833496 1028.833496
10-12 14:08:24.962 11813 11921 I Gecko   : APZSampling at 648840.658346 -> sampleTime 648855.779960 46:1055.333496 3:0.000000
10-12 14:08:24.976 11813 11921 I Gecko   : APZSampling at 648854.753034 -> sampleTime 648871.133293 46:1055.333496 3:0.000000
10-12 14:08:24.976 11813 11813 I Gecko   : APZ untransformed 713 -> 780 using APZ offsets 1028.000000 1055.333496 1055.333496 1055.333496
10-12 14:08:24.992 11813 11813 I Gecko   : APZ untransformed 629 -> 713 using APZ offsets 1028.000000 1088.833496 1055.333496 1088.833496
10-12 14:08:24.992 11813 11921 I Gecko   : APZSampling at 648871.156159 -> sampleTime 648887.550689 46:1130.833496 3:0.000000
10-12 14:08:25.006 11813 11921 I Gecko   : APZSampling at 648884.402461 -> sampleTime 648900.913918 46:1130.833496 3:0.000000
10-12 14:08:25.009 11813 11813 I Gecko   : APZ untransformed 535 -> 713 using APZ offsets 1089.000000 1088.833496 1130.833496 1088.833496
10-12 14:08:25.012 11813 11921 I Gecko   : APZSampling at 648890.502825 -> sampleTime 648904.352720 46:1177.833496 3:0.000000
10-12 14:08:25.018 11813 11921 I Gecko   : APZSampling at 648896.437825 -> sampleTime 648911.195741 46:1177.833496 3:0.000000
10-12 14:08:25.026 11813 11813 I Gecko   : APZ untransformed 445 -> 535 using APZ offsets 1089.000000 1177.833496 1177.833496 1177.833496
10-12 14:08:25.029 11813 11921 I Gecko   : APZSampling at 648907.974023 -> sampleTime 648921.266366 46:1222.833496 3:0.000000
10-12 14:08:25.036 11813 11813 I Gecko   : APZ untransformed 412 -> 445 using APZ offsets 1089.000000 1222.833496 1222.833496 1222.833496
10-12 14:08:25.036 11813 11813 I Gecko   : APZ untransformed 412 -> 445 using APZ offsets 1089.000000 1222.833496 1222.833496 1222.833496
10-12 14:08:25.044 11813 11921 I Gecko   : APZSampling at 648923.016159 -> sampleTime 648938.195325 46:1239.333496 3:0.000000
10-12 14:08:25.069 11813 11921 I Gecko   : APZSampling at 648947.462721 -> sampleTime 648954.708762 46:1313.191040 3:0.000000
10-12 14:08:25.078 11813 11921 I Gecko   : APZSampling at 648956.959075 -> sampleTime 648971.386054 46:1365.365356 3:0.000000
10-12 14:08:25.096 11813 11921 I Gecko   : APZSampling at 648974.717461 -> sampleTime 648988.235064 46:1417.450928 3:0.000000
10-12 14:08:25.136 11813 11921 I Gecko   : APZSampling at 649014.341471 -> sampleTime 649005.011054 46:1469.313965 3:0.000000
10-12 14:08:25.143 11813 11921 I Gecko   : APZSampling at 649021.564388 -> sampleTime 649037.990273 46:1520.125732 3:0.000000
10-12 14:08:25.155 11813 11921 I Gecko   : APZSampling at 649033.668815 -> sampleTime 649050.044752 46:1616.466187 3:0.000000
10-12 14:08:25.164 11813 11921 I Gecko   : APZSampling at 649042.421992 -> sampleTime 649055.062095 46:1650.450806 3:0.000000
10-12 14:08:25.187 11813 11921 I Gecko   : APZSampling at 649065.416471 -> sampleTime 649071.939908 46:1664.408569 3:0.000000
10-12 14:08:25.196 11813 11921 I Gecko   : APZSampling at 649074.869596 -> sampleTime 649088.040064 46:1710.396606 3:0.000000
10-12 14:08:25.218 11813 11921 I Gecko   : APZSampling at 649097.156315 -> sampleTime 649105.360950 46:1752.762939 3:0.000000
10-12 14:08:25.233 11813 11921 I Gecko   : APZSampling at 649112.046888 -> sampleTime 649121.670845 46:1796.838623 3:0.000000
10-12 14:08:25.246 11813 11921 I Gecko   : APZSampling at 649124.335846 -> sampleTime 649138.579283 46:1836.941162 3:0.000000
10-12 14:08:25.262 11813 11921 I Gecko   : APZSampling at 649141.285377 -> sampleTime 649155.261887 46:1876.900879 3:0.000000
10-12 14:08:25.289 11813 11921 I Gecko   : APZSampling at 649167.848763 -> sampleTime 649172.316783 46:1914.785278 3:0.000000
10-12 14:08:25.301 11813 11921 I Gecko   : APZSampling at 649179.950638 -> sampleTime 649188.889960 46:1952.064941 3:0.000000
10-12 14:08:25.314 11813 11921 I Gecko   : APZSampling at 649192.867513 -> sampleTime 649205.318970 46:1986.895996 3:0.000000
10-12 14:08:25.330 11813 11921 I Gecko   : APZSampling at 649208.974700 -> sampleTime 649221.751939 46:2019.925049 3:0.000000
10-12 14:08:25.354 11813 11921 I Gecko   : APZSampling at 649233.056002 -> sampleTime 649238.734960 46:2051.697754 3:0.000000
10-12 14:08:25.369 11813 11921 I Gecko   : APZSampling at 649247.303763 -> sampleTime 649255.728502 46:2083.236084 3:0.000000
10-12 14:08:25.379 11813 11921 I Gecko   : APZSampling at 649258.056888 -> sampleTime 649272.096627 46:2113.434326 3:0.000000
10-12 14:08:25.399 11813 11921 I Gecko   : APZSampling at 649278.094231 -> sampleTime 649289.034804 46:2141.259277 3:0.000000
10-12 14:08:25.413 11813 11921 I Gecko   : APZSampling at 649291.601783 -> sampleTime 649305.486627 46:2168.930908 3:0.000000
10-12 14:08:25.430 11813 11921 I Gecko   : APZSampling at 649308.719336 -> sampleTime 649322.455481 46:2194.708984 3:0.000000
10-12 14:08:25.446 11813 11921 I Gecko   : APZSampling at 649325.061575 -> sampleTime 649338.878397 46:2220.089844 3:0.000000
10-12 14:08:25.463 11813 11921 I Gecko   : APZSampling at 649341.900221 -> sampleTime 649355.654127 46:2243.645752 3:0.000000
10-12 14:08:25.484 11813 11921 I Gecko   : APZSampling at 649362.773606 -> sampleTime 649372.387512 46:2266.759033 3:0.000000
10-12 14:08:25.497 11813 11921 I Gecko   : APZSampling at 649375.499231 -> sampleTime 649389.059074 46:2288.808105 3:0.000000
10-12 14:08:25.514 11813 11921 I Gecko   : APZSampling at 649392.591992 -> sampleTime 649406.021679 46:2309.817871 3:0.000000
10-12 14:08:25.535 11813 11921 I Gecko   : APZSampling at 649413.485169 -> sampleTime 649422.527304 46:2330.312500 3:0.000000
10-12 14:08:25.548 11813 11921 I Gecko   : APZSampling at 649426.302513 -> sampleTime 649439.144543 46:2349.472656 3:0.000000
10-12 14:08:25.563 11813 11921 I Gecko   : APZSampling at 649441.697461 -> sampleTime 649455.923449 46:2367.845215 3:0.000000
10-12 14:08:25.578 11813 11921 I Gecko   : APZSampling at 649457.245117 -> sampleTime 649472.501574 46:2385.639404 3:0.000000
10-12 14:08:25.601 11813 11921 I Gecko   : APZSampling at 649479.562877 -> sampleTime 649488.988345 46:2402.515137 3:0.000000
10-12 14:08:25.613 11813 11921 I Gecko   : APZSampling at 649491.783398 -> sampleTime 649505.681522 46:2418.576660 3:0.000000
10-12 14:08:25.630 11813 11921 I Gecko   : APZSampling at 649509.136158 -> sampleTime 649522.625637 46:2434.109131 3:0.000000
10-12 14:08:25.647 11813 11921 I Gecko   : APZSampling at 649525.887513 -> sampleTime 649539.732356 46:2449.218262 3:0.000000
10-12 14:08:25.664 11813 11921 I Gecko   : APZSampling at 649542.709231 -> sampleTime 649556.332772 46:2463.831055 3:0.000000
10-12 14:08:25.680 11813 11921 I Gecko   : APZSampling at 649559.233710 -> sampleTime 649572.726366 46:2477.337891 3:0.000000
10-12 14:08:25.697 11813 11921 I Gecko   : APZSampling at 649575.961263 -> sampleTime 649589.748085 46:2490.106201 3:0.000000
10-12 14:08:25.714 11813 11921 I Gecko   : APZSampling at 649592.546054 -> sampleTime 649606.383970 46:2502.806641 3:0.000000
10-12 14:08:25.735 11813 11921 I Gecko   : APZSampling at 649614.229075 -> sampleTime 649622.644908 46:2514.656250 3:0.000000
10-12 14:08:25.747 11813 11921 I Gecko   : APZSampling at 649625.658815 -> sampleTime 649639.562981 46:2525.701172 3:0.000000
10-12 14:08:25.765 11813 11921 I Gecko   : APZSampling at 649643.609908 -> sampleTime 649655.905220 46:2536.693359 3:0.000000
10-12 14:08:25.781 11813 11921 I Gecko   : APZSampling at 649660.114127 -> sampleTime 649672.833345 46:2546.841309 3:0.000000
10-12 14:08:25.796 11813 11921 I Gecko   : APZSampling at 649675.231523 -> sampleTime 649689.480689 46:2556.846191 3:0.000000
10-12 14:08:25.815 11813 11921 I Gecko   : APZSampling at 649694.176367 -> sampleTime 649706.604283 46:2566.217773 3:0.000000
10-12 14:08:25.830 11813 11921 I Gecko   : APZSampling at 649709.137721 -> sampleTime 649722.956731 46:2575.418945 3:0.000000
10-12 14:08:25.847 11813 11921 I Gecko   : APZSampling at 649725.552565 -> sampleTime 649739.893658 46:2583.787109 3:0.000000
10-12 14:08:25.869 11813 11921 I Gecko   : APZSampling at 649748.022252 -> sampleTime 649756.692043 46:2591.983398 3:0.000000
10-12 14:08:25.880 11813 11921 I Gecko   : APZSampling at 649759.072044 -> sampleTime 649773.439022 46:2599.728516 3:0.000000
10-12 14:08:25.897 11813 11921 I Gecko   : APZSampling at 649775.458502 -> sampleTime 649789.429126 46:2607.074707 3:0.000000
10-12 14:08:25.913 11813 11921 I Gecko   : APZSampling at 649792.029387 -> sampleTime 649806.249595 46:2613.705078 3:0.000000
10-12 14:08:25.930 11813 11921 I Gecko   : APZSampling at 649809.067044 -> sampleTime 649823.647772 46:2620.310547 3:0.000000
10-12 14:08:25.950 11813 11921 I Gecko   : APZSampling at 649828.992721 -> sampleTime 649839.963501 46:2626.778076 3:0.000000
10-12 14:08:25.966 11813 11921 I Gecko   : APZSampling at 649844.694075 -> sampleTime 649856.669699 46:2632.517090 3:0.000000
10-12 14:08:25.980 11813 11921 I Gecko   : APZSampling at 649859.136106 -> sampleTime 649873.781418 46:2638.018066 3:0.000000
10-12 14:08:25.999 11813 11921 I Gecko   : APZSampling at 649877.784908 -> sampleTime 649890.186887 46:2643.334229 3:0.000000
10-12 14:08:26.015 11813 11921 I Gecko   : APZSampling at 649894.022721 -> sampleTime 649906.651522 46:2648.134766 3:0.000000
10-12 14:08:26.032 11813 11921 I Gecko   : APZSampling at 649910.434075 -> sampleTime 649923.717824 46:2652.636230 3:0.000000
10-12 14:08:26.049 11813 11921 I Gecko   : APZSampling at 649927.426002 -> sampleTime 649940.368189 46:2656.986328 3:0.000000
10-12 14:08:26.065 11813 11921 I Gecko   : APZSampling at 649944.101367 -> sampleTime 649957.087564 46:2660.951172 3:0.000000
10-12 14:08:26.082 11813 11921 I Gecko   : APZSampling at 649960.934492 -> sampleTime 649973.630428 46:2664.661621 3:0.000000
10-12 14:08:26.098 11813 11921 I Gecko   : APZSampling at 649976.910637 -> sampleTime 649990.872408 46:2668.029541 3:0.000000
10-12 14:08:26.115 11813 11921 I Gecko   : APZSampling at 649993.477460 -> sampleTime 650007.129178 46:2671.273438 3:0.000000
10-12 14:08:26.131 11813 11921 I Gecko   : APZSampling at 650010.021627 -> sampleTime 650023.756105 46:2674.088379 3:0.000000
10-12 14:08:26.150 11813 11921 I Gecko   : APZSampling at 650028.923502 -> sampleTime 650040.812043 46:2676.705322 3:0.000000
10-12 14:08:26.165 11813 11921 I Gecko   : APZSampling at 650044.201106 -> sampleTime 650057.275741 46:2679.128906 3:0.000000
10-12 14:08:26.182 11813 11921 I Gecko   : APZSampling at 650061.014231 -> sampleTime 650073.804803 46:2681.238281 3:0.000000
10-12 14:08:26.202 11813 11921 I Gecko   : APZSampling at 650080.878814 -> sampleTime 650090.523189 46:2683.136963 3:0.000000
10-12 14:08:26.214 11813 11921 I Gecko   : APZSampling at 650092.891106 -> sampleTime 650107.312147 46:2684.801758 3:0.000000
10-12 14:08:26.231 11813 11921 I Gecko   : APZSampling at 650109.989700 -> sampleTime 650124.009595 46:2686.255371 3:0.000000
10-12 14:08:26.249 11813 11921 I Gecko   : APZSampling at 650128.088398 -> sampleTime 650141.218189 46:2687.491943 3:0.000000
10-12 14:08:26.266 11813 11921 I Gecko   : APZSampling at 650144.275377 -> sampleTime 650157.631678 46:2688.536377 3:0.000000
10-12 14:08:26.282 11813 11921 I Gecko   : APZSampling at 650161.209908 -> sampleTime 650174.518918 46:2689.317871 3:0.000000
10-12 14:08:26.299 11813 11921 I Gecko   : APZSampling at 650177.728241 -> sampleTime 650191.125637 46:2689.925293 3:0.000000
10-12 14:08:26.316 11813 11921 I Gecko   : APZSampling at 650194.228866 -> sampleTime 650208.403189 46:2690.333252 3:0.000000
10-12 14:08:26.332 11813 11921 I Gecko   : APZSampling at 650211.239283 -> sampleTime 650224.499751 46:2690.333252 3:0.000000
10-12 14:08:26.562 11813 11813 I Gecko   : APZ untransformed 890 -> 890 using APZ offsets 2679.000000 2690.333252 2690.333252 2690.333252
10-12 14:08:26.587 11813 11921 I Gecko   : APZSampling at 650465.713710 -> sampleTime 650482.121939 46:2690.333252 3:0.000000
10-12 14:08:26.597 11813 11813 I Gecko   : APZ untransformed 883 -> 883 using APZ offsets 2690.500000 2690.333252 2690.333252 2690.333252
10-12 14:08:26.615 11813 11813 I Gecko   : APZ untransformed 865 -> 865 using APZ offsets 2690.500000 2690.333252 2690.333252 2690.333252
10-12 14:08:26.630 11813 11813 I Gecko   : APZ untransformed 834 -> 865 using APZ offsets 2690.500000 2690.333252 2690.333252 2690.333252
10-12 14:08:26.631 11813 11921 I Gecko   : APZSampling at 650509.725325 -> sampleTime 650525.091366 46:2705.833252 3:0.000000
10-12 14:08:26.647 11813 11813 I Gecko   : APZ untransformed 773 -> 834 using APZ offsets 2690.500000 2705.833252 2705.833252 2705.833252
10-12 14:08:26.648 11813 11921 I Gecko   : APZSampling at 650526.751106 -> sampleTime 650542.516366 46:2736.333252 3:0.000000
10-12 14:08:26.656 11813 11813 I Gecko   : APZ untransformed 739 -> 773 using APZ offsets 2690.500000 2736.333252 2736.333252 2736.333252
10-12 14:08:26.657 11813 11813 I Gecko   : APZ untransformed 739 -> 739 using APZ offsets 2690.500000 2753.333252 2736.333252 2753.333252
10-12 14:08:26.658 11813 11921 I Gecko   : APZSampling at 650536.508033 -> sampleTime 650553.026887 46:2753.333252 3:0.000000
10-12 14:08:26.664 11813 11921 I Gecko   : APZSampling at 650542.643189 -> sampleTime 650558.877043 46:2796.613037 3:0.000000
10-12 14:08:26.677 11813 11921 I Gecko   : APZSampling at 650556.083658 -> sampleTime 650572.562199 46:2811.707031 3:0.000000
10-12 14:08:26.686 11813 11921 I Gecko   : APZSampling at 650564.356835 -> sampleTime 650575.682928 46:2846.775635 3:0.000000
10-12 14:08:26.699 11813 11921 I Gecko   : APZSampling at 650578.105377 -> sampleTime 650592.186834 46:2854.720459 3:0.000000
10-12 14:08:26.716 11813 11921 I Gecko   : APZSampling at 650594.347460 -> sampleTime 650608.970220 46:2896.429199 3:0.000000
10-12 14:08:26.737 11813 11921 I Gecko   : APZSampling at 650615.844023 -> sampleTime 650625.667668 46:2937.951904 3:0.000000
10-12 14:08:26.749 11813 11921 I Gecko   : APZSampling at 650627.757095 -> sampleTime 650642.117251 46:2978.409668 3:0.000000
10-12 14:08:26.765 11813 11921 I Gecko   : APZSampling at 650643.895585 -> sampleTime 650658.781991 46:3017.009277 3:0.000000
10-12 14:08:26.787 11813 11921 I Gecko   : APZSampling at 650665.631366 -> sampleTime 650675.594334 46:3054.996338 3:0.000000
10-12 14:08:26.800 11813 11921 I Gecko   : APZSampling at 650678.310845 -> sampleTime 650692.193032 46:3091.846191 3:0.000000
10-12 14:08:26.817 11813 11921 I Gecko   : APZSampling at 650695.423085 -> sampleTime 650709.230793 46:3126.967285 3:0.000000
10-12 14:08:26.833 11813 11921 I Gecko   : APZSampling at 650712.103345 -> sampleTime 650725.727147 46:3161.429688 3:0.000000
10-12 14:08:26.853 11813 11921 I Gecko   : APZSampling at 650731.714439 -> sampleTime 650742.357407 46:3193.497803 3:0.000000
10-12 14:08:26.866 11813 11921 I Gecko   : APZSampling at 650744.544439 -> sampleTime 650758.709386 46:3224.288574 3:0.000000
10-12 14:08:26.882 11813 11921 I Gecko   : APZSampling at 650760.763137 -> sampleTime 650775.413553 46:3253.313965 3:0.000000
10-12 14:08:26.900 11813 11921 I Gecko   : APZSampling at 650778.494335 -> sampleTime 650792.598761 46:3281.538086 3:0.000000
10-12 14:08:26.919 11813 11921 I Gecko   : APZSampling at 650798.022252 -> sampleTime 650809.779803 46:3309.302002 3:0.000000
10-12 14:08:26.934 11813 11921 I Gecko   : APZSampling at 650813.038241 -> sampleTime 650825.613657 46:3335.582031 3:0.000000
10-12 14:08:26.951 11813 11921 I Gecko   : APZSampling at 650830.188033 -> sampleTime 650842.783084 46:3358.756592 3:0.000000
10-12 14:08:26.966 11813 11921 I Gecko   : APZSampling at 650845.015585 -> sampleTime 650859.261418 46:3382.600342 3:0.000000
10-12 14:08:26.985 11813 11921 I Gecko   : APZSampling at 650863.685637 -> sampleTime 650876.213084 46:3404.450439 3:0.000000
10-12 14:08:27.004 11813 11921 I Gecko   : APZSampling at 650882.406366 -> sampleTime 650892.836991 46:3425.753906 3:0.000000
10-12 14:08:27.016 11813 11921 I Gecko   : APZSampling at 650894.754283 -> sampleTime 650909.847616 46:3445.697510 3:0.000000
10-12 14:08:27.035 11813 11921 I Gecko   : APZSampling at 650913.588762 -> sampleTime 650926.081209 46:3465.034424 3:0.000000
10-12 14:08:27.051 11813 11921 I Gecko   : APZSampling at 650929.964231 -> sampleTime 650942.998553 46:3482.644531 3:0.000000
10-12 14:08:27.067 11813 11921 I Gecko   : APZSampling at 650945.970741 -> sampleTime 650959.514386 46:3500.066650 3:0.000000
10-12 14:08:27.085 11813 11921 I Gecko   : APZSampling at 650963.556366 -> sampleTime 650975.892668 46:3516.267578 3:0.000000
10-12 14:08:27.101 11813 11921 I Gecko   : APZSampling at 650979.501314 -> sampleTime 650993.237928 46:3531.539062 3:0.000000
10-12 14:08:27.121 11813 11921 I Gecko   : APZSampling at 650999.759804 -> sampleTime 651009.828813 46:3546.928223 3:0.000000
10-12 14:08:27.136 11813 11921 I Gecko   : APZSampling at 651014.517199 -> sampleTime 651026.282095 46:3560.881348 3:0.000000
10-12 14:08:27.150 11813 11921 I Gecko   : APZSampling at 651028.409699 -> sampleTime 651043.046730 46:3574.070312 3:0.000000
10-12 14:08:27.167 11813 11921 I Gecko   : APZSampling at 651045.678762 -> sampleTime 651059.877303 46:3586.827393 3:0.000000
10-12 14:08:27.192 11813 11921 I Gecko   : APZSampling at 651070.387720 -> sampleTime 651076.503449 46:3599.007080 3:0.000000
10-12 14:08:27.207 11813 11921 I Gecko   : APZSampling at 651085.969231 -> sampleTime 651094.894699 46:3610.413574 3:0.000000
10-12 14:08:27.217 11813 11921 I Gecko   : APZSampling at 651095.559699 -> sampleTime 651110.126313 46:3622.399902 3:0.000000
10-12 14:08:27.234 11813 11921 I Gecko   : APZSampling at 651112.775949 -> sampleTime 651126.547043 46:3631.772461 3:0.000000
10-12 14:08:27.299 11813 11921 I Gecko   : APZSampling at 651177.950064 -> sampleTime 651143.196886 46:3641.411621 3:0.000000
10-12 14:08:27.315 11813 11921 I Gecko   : APZSampling at 651193.625845 -> sampleTime 651209.980532 46:3650.677490 3:0.000000
10-12 14:08:27.332 11813 11921 I Gecko   : APZSampling at 651210.764022 -> sampleTime 651226.851886 46:3683.163574 3:0.000000
10-12 14:08:27.350 11813 11921 I Gecko   : APZSampling at 651228.266574 -> sampleTime 651241.910324 46:3690.279297 3:0.000000
10-12 14:08:27.361 11813 11921 I Gecko   : APZSampling at 651239.329751 -> sampleTime 651255.436834 46:3696.287354 3:0.000000
10-12 14:08:27.369 11813 11921 I Gecko   : APZSampling at 651248.233085 -> sampleTime 651260.259282 46:3701.402344 3:0.000000
10-12 14:08:27.384 11813 11921 I Gecko   : APZSampling at 651262.573814 -> sampleTime 651276.581105 46:3703.172607 3:0.000000
10-12 14:08:27.401 11813 11921 I Gecko   : APZSampling at 651279.797616 -> sampleTime 651293.961157 46:3708.929688 3:0.000000
10-12 14:08:27.419 11813 11921 I Gecko   : APZSampling at 651297.368970 -> sampleTime 651310.346001 46:3714.680420 3:0.000000
10-12 14:08:27.440 11813 11921 I Gecko   : APZSampling at 651318.402564 -> sampleTime 651326.690845 46:3719.761963 3:0.000000
10-12 14:08:27.452 11813 11921 I Gecko   : APZSampling at 651331.150637 -> sampleTime 651344.111105 46:3724.509766 3:0.000000
10-12 14:08:27.468 11813 11921 I Gecko   : APZSampling at 651347.032824 -> sampleTime 651360.247720 46:3729.235352 3:0.000000
10-12 14:08:27.485 11813 11921 I Gecko   : APZSampling at 651363.296679 -> sampleTime 651377.306053 46:3733.309082 3:0.000000
10-12 14:08:27.502 11813 11921 I Gecko   : APZSampling at 651380.805793 -> sampleTime 651393.863865 46:3737.316895 3:0.000000
10-12 14:08:27.519 11813 11921 I Gecko   : APZSampling at 651397.872460 -> sampleTime 651410.712511 46:3740.911621 3:0.000000
10-12 14:08:27.539 11813 11921 I Gecko   : APZSampling at 651417.600168 -> sampleTime 651427.227563 46:3744.290527 3:0.000000
10-12 14:08:27.553 11813 11921 I Gecko   : APZSampling at 651431.650429 -> sampleTime 651443.700845 46:3747.330078 3:0.000000
10-12 14:08:27.608 11813 11921 I Gecko   : APZSampling at 651487.022824 -> sampleTime 651460.728188 46:3750.113525 3:0.000000
10-12 14:08:27.617 11813 11921 I Gecko   : APZSampling at 651495.508501 -> sampleTime 651510.979490 46:3752.720215 3:0.000000
10-12 14:08:27.632 11813 11921 I Gecko   : APZSampling at 651511.064439 -> sampleTime 651527.417667 46:3758.961426 3:0.000000
10-12 14:08:27.649 11813 11921 I Gecko   : APZSampling at 651527.970116 -> sampleTime 651544.101417 46:3760.544189 3:0.000000
10-12 14:08:27.663 11813 11921 I Gecko   : APZSampling at 651541.875845 -> sampleTime 651557.924438 46:3761.943359 3:0.000000
10-12 14:08:27.671 11813 11921 I Gecko   : APZSampling at 651549.391574 -> sampleTime 651560.951522 46:3762.931152 3:0.000000
10-12 14:08:27.684 11813 11921 I Gecko   : APZSampling at 651563.258345 -> sampleTime 651577.315897 46:3763.129639 3:0.000000
10-12 14:08:27.701 11813 11921 I Gecko   : APZSampling at 651579.941262 -> sampleTime 651594.219282 46:3764.090820 3:0.000000
10-12 14:08:27.718 11813 11921 I Gecko   : APZSampling at 651596.873189 -> sampleTime 651611.073136 46:3764.868164 3:0.000000
10-12 14:08:27.734 11813 11921 I Gecko   : APZSampling at 651613.254595 -> sampleTime 651627.236261 46:3765.454590 3:0.000000
10-12 14:08:27.754 11813 11921 I Gecko   : APZSampling at 651632.258918 -> sampleTime 651645.157199 46:3765.823242 3:0.000000
10-12 14:08:27.769 11813 11921 I Gecko   : APZSampling at 651648.304387 -> sampleTime 651660.951626 46:3765.823242 3:0.000000
10-12 14:08:27.833 11813 11921 I Gecko   : APZSampling at 651711.712303 -> sampleTime 651727.839230 46:3765.823242 3:0.000000
10-12 14:08:27.933 11813 11921 I Gecko   : APZSampling at 651811.864751 -> sampleTime 651828.251678 46:3765.823242 3:0.000000
10-12 14:08:28.034 11813 11921 I Gecko   : APZSampling at 651912.323605 -> sampleTime 651928.245480 46:3765.823242 3:0.000000
10-12 14:08:28.234 11813 11921 I Gecko   : APZSampling at 652112.405897 -> sampleTime 652128.833188 46:3765.823242 3:0.000000
10-12 14:08:28.648 11813 11921 I Gecko   : APZSampling at 652527.093189 -> sampleTime 652543.381052 46:3765.823242 3:0.000000

Comment 52

[Mark]

And I think this is a fling jank when an image popped in on mozilla.org. I think (but am not at all sure) the jank and the "APZ untransformed" messages happened at the same time. This is just an excerpt from an enormous fling logging message set.

10-12 14:11:44.069 11813 11921 I Gecko   : APZSampling at 847947.971031 -> sampleTime 847954.642801 59:1297.593750 3:0.000000
10-12 14:11:44.078 11813 11921 I Gecko   : APZSampling at 847956.986291 -> sampleTime 847971.202020 59:1302.662598 3:0.000000
10-12 14:11:44.095 11813 11921 I Gecko   : APZSampling at 847973.885562 -> sampleTime 847988.182853 59:1307.439819 3:0.000000
10-12 14:11:44.112 11813 11921 I Gecko   : APZSampling at 847990.615093 -> sampleTime 848004.735665 59:1311.996582 3:0.000000
10-12 14:11:44.131 11813 11921 I Gecko   : APZSampling at 848009.696760 -> sampleTime 848021.464415 59:1316.149048 3:0.000000
10-12 14:11:44.146 11813 11921 I Gecko   : APZSampling at 848025.131916 -> sampleTime 848038.412540 59:1320.057373 3:0.000000
10-12 14:11:44.163 11813 11921 I Gecko   : APZSampling at 848041.309885 -> sampleTime 848054.950405 59:1323.706421 3:0.000000
10-12 14:11:44.180 11813 11921 I Gecko   : APZSampling at 848058.472281 -> sampleTime 848071.800717 59:1327.017090 3:0.000000
10-12 14:11:44.196 11813 11921 I Gecko   : APZSampling at 848074.874208 -> sampleTime 848088.534728 59:1330.096924 3:0.000000
10-12 14:11:44.214 11813 11921 I Gecko   : APZSampling at 848092.639051 -> sampleTime 848105.299936 59:1332.904053 3:0.000000
10-12 14:11:44.230 11813 11921 I Gecko   : APZSampling at 848108.968374 -> sampleTime 848121.779780 59:1335.466309 3:0.000000
10-12 14:11:44.246 11813 11921 I Gecko   : APZSampling at 848124.943791 -> sampleTime 848138.708217 59:1337.726196 3:0.000000
10-12 14:11:44.262 11813 11921 I Gecko   : APZSampling at 848141.169833 -> sampleTime 848155.568322 59:1339.826416 3:0.000000
10-12 14:11:44.281 11813 11921 I Gecko   : APZSampling at 848159.458635 -> sampleTime 848171.515092 59:1341.661621 3:0.000000
10-12 14:11:44.297 11813 11921 I Gecko   : APZSampling at 848175.834416 -> sampleTime 848188.866759 59:1343.191528 3:0.000000
10-12 14:11:44.314 11813 11921 I Gecko   : APZSampling at 848193.224468 -> sampleTime 848205.580092 59:1344.637573 3:0.000000
10-12 14:11:44.334 11813 11921 I Gecko   : APZSampling at 848212.484156 -> sampleTime 848221.943113 59:1345.792114 3:0.000000
10-12 14:11:44.346 11813 11921 I Gecko   : APZSampling at 848224.934364 -> sampleTime 848238.475665 59:1346.735596 3:0.000000
10-12 14:11:44.362 11813 11921 I Gecko   : APZSampling at 848241.157020 -> sampleTime 848255.400040 59:1347.481934 3:0.000000
10-12 14:11:44.379 11813 11921 I Gecko   : APZSampling at 848257.948635 -> sampleTime 848272.205144 59:1348.042114 3:0.000000
10-12 14:11:44.396 11813 11921 I Gecko   : APZSampling at 848274.750822 -> sampleTime 848288.843999 59:1348.414917 3:0.000000
10-12 14:11:44.413 11813 11921 I Gecko   : APZSampling at 848292.044520 -> sampleTime 848305.646499 59:1348.414917 3:0.000000
10-12 14:11:44.429 11813 11921 I Gecko   : APZSampling at 848307.811812 -> sampleTime 848322.256603 59:1348.414917 3:0.000000
10-12 14:11:44.446 11813 11921 I Gecko   : APZSampling at 848325.051760 -> sampleTime 848338.727749 59:1348.414917 3:0.000000
10-12 14:11:44.463 11813 11921 I Gecko   : APZSampling at 848341.489155 -> sampleTime 848356.183530 59:1348.414917 3:0.000000
10-12 14:11:44.482 11813 11921 I Gecko   : APZSampling at 848360.394468 -> sampleTime 848372.162436 59:1348.414917 3:0.000000
10-12 14:11:44.498 11813 11921 I Gecko   : APZSampling at 848376.622333 -> sampleTime 848388.910405 59:1348.414917 3:0.000000
10-12 14:11:44.514 11813 11921 I Gecko   : APZSampling at 848393.280562 -> sampleTime 848405.815561 59:1348.414917 3:0.000000
10-12 14:11:44.532 11813 11921 I Gecko   : APZSampling at 848410.309885 -> sampleTime 848422.450249 59:1348.414917 3:0.000000
10-12 14:11:44.548 11813 11921 I Gecko   : APZSampling at 848426.865145 -> sampleTime 848439.293321 59:1348.414917 3:0.000000
10-12 14:11:44.564 11813 11921 I Gecko   : APZSampling at 848442.565145 -> sampleTime 848456.087696 59:1348.414917 3:0.000000
10-12 14:11:44.580 11813 11921 I Gecko   : APZSampling at 848459.272853 -> sampleTime 848472.593061 59:1348.414917 3:0.000000
10-12 14:11:44.599 11813 11921 I Gecko   : APZSampling at 848478.036864 -> sampleTime 848489.488999 59:1348.414917 3:0.000000
10-12 14:11:44.872 11813 11921 I Gecko   : APZSampling at 848750.951551 -> sampleTime 848767.339155 59:1348.414917 3:0.000000
10-12 14:11:45.291 11813 11921 I Gecko   : APZSampling at 849169.752124 -> sampleTime 849186.252540 59:1348.414917 3:0.000000
10-12 14:11:48.518 11813 11837 W GeckoEventDispatcher: No listener for Session:DataWritten
10-12 14:11:50.276 11813 11813 I Gecko   : APZ untransformed 747 -> 747 using APZ offsets 1348.500000 1348.414917 1348.414917 1348.414917
10-12 14:11:50.307 11813 11813 I Gecko   : APZ untransformed 746 -> 746 using APZ offsets 1348.500000 1348.414917 1348.414917 1348.414917
10-12 14:11:50.324 11813 11813 I Gecko   : APZ untransformed 736 -> 736 using APZ offsets 1348.500000 1348.414917 1348.414917 1348.414917
10-12 14:11:50.341 11813 11813 I Gecko   : APZ untransformed 704 -> 704 using APZ offsets 1348.500000 1348.414917 1348.414917 1348.414917
10-12 14:11:50.358 11813 11813 I Gecko   : APZ untransformed 648 -> 704 using APZ offsets 1348.500000 1348.414917 1348.414917 1348.414917
10-12 14:11:50.358 11813 11921 I Gecko   : APZSampling at 854237.283528 -> sampleTime 854253.838163 59:1376.414917 3:0.000000
10-12 14:11:50.374 11813 11813 I Gecko   : APZ untransformed 566 -> 648 using APZ offsets 1348.500000 1376.414917 1376.414917 1376.414917
10-12 14:11:50.375 11813 11921 I Gecko   : APZSampling at 854254.183372 -> sampleTime 854269.801705 59:1417.414917 3:0.000000
10-12 14:11:50.382 11813 11921 I Gecko   : APZSampling at 854261.187799 -> sampleTime 854270.089725 59:1417.414917 3:0.000000
10-12 14:11:50.391 11813 11813 I Gecko   : APZ untransformed 450 -> 566 using APZ offsets 1348.500000 1417.414917 1417.414917 1417.414917
10-12 14:11:50.392 11813 11813 I Gecko   : APZ untransformed 450 -> 566 using APZ offsets 1348.500000 1417.414917 1417.414917 1417.414917
10-12 14:11:50.408 11813 11921 I Gecko   : APZSampling at 854286.337539 -> sampleTime 854302.631548 59:1475.414917 3:0.000000
10-12 14:11:50.420 11813 11921 I Gecko   : APZSampling at 854298.387174 -> sampleTime 854314.719986 59:1598.645996 3:0.000000
10-12 14:11:50.427 11813 11921 I Gecko   : APZSampling at 854305.985403 -> sampleTime 854318.241288 59:1644.658569 3:0.000000
10-12 14:11:50.434 11813 11921 I Gecko   : APZSampling at 854313.056862 -> sampleTime 854329.518267 59:1657.970215 3:0.000000
10-12 14:11:50.446 11813 11921 I Gecko   : APZSampling at 854324.819153 -> sampleTime 854334.973632 59:1700.544434 3:0.000000
10-12 14:11:50.459 11813 11921 I Gecko   : APZSampling at 854337.623945 -> sampleTime 854352.132590 59:1720.947144 3:0.000000
10-12 14:11:50.476 11813 11921 I Gecko   : APZSampling at 854355.139674 -> sampleTime 854368.899830 59:1784.682129 3:0.000000
10-12 14:11:50.495 11813 11921 I Gecko   : APZSampling at 854373.581184 -> sampleTime 854386.057330 59:1846.048462 3:0.000000
10-12 14:11:50.511 11813 11921 I Gecko   : APZSampling at 854389.587174 -> sampleTime 854401.954100 59:1907.727417 3:0.000000
10-12 14:11:50.527 11813 11921 I Gecko   : APZSampling at 854405.883632 -> sampleTime 854418.740402 59:1963.684204 3:0.000000
10-12 14:11:50.553 11813 11921 I Gecko   : APZSampling at 854431.684257 -> sampleTime 854435.367642 59:2021.462524 3:0.000000
10-12 14:11:50.563 11813 11921 I Gecko   : APZSampling at 854441.730403 -> sampleTime 854455.558632 59:2077.265381 3:0.000000
10-12 14:11:50.575 11813 11921 I Gecko   : APZSampling at 854453.833268 -> sampleTime 854468.593059 59:2142.878906 3:0.000000
10-12 14:11:50.602 11813 11921 I Gecko   : APZSampling at 854480.563007 -> sampleTime 854485.591027 59:2184.155518 3:0.000000
10-12 14:11:50.609 11813 11921 I Gecko   : APZSampling at 854488.041601 -> sampleTime 854502.298527 59:2236.464600 3:0.000000
10-12 14:11:50.627 11813 11921 I Gecko   : APZSampling at 854505.710247 -> sampleTime 854518.823944 59:2286.315430 3:0.000000
10-12 14:11:50.647 11813 11921 I Gecko   : APZSampling at 854525.885351 -> sampleTime 854535.833423 59:2334.068848 3:0.000000
10-12 14:11:50.660 11813 11921 I Gecko   : APZSampling at 854538.892330 -> sampleTime 854552.293892 59:2381.600098 3:0.000000
10-12 14:11:50.680 11813 11921 I Gecko   : APZSampling at 854558.860039 -> sampleTime 854569.161652 59:2426.092041 3:0.000000
10-12 14:11:50.693 11813 11921 I Gecko   : APZSampling at 854571.662278 -> sampleTime 854585.955246 59:2470.106445 3:0.000000
10-12 14:11:50.710 11813 11921 I Gecko   : APZSampling at 854588.537122 -> sampleTime 854602.813007 59:2512.321289 3:0.000000
10-12 14:11:50.732 11813 11921 I Gecko   : APZSampling at 854610.805403 -> sampleTime 854619.272069 59:2553.201172 3:0.000000
10-12 14:11:50.743 11813 11921 I Gecko   : APZSampling at 854621.661028 -> sampleTime 854635.905298 59:2591.734619 3:0.000000
10-12 14:11:50.770 11813 11921 I Gecko   : APZSampling at 854648.390924 -> sampleTime 854652.816965 59:2629.269775 3:0.000000
10-12 14:11:50.779 11813 11921 I Gecko   : APZSampling at 854657.575143 -> sampleTime 854669.333996 59:2666.097412 3:0.000000

Comment 53

[Mark]

PS good luck!

Comment 54

[Kartikaya Gupta (email:[e-mail])]

Interesting. The numbers themselves seem reasonable, but the jank is correlated with bad interleavings of sampling and touch events. That is, on the "no jank" case, there is a smooth interleaving of touch events and vsyncs, whereas on the janky case we sometimes get multiple touch events per vsync and sometimes don't get any touch events per vsync. In theory the delivery of touch events is entirely up to the OS, and the touch event delivery happens on the java UI thread which shouldn't be blocking on anything else so it's not clear to me why this is happening. More logging needed I guess.

Comment 55

[Mark]

Ha I just spent half an hour swearing at Excel to get to the same conclusion. I'll attach a picture anyway. This is for the "first fling" case bug 1401526 which I haven't looked at so far. I see two janks, perhaps the first is when my finger comes off the screen around 200 px scroll offset; and the second is definitely bug 1401526 as the first page of content goes off the top of the screen around 520 px scroll offset.

What I see is an extra vsync so the vsync delta goes e.g. 16 ms; 17 ms ; 16 ms; 11 ms; 6 ms; 16 ms; 17 ms etc so a short vysnc (11 ms) and then a very short one (6 ms) adding up in total to ~16 ms. Then this extra vsync screws up the scroll offset for the next one or two frames. Or something like that.

I'm sure you know all this already ;)

Comment 56

[Mark]

Attachment: Firefox jank first fling 1.pdf

Comment 57

[Mark]

Yeah it's all over the place, sometimes extra vsync sometimes missing

I have a very slow & fairly fast phone, I guess if the UI thread was struggling the jank would be much worse on the slow phone. It's not (IIRC).

On drag scrolling the jank seems to happen fairly periodically at around every 5-7 frames so perhaps it's some moire effect where the vsync clock rolls past another clock and every now and then they collide and it glitches??

It can't just be hardware interfacing, something in Gecko must be influencing it too because it's worse when the displayport is against its endstops, and the "single jank on the first page fling" always occurs at exactly the same point on the page, ~520 px scroll offset. 

But it's clearly Android specific cos I don't see it on Mac Desktop.

Comment 58

[Mark]

Is the whole refresh driven only by vsync ticks, or is there an event-driven aspect too (i.e. can a TouchEvent trigger a vsync?)

I set your Try to software vsync with layout.frame_rate 10 and expected to see exact 100 ms vsync ticks. But nothing like. They are all over the place for both flings and drags. Ranging from <10 ms right up to 100 ms. On screen fps meter shows the same thing, fps ranges from 10 up to 60 fps, and Mk I eyeball sees the scrolling ranging from very very janky as expected right up to very smooth when I drag up/down/up/down etc.

Expected or weird?

Here's a fling at the middle of the page with layout.frame_rate 10. I think the actual ticks should be at 608*42 ms so 608442, 608542, 608642, 608743, 608842, 608942, 609042, 609143, 609243, 609342, 609443, 609542. But there are loads of extra vsyncs in there. Mostly (but not completely) the "actual" ticks conform to a smooth fling curve, the "extras" seem to cause most (but not all) of the jank problem.

10-13 12:06:26.286 29344 29399 I Gecko   : APZSampling at 608358.669403 -> sampleTime 608458.502632 5:8258.471680 3:0.000000
10-13 12:06:26.289 29344 29399 I Gecko   : APZSampling at 608362.011382 -> sampleTime 608461.802216 5:8258.471680 3:0.000000
10-13 12:06:26.336 29344 29399 I Gecko   : APZSampling at 608408.942320 -> sampleTime 608508.102216 5:8356.471680 3:0.000000
10-13 12:06:26.362 29344 29399 I Gecko   : APZSampling at 608434.237268 -> sampleTime 608533.676278 5:8415.471680 3:0.000000
10-13 12:06:26.369 29344 29399 I Gecko   : APZSampling at 608442.020861 -> sampleTime 608541.704768 5:8691.242188 3:0.000000
10-13 12:06:26.390 29344 29399 I Gecko   : APZSampling at 608462.746278 -> sampleTime 608561.297111 5:8712.155273 3:0.000000
10-13 12:06:26.410 29344 29399 I Gecko   : APZSampling at 608482.804559 -> sampleTime 608574.246278 5:8761.745117 3:0.000000
10-13 12:06:26.470 29344 29399 I Gecko   : APZSampling at 608542.599090 -> sampleTime 608642.058674 5:8793.557617 3:0.000000
10-13 12:06:26.507 29344 29399 I Gecko   : APZSampling at 608579.807215 -> sampleTime 608677.096747 5:8946.008789 3:0.000000
10-13 12:06:26.570 29344 29399 I Gecko   : APZSampling at 608642.705392 -> sampleTime 608742.315861 5:9015.371094 3:0.000000
10-13 12:06:26.609 29344 29399 I Gecko   : APZSampling at 608681.475288 -> sampleTime 608778.838517 5:9128.497070 3:0.000000
10-13 12:06:26.671 29344 29399 I Gecko   : APZSampling at 608743.423517 -> sampleTime 608842.508882 5:9183.582031 3:0.000000
10-13 12:06:26.689 29344 29399 I Gecko   : APZSampling at 608761.211070 -> sampleTime 608860.921590 5:9267.267578 3:0.000000
10-13 12:06:26.711 29344 29399 I Gecko   : APZSampling at 608783.211174 -> sampleTime 608878.626695 5:9288.756836 3:0.000000
10-13 12:06:26.770 29344 29399 I Gecko   : APZSampling at 608842.275028 -> sampleTime 608941.887111 5:9308.503906 3:0.000000
10-13 12:06:26.820 29344 29399 I Gecko   : APZSampling at 608892.277111 -> sampleTime 608989.070549 5:9371.363281 3:0.000000
10-13 12:06:26.870 29344 29399 I Gecko   : APZSampling at 608942.640028 -> sampleTime 609042.208309 5:9411.491211 3:0.000000
10-13 12:06:26.907 29344 29399 I Gecko   : APZSampling at 608979.367736 -> sampleTime 609078.302007 5:9450.607422 3:0.000000
10-13 12:06:26.920 29344 29399 I Gecko   : APZSampling at 608992.987944 -> sampleTime 609090.348830 5:9473.923828 3:0.000000
10-13 12:06:26.932 29344 29399 I Gecko   : APZSampling at 609005.129142 -> sampleTime 609102.021694 5:9481.166016 3:0.000000
10-13 12:06:26.970 29344 29399 I Gecko   : APZSampling at 609042.752840 -> sampleTime 609142.402528 5:9487.936523 3:0.000000
10-13 12:06:27.070 29344 29399 I Gecko   : APZSampling at 609143.064142 -> sampleTime 609242.508882 5:9509.593750 3:0.000000
10-13 12:06:27.170 29344 29399 I Gecko   : APZSampling at 609242.755236 -> sampleTime 609341.894455 5:9552.545898 3:0.000000
10-13 12:06:27.214 29344 29399 I Gecko   : APZSampling at 609286.321434 -> sampleTime 609383.533830 5:9582.431641 3:0.000000
10-13 12:06:27.270 29344 29399 I Gecko   : APZSampling at 609342.621069 -> sampleTime 609442.262996 5:9591.742188 3:0.000000
10-13 12:06:27.281 29344 29399 I Gecko   : APZSampling at 609353.994090 -> sampleTime 609453.737319 5:9601.982422 3:0.000000
10-13 12:06:27.370 29344 29399 I Gecko   : APZSampling at 609443.040496 -> sampleTime 609542.508882 5:9603.612305 3:0.000000
10-13 12:06:27.470 29344 29399 I Gecko   : APZSampling at 609542.300965 -> sampleTime 609641.837007 5:9612.541016 3:0.000000
10-13 12:06:27.570 29344 29399 I Gecko   : APZSampling at 609642.640861 -> sampleTime 609742.117528 5:9612.541016 3:0.000000
10-13 12:06:27.670 29344 29399 I Gecko   : APZSampling at 609742.697163 -> sampleTime 609842.359975 5:9612.541016 3:0.000000
10-13 12:06:28.070 29344 29399 I Gecko   : APZSampling at 610143.034819 -> sampleTime 610242.377423 5:9612.541016 3:0.000000
10-13 12:06:28.570 29344 29399 I Gecko   : APZSampling at 610642.424402 -> sampleTime 610741.844767 5:9612.541016 3:0.000000

Comment 59

[Mark]

Attachment: fling jank software vsync 10 fps.pdf

I did another fling with layout.frame_rate 10 and graphed it. The black squares are all the logged vsync ticks. The red squares are the subset of vsync ticks on 100 ms spacings (what I expected to see). The red line is a cubic fit to just the 100 ms ticks.

The 100 ms ticks form a pretty smooth curve so I think if we had just the 100 ms ticks and the corresponding scroll offsets the fling would be pretty jank free.

But in fact there are a bunch of extra vsyncs in there and they all seem to have an incorrect scroll offset that's not on the curve. They all seem to have scroll offset values that are too large.

What causes the extra vsyncs? Why do they consistently have the wrong scroll offset?

Comment 60

[Mark]

Firefox Desktop (Mac) does what I would expect:- for layout.frame_rate 10 the fps meter hovers around 10 fps and everything scrolls and flings as I expect, jerky but with consistent time steps. So Fennec is very weird:- many unexpected extra vsyncs and occasional missing vsyncs even when using software vsync. Seen on the logging, on the fps meter and by eye. And the extra vsyncs have wrong scroll offsets.

Comment 61

[Mark]

I think that the faster the fling, the more rogue vsyncs occur. With layout.frame_rate 10 if I fling really hard, at the start of the fling about 80% of the vsyncs are rogues and it reduces as the fling slows down. If I fling gently, at the start of the fling only about 25% of the vsyncs are rogues. In both cases, by the time the fling is just drifting to a stop at a few mm/second the rogue vsyncs almost disappear.

Something about the fling velocity affects how often rogue vsyncs occur (I think).

It doesn't seem to happen with a drag scroll, lots of rogue vsyncs no matter how quickly or slowly I drag.

Comment 62

[Kartikaya Gupta (email:[e-mail])]

So in theory the vsync should be driven just by the layout.frame_rate timer (i.e. 100ms spacing in your case). But bug 1484173 which we discovered earlier means that we will get more sampling than that. So maybe I should clean up that patch and get it landed before proceeding here. That is clearly a bug that needs fixing and it seems to at least part of the problem here.

Comment 63

[Mark]

A sensible approach. I'm very curious to know what's going on. I'll keep noodling and will post if I learn more.

Comment 64

[Mark]

I re-installed build 7a20 from comment 17, set layout.frame_rate 10 and did a big fling, got ~5 "faking vsync" messages. A lot fewer "faking vsync" messages than the total "rogue vsyncs" (>20) in a similar fling in comment 59. So I think "faking vsync" is part but probably not all of the problem. But it needs to be fixed first - seeing woods/trees etc.

Comment 65

[Mark]

I assume that the patch for bug 1484173 is in today's Nightly (2018-10-17). If so it didn't make any noticeable difference to the scroll jank.

Comment 66

[Kartikaya Gupta (email:[e-mail])]

Yeah it should be. I made a new try build with the logging on top of the latest mozilla-central code: https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&revision=2063b446f33e1175262939f6b7be9d0a14006d4b

This also includes some logging for when we get touch events from the OS to see if there's any weirdness between that and delivering them to APZ.

Comment 67

[Mark]

I'm quite excited here...

I switched to software vsync using layout.frame_rate 60 and it's substantially better, really smooth in most cases. I think it goes like this.

Switch on software vsync with layout.frame_rate 60
Switch on the fps meter using layers.acceleration.draw-fps

If I jiggle up and down the page there is still some jank while the TXN number is non zero. When it goes to zero everything gets buttery smooth.

But hardware vsync (layout.frame_rate -1) is still janky.

I glanced at your test log version and saw significantly fewer rogue vsync.

I'll dig in some more but the hardware vs software vsync & the TXN things might give you food for thought.

Progress!

Comment 68

[Kartikaya Gupta (email:[e-mail])]

Cool. I'd also be interested in log output from software vsync at 10 fps like you did before. In that scenario we should now only be compositing 10 fps so if there are rogue composites triggered by input events still happening then we should track those down as well.

Comment 69

[Mark]

No rogue composites with software vsync!

layout.frame_rate 10, a fling, notice everything is verrrrry nice with sampleTime at xxx55 ms all the way through. Brilliant.

10-17 18:02:15.982 25207 25264 I Gecko   : APZSampling at 64356.085079 -> sampleTime 64455.606488 5:3565.391846 3:0.000000
10-17 18:02:16.282 25207 25264 I Gecko   : APZSampling at 64656.142996 -> sampleTime 64755.606488 5:3586.391846 3:0.000000
10-17 18:02:16.381 25207 25264 I Gecko   : APZSampling at 64755.531798 -> sampleTime 64855.246850 5:3793.891846 3:0.000000
10-17 18:02:16.487 25207 25264 I Gecko   : APZSampling at 64861.323777 -> sampleTime 64955.606488 5:4046.391846 3:0.000000
10-17 18:02:16.581 25207 25264 I Gecko   : APZSampling at 64955.636121 -> sampleTime 65055.181277 5:5128.609863 3:0.000000
10-17 18:02:16.681 25207 25264 I Gecko   : APZSampling at 65055.876850 -> sampleTime 65155.489923 5:5750.184570 3:0.000000
10-17 18:02:16.782 25207 25264 I Gecko   : APZSampling at 65156.518152 -> sampleTime 65255.606488 5:6314.190918 3:0.000000
10-17 18:02:16.882 25207 25264 I Gecko   : APZSampling at 65255.873412 -> sampleTime 65355.432527 5:6811.090332 3:0.000000
10-17 18:02:16.982 25207 25264 I Gecko   : APZSampling at 65356.372527 -> sampleTime 65455.606488 5:7243.192383 3:0.000000
10-17 18:02:17.082 25207 25264 I Gecko   : APZSampling at 65456.424089 -> sampleTime 65555.406746 5:7619.529297 3:0.000000
10-17 18:02:17.182 25207 25264 I Gecko   : APZSampling at 65556.296225 -> sampleTime 65655.606488 5:7944.368164 3:0.000000
10-17 18:02:17.282 25207 25264 I Gecko   : APZSampling at 65655.874975 -> sampleTime 65755.191068 5:8226.228516 3:0.000000
10-17 18:02:17.382 25207 25264 I Gecko   : APZSampling at 65756.327318 -> sampleTime 65855.596798 5:8468.401367 3:0.000000
10-17 18:02:17.481 25207 25264 I Gecko   : APZSampling at 65855.661016 -> sampleTime 65954.990183 5:8679.425781 3:0.000000
10-17 18:02:17.582 25207 25264 I Gecko   : APZSampling at 65955.902058 -> sampleTime 66055.427735 5:8859.236328 3:0.000000
10-17 18:02:17.682 25207 25264 I Gecko   : APZSampling at 66056.322162 -> sampleTime 66155.606488 5:9015.291992 3:0.000000
10-17 18:02:17.781 25207 25264 I Gecko   : APZSampling at 66155.766745 -> sampleTime 66255.009506 5:9148.394531 3:0.000000
10-17 18:02:17.882 25207 25264 I Gecko   : APZSampling at 66256.038256 -> sampleTime 66355.426120 5:9260.490234 3:0.000000
10-17 18:02:17.982 25207 25264 I Gecko   : APZSampling at 66356.104245 -> sampleTime 66455.606488 5:9355.736328 3:0.000000
10-17 18:02:18.082 25207 25264 I Gecko   : APZSampling at 66455.862006 -> sampleTime 66555.084714 5:9434.667969 3:0.000000
10-17 18:02:18.182 25207 25264 I Gecko   : APZSampling at 66555.921953 -> sampleTime 66655.354870 5:9498.523438 3:0.000000
10-17 18:02:18.282 25207 25264 I Gecko   : APZSampling at 66656.447735 -> sampleTime 66755.606488 5:9549.663086 3:0.000000
10-17 18:02:18.381 25207 25264 I Gecko   : APZSampling at 66755.356433 -> sampleTime 66855.032578 5:9588.780273 3:0.000000
10-17 18:02:18.482 25207 25264 I Gecko   : APZSampling at 66856.058880 -> sampleTime 66955.475026 5:9616.611328 3:0.000000
10-17 18:02:18.583 25207 25264 I Gecko   : APZSampling at 66957.088724 -> sampleTime 67055.606488 5:9634.567383 3:0.000000
10-17 18:02:18.683 25207 25264 I Gecko   : APZSampling at 67057.185964 -> sampleTime 67155.606488 5:9643.177734 3:0.000000
10-17 18:02:18.781 25207 25264 I Gecko   : APZSampling at 67155.674297 -> sampleTime 67255.163516 5:9643.177734 3:0.000000
10-17 18:02:19.282 25207 25264 I Gecko   : APZSampling at 67655.908828 -> sampleTime 67755.459974 5:9643.177734 3:0.000000
10-17 18:02:19.782 25207 25264 I Gecko   : APZSampling at 68156.211588 -> sampleTime 68255.606488 5:9643.177734 3:0.000000

Comment 70

[Mark]

Where I am at the moment

With hardware vsync, I think you've fixed all the fling problems
- single frame of jank when leaving the first screenful - fixed (TBC)
- jank when JS images pop in - fixed (TBC)

with hardware vsync, I think you've not fixed the drag scroll problems
- very janky when dragging in first screen
- jank when reversing scroll direction

Comment 71

[Mark]

Remember the duplicate scroll offsets from comment 44? They often happened at funny vsync timestamps. Now they still occur, but they seem to always occur at the "correct" vsync 16.666 ms timestamp (I think)

With hardware vsync...

Sometimes the touch events come in too late, after the vsync has fired?

Here's an extract of a drag scroll at the top of the page with some duplicate scroll offsets (135.0 px, 169.5 px). What seems to happen is that there is a touch event e.g. 703 px, then a vsync, at 18:11:22.310, moving the scroll position to 135.0, then no new touch event in the next 16 ms frame. The next vsync fires at 18:11:22.326, but the next touch event just misses the vsync by the tiniest amount. So the scroll offset doesn't get updated in the next vsync, it sticks at 135.00. Ditto at 169.5.




10-17 18:11:22.293 25637 25637 I Gecko   : APZ untransformed 606 -> 621 using APZ offsets 0.000000 120.500000 120.500000 120.500000
10-17 18:11:22.309 25637 25637 W GeckoNPZC: Received touch event y=703.246 at t=51034497
10-17 18:11:22.310 25637 25637 I Gecko   : APZ untransformed 592 -> 606 using APZ offsets 0.000000 128.000000 120.500000 128.000000
10-17 18:11:22.310 25637 25694 I Gecko   : APZSampling at 107673.272251 -> sampleTime 107689.235479 5:135.000000 3:0.000000
10-17 18:11:22.326 25637 25694 I Gecko   : APZSampling at 107689.752667 -> sampleTime 107705.966000 5:135.000000 3:0.000000
10-17 18:11:22.326 25637 25637 W GeckoNPZC: Received touch event y=688.8487 at t=51034513
10-17 18:11:22.326 25637 25637 I Gecko   : APZ untransformed 577 -> 592 using APZ offsets 0.000000 135.000000 135.000000 135.000000
10-17 18:11:22.343 25637 25637 W GeckoNPZC: Received touch event y=674.80096 at t=51034530
10-17 18:11:22.343 25637 25694 I Gecko   : APZSampling at 107706.501313 -> sampleTime 107722.629750 5:142.500000 3:0.000000
10-17 18:11:22.343 25637 25637 I Gecko   : APZ untransformed 563 -> 577 using APZ offsets 0.000000 142.500000 142.500000 142.500000
10-17 18:11:22.359 25637 25637 W GeckoNPZC: Received touch event y=660.8459 at t=51034547
10-17 18:11:22.360 25637 25694 I Gecko   : APZSampling at 107723.365219 -> sampleTime 107739.384958 5:149.500000 3:0.000000
10-17 18:11:22.360 25637 25637 I Gecko   : APZ untransformed 549 -> 563 using APZ offsets 0.000000 149.500000 149.500000 149.500000
10-17 18:11:22.376 25637 25694 I Gecko   : APZSampling at 107739.918657 -> sampleTime 107756.273187 5:156.500000 3:0.000000
10-17 18:11:22.376 25637 25637 W GeckoNPZC: Received touch event y=648.10266 at t=51034563
10-17 18:11:22.377 25637 25637 I Gecko   : APZ untransformed 537 -> 549 using APZ offsets 0.000000 156.500000 156.500000 156.500000
10-17 18:11:22.392 25637 25637 W GeckoNPZC: Received touch event y=634.96655 at t=51034580
10-17 18:11:22.393 25637 25637 I Gecko   : APZ untransformed 523 -> 537 using APZ offsets 0.000000 162.500000 156.500000 162.500000
10-17 18:11:22.393 25637 25694 I Gecko   : APZSampling at 107756.820428 -> sampleTime 107772.886104 5:169.500000 3:0.000000
10-17 18:11:22.409 25637 25694 I Gecko   : APZSampling at 107773.269751 -> sampleTime 107789.508135 5:169.500000 3:0.000000
10-17 18:11:22.410 25637 25637 W GeckoNPZC: Received touch event y=621.23895 at t=51034597
10-17 18:11:22.410 25637 25637 I Gecko   : APZ untransformed 510 -> 523 using APZ offsets 162.500000 169.500000 169.500000 169.500000
10-17 18:11:22.426 25637 25637 W GeckoNPZC: Received touch event y=608.18634 at t=51034614

Comment 72

[Mark]

With software vsync @ 60 fps I do see the same problem (touch event happening too late for the vsync to which it pertains) but for some reason it happens much less often. And it seems to happen more when the TXN number on the fps counter is showing quite high values, so when I load a page and first start drag scrolling up/down/up/down it's a bit janky but it cleans up as the TXN number falls away to zero. With hardware vsync it never cleans up.

Comment 73

[Kartikaya Gupta (email:[e-mail])]

Do you still get rogue composites at 10 fps when *dragging* ? (You said no for flinging, but I would expect the same for dragging).

But yeah, from the log in comment 71 it looks like the touch event handling is racing with the sampling. Most likely the OS is handing us touch events aligned with vsync somehow, but we handle those on a separate thread from the sampling code, and so sometimes we update the sample based on the new touch event and sometimes we don't. With software vsync this is less likely to happen because I presume the OS will still give us touch events aligned with hardware vsync while we are using our software timer for sampling. When the TXN count is high the compositor thread (which does the sampling) is going to be more busy and so it won't be as regularly aligned with the vsync timer as it would be if the TXN count is low. That probably explains the behaviour you're seeing.

I'll have to think about a good way to fix this.

Comment 74

[Mark]

No rogue composites when dragging at 10 fps

Re the race you could hardwire a 1 ms delay into acting on the vsync... that should catch the touch event (joke) ;)

I'm looking at a another (!) fling jank issue, can you tell me

- what's the sampleTime number? I understand that APZSampling is the vsync tick timestamp, but what's sampleTime?
- should there be a ~fixed time relationship between APZSampling and sampleTime. If that relationship changes dramatically on a single frame, what does that mean (e.g. blocking on thread X)?
- which value (APZSampling or sampleTime) is used in the fling physics calculation?

cheers & sorry I am causing so much trouble.

Comment 75

[Kartikaya Gupta (email:[e-mail])]

(In reply to Mark from comment #74)
> No rogue composites when dragging at 10 fps

Great :)

> Re the race you could hardwire a 1 ms delay into acting on the vsync... that
> should catch the touch event (joke) ;)

Yeah that was the first thing that came to mind for me as well :) Not good to land something like that but I might make a try build for you to test and see if that actually resolves the issue satisfactorily. It might expose other issues, who knows.

> I'm looking at a another (!) fling jank issue, can you tell me
> 
> - what's the sampleTime number? I understand that APZSampling is the vsync
> tick timestamp, but what's sampleTime?

sampleTime is a number derived from the vsync timestamp (it's the vsync timestamp + one vsync interval, so the "next expected vsync tick" time). The first timestamp in the APZSampling output is the "now" time at which the log line is printed.

> - should there be a ~fixed time relationship between APZSampling and
> sampleTime. If that relationship changes dramatically on a single frame,
> what does that mean (e.g. blocking on thread X)?

Yes, there should be a ~fixed time relationship between the two. If the relationship changes it means the compositor thread got blocked by something. The way the vsync works is that there's a dedicated vsync thread which generates the tick, and that thread does nothing else. The `sampleTime` value is derived from this tick, so it should be very regular. The tick message is sent to the compositor thread, which then does the sampling. But if the compositor thread is busy doing something else when it receives that tick message, it's going to delay the sampling. In that case the APZSampling/sampleTime difference will change. Small variations in this difference should be fine since as long as the sampling/composition step complete before that next vsync things will still turn out ok. If the variation is so large that we end up missing the vsync then there's going to visual jank.

> - which value (APZSampling or sampleTime) is used in the fling physics
> calculation?

The sampleTime value is used in the fling calculations. The idea is that this represents the next vsync time, i.e. the next update to the screen, and so that's what we want to use to calculate positions of things.

> cheers & sorry I am causing so much trouble.

Not at all! Thank you for spending the time to do all this investigation and analysis :)

Comment 76

[Mark]

OK so food for thought.

This is an image popping in during a fling on mozilla.org (it's the "IRL with Veronica Belmont" image I think). Hardware vsync. There is a vsync stutter at APZSampling 502133.88 ms, there is a 26 ms frame then a 6 ms frame, then everything is OK again. The sampleTime prediction is OK with smooth 16 ms increments, and the scroll offset updates correctly by ~27 px / frame

But because the vsync has stuttered the actual scroll offset is wrong for the actual vsync to the screen? I think???

Anyway I think this is the stutter I see on image pop in??? I don't always see it, perhaps one time in four. Not sure. I sometimes - not always - see a similar stutter on any page as the first page of content flings up off the screen, around 400 px scroll offset.

I guess the stutter is always there, but whether I see it or not depends on how far out of alignment that single vsync is. If it's only a couple of ms I don't see it, if it's ~ 10 ms as here, I see it.

I don't really understand why the hardware vsync stutters if what you said about dedicated thread is true. And I guesss that this stutter is workload-related, it happens when Fennec gets busy painting that image in. Not on normal flings Or something???

Not really sure about this one, still digging in, any thoughts welcome.

Excerpt from fling:-

10-19 12:30:51.211 10448 10516 I Gecko   : APZSampling at 502056.949548 -> sampleTime 502073.283975 15:1254.265381 3:0.000000
10-19 12:30:51.227 10448 10516 I Gecko   : APZSampling at 502073.724496 -> sampleTime 502090.062464 15:1284.435669 3:0.000000
10-19 12:30:51.244 10448 10516 I Gecko   : APZSampling at 502090.568663 -> sampleTime 502106.970173 15:1313.591187 3:0.000000
10-19 12:30:51.261 10448 10516 I Gecko   : APZSampling at 502107.571423 -> sampleTime 502123.765329 15:1341.883057 3:0.000000
10-19 12:30:51.288 10448 10516 I Gecko   : APZSampling at 502133.884288 -> sampleTime 502139.968714 15:1368.900635 3:0.000000
10-19 12:30:51.294 10448 10516 I Gecko   : APZSampling at 502140.521111 -> sampleTime 502156.784183 15:1394.000366 3:0.000000
10-19 12:30:51.311 10448 10516 I Gecko   : APZSampling at 502157.455903 -> sampleTime 502173.790017 15:1419.033447 3:0.000000
10-19 12:30:51.328 10448 10516 I Gecko   : APZSampling at 502174.049236 -> sampleTime 502190.410485 15:1443.311401 3:0.000000
10-19 12:30:51.344 10448 10516 I Gecko   : APZSampling at 502190.728038 -> sampleTime 502207.060225 15:1466.114258 3:0.000000
10-19 12:30:51.362 10448 10516 I Gecko   : APZSampling at 502207.935330 -> sampleTime 502223.946371 15:1488.116821 3:0.000000
10-19 12:30:51.378 10448 10516 I Gecko   : APZSampling at 502224.599184 -> sampleTime 502240.374287 15:1509.573853 3:0.000000

(by all means send me the Try with the hacky delay to beat the race condition)

Comment 77

[Kartikaya Gupta (email:[e-mail])]

Just to be clear: the hardware vsync isn't stuttering here, since the "sampleTime" numbers are smooth. What's happening here is like this:

-> at t=~502106 hardware vsync ticks on the vsync thread, sends a message to compositor thread to do sampling for sampleTime=502123.765329
-> at t=502107.571423 the compositor thread handles that and does the sampling, computes scroll position y=1341.883057
-> sometime after that but before t=502123, compositor gets a paint message with the big image data which takes some time to process
-> at t=~502123 the screen updates, and shows the sampled content at scroll position y=1341.883057
-> at t=~502123 hardware vsync ticks on the vsync thread, sends a message to compositor thread to do sampling for sampleTime=502139.968714
-> at t=502133.884288 the compositor thread is finally done processing the big paint message and starts the new sampling, computes scroll position=1368.900635. But! I suspect this sampling step takes longer than 6ms to complete and so when the vsync at t=~502139 happens it still updates the screen with the old scroll position y=1341.883057 instead of the new 1341.883057. this results in the jank.

Comment 78

[Mark]

Ah, I see, I think.

I guess when I see jank as the first page scrolls away it's a similar reason - because there's a big paint to move the displayport away from its end stop?

So is this an inherent limitation of the power of my phone CPU? i.e. some paints are going to take too long. My phone is reasonably fast, a solid mid-ranger I would say.

Is it something that OMTP and/or WebRender is going to help with? Or maybe reducing the displayport size? Any tricks I can play?

Flinging is actually pretty good now, nearly up there with Chrome. But there is still this jank going on now and then, I wonder if there are any tricks. I am looking for *perfection* ;)

Comment 79

[Mark]

Sorry, me again

The debug info on layers.acceleration.draw-fps always shows zeros for the [Content] stuff on Fennec. Whereas on Desktop it shows plausible time values for frame-y stuff. I understand there's an architectural difference between the two browsers but is there a way to see how much time Fennec is spending building the frame?

Comment 80

[Mark]

And again (don't worry, knocking off for a beer in a second)

I tried the Try with the rogue jank patch on my very slow old phone and the difference in flings is really remarkable. Ignoring the pop in stuff (just on a normal fling on a "boring" web page) the unpatched Nightly janks like crazy on a fling. The patched Nightly is very very smooth. I would say Chrome is still smoother, but it's close.

So I think the difference on slow hardware is even more pronounced than on faster.

Comment 81

[Chris Lord [:cwiiis]]

Sorry if this is just noise - didn't there used to be two different modes of touch-event delivery on Android? 1, the default, synced with screen refresh, because that's what most single-threaded Android apps really want, and 2, 'raw', where they may get delivered way more frequently than 60Hz and not aligned with the screen refresh? If that's correct, sounds like Firefox uses 1 when really it wants 2(?)

Comment 82

[Kartikaya Gupta (email:[e-mail])]

(In reply to Mark from comment #78)
> I guess when I see jank as the first page scrolls away it's a similar reason
> - because there's a big paint to move the displayport away from its end stop?

Maybe? I'm not totally sure.

> So is this an inherent limitation of the power of my phone CPU? i.e. some
> paints are going to take too long. My phone is reasonably fast, a solid
> mid-ranger I would say.
> 
> Is it something that OMTP and/or WebRender is going to help with? Or maybe
> reducing the displayport size? Any tricks I can play?

Again, not sure. You can try reducing the displayport size and see if that helps. But more useful probably is to get a profile using the Gecko Profiler. However I'm not sure what the status is with respect to the profiler on Android, I haven't used it there in forever and I don't know what the steps are now to getting it set up for Android.

(In reply to Mark from comment #79)
> The debug info on layers.acceleration.draw-fps always shows zeros for the
> [Content] stuff on Fennec. Whereas on Desktop it shows plausible time values
> for frame-y stuff. I understand there's an architectural difference between
> the two browsers but is there a way to see how much time Fennec is spending
> building the frame?

Again the profiler is the best tool for this. But I wrote a patch to have the draw-fps overlay also display the timings for Fennec, it's in the try push below, which also includes a 2ms artificial delay on handling vsync in the compositor. Give that a spin and see if it helps any.

https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&revision=a6498b1aa50d11d0e3b7d72beaa3b898bc96940e

(In reply to Chris Lord [:cwiiis] from comment #81)
> Sorry if this is just noise - didn't there used to be two different modes of
> touch-event delivery on Android? 1, the default, synced with screen refresh,
> because that's what most single-threaded Android apps really want, and 2,
> 'raw', where they may get delivered way more frequently than 60Hz and not
> aligned with the screen refresh? If that's correct, sounds like Firefox uses
> 1 when really it wants 2(?)

I don't recall a setting that allows controlling this. AFAIK Android switched to (1) with JellyBean and it's been on ever since. I know that with Gonk we had to implement the vsync-aligned input resampling ourselves and I think we could turn it off if needed, but that was Gonk and is dead now. If you know of a way to do this in Android I'd be interested in hearing about it.

Comment 83

[Mark]

I think that Try build failed??

Comment 84

[Kartikaya Gupta (email:[e-mail])]

Sorry, that build didn't work. Here's a better one: https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&revision=5fa8c5ca4ea9a7cb29694b7cee3f383470aaad28

Comment 85

[Mark]

On my fast phone all looks pretty good but I only glanced at it

On my slower phone it's better, but I still see some drag scroll jank and duplicate scroll offsets. Extract from a drag scroll on first screenful. Not sure what it means. I'm sure you do :)

10-22 18:52:31.199  7620  7620 W GeckoNPZC: Received touch event y=771.46985 at t=11496921
10-22 18:52:31.200  7620  7620 I Gecko   : APZ untransformed 660 -> 693 using APZ offsets 29.500000 146.000000 146.000000 146.000000
10-22 18:52:31.200  7620  7741 I Gecko   : APZSampling at 918346.958452 -> sampleTime 918360.720952 6:162.500000 3:0.000000
10-22 18:52:31.215  7620  7620 W GeckoNPZC: Received touch event y=739.6769 at t=11496938
10-22 18:52:31.216  7620  7620 I Gecko   : APZ untransformed 628 -> 660 using APZ offsets 29.500000 162.500000 162.500000 162.500000
10-22 18:52:31.217  7620  7741 I Gecko   : APZSampling at 918363.740379 -> sampleTime 918377.922514 6:178.500000 3:0.000000
10-22 18:52:31.233  7620  7620 W GeckoNPZC: Received touch event y=707.13745 at t=11496954
10-22 18:52:31.233  7620  7741 I Gecko   : APZSampling at 918379.741161 -> sampleTime 918393.827202 6:178.500000 3:0.000000
10-22 18:52:31.234  7620  7620 I Gecko   : APZ untransformed 596 -> 628 using APZ offsets 29.500000 178.500000 178.500000 178.500000
10-22 18:52:31.248  7620  7620 W GeckoNPZC: Received touch event y=674.9958 at t=11496971
10-22 18:52:31.249  7620  7620 I Gecko   : APZ untransformed 563 -> 596 using APZ offsets 29.500000 194.500000 178.500000 194.500000
10-22 18:52:31.251  7620  7741 I Gecko   : APZSampling at 918397.270119 -> sampleTime 918410.861264 6:211.000000 3:0.000000
10-22 18:52:31.265  7620  7620 W GeckoNPZC: Received touch event y=642.0555 at t=11496987
10-22 18:52:31.266  7620  7620 I Gecko   : APZ untransformed 531 -> 563 using APZ offsets 29.500000 211.000000 211.000000 211.000000
10-22 18:52:31.266  7620  7741 I Gecko   : APZSampling at 918412.988869 -> sampleTime 918426.699337 6:227.000000 3:0.000000
10-22 18:52:31.282  7620  7741 I Gecko   : APZSampling at 918429.058140 -> sampleTime 918443.270431 6:227.000000 3:0.000000
10-22 18:52:31.283  7620  7620 W GeckoNPZC: Received touch event y=609.69226 at t=11497004
10-22 18:52:31.283  7620  7620 I Gecko   : APZ untransformed 498 -> 531 using APZ offsets 29.500000 227.000000 227.000000 227.000000
10-22 18:52:31.298  7620  7620 W GeckoNPZC: Received touch event y=577.396 at t=11497020
10-22 18:52:31.299  7620  7620 I Gecko   : APZ untransformed 466 -> 498 using APZ offsets 29.500000 243.500000 227.000000 243.500000
10-22 18:52:31.300  7620  7741 I Gecko   : APZSampling at 918446.762463 -> sampleTime 918459.819962 6:259.500000 3:0.000000

Comment 86

[Mark]

You put a 2 ms delay into the vsync firing. It might not be enough. I think the problem in comment 85 might simply be that the touch events can come in >2 ms late on my slow phone.

I went back to the old Try (with the overcompositing fixed, but without the 2 ms delay in vsync) and had a closer look at the timestamps on my old slow phone, as usual an extract from a couple of drag scrolls, first page of mozilla.org.

Most of the time the touch event comes in <1 ms but sometimes it can be 2 ms, maybe more than 2 ms? I haven't seen any 3 ms but I haven't looked that hard, I am getting number blind.

I don't see this on my faster phone, presumably the hardware can keep up better? Drag scrolling is buttery with the latest Try with the 2 ms delay.

[are you confused by all these Trys ;) hope not]



Examples below, again emphasizing these are last week's Try WITHOUT the 2 ms delay.

At 19:48:08.974 the APZSampling fires, but the touch event doesn't come in until 19:48:08.976 so 2 ms later, perhaps between 2 and 3 ms?

10-22 19:48:08.958 10171 10171 W GeckoNPZC: Received touch event y=705.16956 at t=14639589
10-22 19:48:08.958 10171 10171 I Gecko   : APZ untransformed 594 -> 671 using APZ offsets 0.000000 126.000000 92.500000 126.000000
10-22 19:48:08.959 10171 10266 I Gecko   : APZSampling at 24452.623637 -> sampleTime 24466.675147 6:164.500000 3:0.000000
10-22 19:48:08.974 10171 10266 I Gecko   : APZSampling at 24467.257179 -> sampleTime 24483.216865 6:164.500000 3:0.000000
10-22 19:48:08.976 10171 10171 W GeckoNPZC: Received touch event y=627.0586 at t=14639606
10-22 19:48:08.976 10171 10171 I Gecko   : APZ untransformed 516 -> 594 using APZ offsets 0.000000 164.500000 164.500000 164.500000
10-22 19:48:08.991 10171 10266 I Gecko   : APZSampling at 24483.681137 -> sampleTime 24499.642751 6:203.500000 3:0.000000
10-22 19:48:08.991 10171 10171 W GeckoNPZC: Received touch event y=552.9869 at t=14639622

Another example, touch event comes in at least 2 ms late

10-22 19:56:27.257 10171 10171 I Gecko   : APZ untransformed 685 -> 722 using APZ offsets 0.000000 160.500000 160.500000 160.500000
10-22 19:56:27.257 10171 10266 I Gecko   : APZSampling at 522750.504905 -> sampleTime 522764.425738 6:179.000000 3:0.000000
10-22 19:56:27.273 10171 10266 I Gecko   : APZSampling at 522765.732197 -> sampleTime 522780.957613 6:179.000000 3:0.000000
10-22 19:56:27.275 10171 10171 W GeckoNPZC: Received touch event y=756.93866 at t=15137903
10-22 19:56:27.279 10171 10171 I Gecko   : APZ untransformed 645 -> 645 using APZ offsets 0.000000 199.000000 179.000000 199.000000
10-22 19:56:27.288 10171 10171 W GeckoNPZC: Received touch event y=718.72784 at t=15137920

Comment 87

[Kartikaya Gupta (email:[e-mail])]

Yeah I agree with your analysis, the 2ms might not be enough on the slow phone. But it's good that on the fast phone this resolves the jank, it means we have identified the root cause (I hope) and can think about a proper fix. If you really want I can make another build with a configurable delay for you to try on the slow phone.

Comment 88

[Mark]

Don't bother, I think we can both see what's happening. It's a bit **** of Android that the delay between vsync and touch event can be a substantial fraction of a frame! The scrolling and flinging on my faster phone is glorious now, really nice. I will continue to try to break it, obviously, and feed back if necessary. And I will dig into the profiling/timing stuff a bit. Good luck with a proper fix. I think it'll be well worth the effort, scrolling is sooo good now.

Comment 89

[Kartikaya Gupta (email:[e-mail])]

I thought about different ways to fix this. The most obvious way is to bounce the vsync notification from the vsync thread through the controller (aka java UI) thread to the compositor thread instead of just directly posting to the compositor thread at [1]. While that would probably work fine for Fennec, I'm not so sure about GeckoView because the java UI thread might be busy with some work in the embedding application, and we don't really want to block vsync on that in all cases. Other potential solutions along similar lines would only minimize the chance of hitting the race condition and not eliminate it entirely. Finally I found a fix that I think is reasonable, on the Java side of things:

When we get the event from the OS, we record the timestamp of the event, for as long as it is "inflight" (i.e. while we give it to APZ). After that we clear the timestamp. In particular the timestamp being cleared doesn't block on gecko main thread handling of the event which can take arbitrarily long. It only blocks on APZ's handling which is fast. During this "inflight" time, if we get a vsync notification with a timestamp greater than that of the event, we wait until the event is done before dispatching that vsync. So in the common case where there is no input event inflight, the only performance penalty is grabbing a lock and doing an if condition. In the case where the input event is inflight, we delay vsync delivery by a bit, which reduces our available composition time but also ensures we get smoother scrolling. Conceptually this agrees with what Android is trying to do with it's Choreographer anyway, since it delivers events a few ms before vsync with the expectation that the handling will be done for vsync.

Here's a try push for you to try out: https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&revision=bcda5301ff30e1579f39cbe5f1bbf6f6070c8e09

[1] https://searchfox.org/mozilla-central/rev/eac6295c397133b7346822ad31867197e30d7e94/gfx/layers/ipc/CompositorVsyncScheduler.cpp#131

Comment 90

[Mark]

Hmm, I don't really see any improvement on my faster Sony. I haven't tried on my slower phone. Still fairly janky, moving to layout.frame_rate 60 still gives much smoother drag scrolling. I tried mozilla.org, arstechnica.com, bbc.com. Do you fancy doing a version with timestamp logging?

Comment 91

[Mark]

I think bug 1457702 might be a duplicate of this bug. Setting layout.frame_rate 60 mostly fixes bug 1457702, just like this bug.

Comment 92

[Mark]

I tried on my slower phone too. Same story. And I doubled checked I was using the correct Try version.

Comment 93

[Kartikaya Gupta (email:[e-mail])]

It might be that the event and vsync are arriving with the same timestamp. Hopefully that's all it is. Here's a build with logging to see what's going on: https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&selectedJob=209237671&revision=6066b57bc35ce0654bcc9478bd1f1dcbb627a5cd

I mostly care about the logging with the GeckoVsyncSource tag but it has the other logging from prior builds as well.

Comment 94

[Mark]

The Try from comment 93 (with the logging) is much smoother than the previous Try. In fact, it's butter smooth, really lovely, with hardware vsync. I did some double checking and I think I have all the right Trys going on and my vsync set properly. I don't understand.

Logging output from a typical drag on first screenful, hardware vsync:-

11-02 07:15:38.541 24766 24766 I GeckoVsyncSource: Event inflight: 30062716
11-02 07:15:38.541 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.557 24766 24766 I GeckoVsyncSource: Event inflight: 30062733
11-02 07:15:38.557 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30062738(from 30062738696860)
11-02 07:15:38.557 24766 24888 I GeckoVsyncSource: Vsync waiting for inflight event 30062733
11-02 07:15:38.557 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.573 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30062755(from 30062755395122)
11-02 07:15:38.574 24766 24766 I GeckoVsyncSource: Event inflight: 30062750
11-02 07:15:38.574 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.590 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30062772(from 30062772093416)
11-02 07:15:38.591 24766 24766 I GeckoVsyncSource: Event inflight: 30062767
11-02 07:15:38.591 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.607 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30062788(from 30062788792191)
11-02 07:15:38.607 24766 24766 I GeckoVsyncSource: Event inflight: 30062783
11-02 07:15:38.607 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.624 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30062805(from 30062805490745)
11-02 07:15:38.624 24766 24766 I GeckoVsyncSource: Event inflight: 30062800
11-02 07:15:38.624 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.640 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30062822(from 30062822189341)
11-02 07:15:38.640 24766 24766 I GeckoVsyncSource: Event inflight: 30062817
11-02 07:15:38.642 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.657 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30062838(from 30062838887705)
11-02 07:15:38.657 24766 24766 I GeckoVsyncSource: Event inflight: 30062833
11-02 07:15:38.658 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.673 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30062855(from 30062855585919)
11-02 07:15:38.673 24766 24766 I GeckoVsyncSource: Event inflight: 30062850
11-02 07:15:38.674 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.691 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30062872(from 30062872284397)
11-02 07:15:38.693 24766 24766 I GeckoVsyncSource: Event inflight: 30062867
11-02 07:15:38.693 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.707 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30062888(from 30062888982328)
11-02 07:15:38.707 24766 24766 I GeckoVsyncSource: Event inflight: 30062883
11-02 07:15:38.707 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.723 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30062905(from 30062905681140)
11-02 07:15:38.724 24766 24766 I GeckoVsyncSource: Event inflight: 30062900
11-02 07:15:38.724 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.740 24766 24766 I GeckoVsyncSource: Event inflight: 30062917
11-02 07:15:38.741 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30062922(from 30062922377596)
11-02 07:15:38.741 24766 24888 I GeckoVsyncSource: Vsync waiting for inflight event 30062917
11-02 07:15:38.741 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.757 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30062939(from 30062939076284)
11-02 07:15:38.757 24766 24766 I GeckoVsyncSource: Event inflight: 30062934
11-02 07:15:38.758 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.773 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30062955(from 30062955774877)
11-02 07:15:38.774 24766 24766 I GeckoVsyncSource: Event inflight: 30062950
11-02 07:15:38.775 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.791 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30062972(from 30062972472536)
11-02 07:15:38.791 24766 24766 I GeckoVsyncSource: Event inflight: 30062967
11-02 07:15:38.791 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.807 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30062989(from 30062989170999)
11-02 07:15:38.807 24766 24766 I GeckoVsyncSource: Event inflight: 30062984
11-02 07:15:38.808 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.824 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30063005(from 30063005869602)
11-02 07:15:38.824 24766 24766 I GeckoVsyncSource: Event inflight: 30063000
11-02 07:15:38.825 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.841 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30063022(from 30063022568232)
11-02 07:15:38.841 24766 24766 I GeckoVsyncSource: Event inflight: 30063017
11-02 07:15:38.841 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.857 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30063039(from 30063039266607)
11-02 07:15:38.857 24766 24766 I GeckoVsyncSource: Event inflight: 30063034
11-02 07:15:38.858 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.874 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30063055(from 30063055964826)
11-02 07:15:38.874 24766 24766 I GeckoVsyncSource: Event inflight: 30063050
11-02 07:15:38.875 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.891 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30063072(from 30063072663549)
11-02 07:15:38.892 24766 24766 I GeckoVsyncSource: Event inflight: 30063067
11-02 07:15:38.892 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.907 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30063089(from 30063089361826)
11-02 07:15:38.908 24766 24766 I GeckoVsyncSource: Event inflight: 30063084
11-02 07:15:38.908 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.924 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30063106(from 30063106059499)
11-02 07:15:38.924 24766 24766 I GeckoVsyncSource: Event inflight: 30063101
11-02 07:15:38.925 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.941 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30063122(from 30063122757661)
11-02 07:15:38.941 24766 24766 I GeckoVsyncSource: Event inflight: 30063117
11-02 07:15:38.941 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.957 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30063139(from 30063139456055)
11-02 07:15:38.958 24766 24766 I GeckoVsyncSource: Event inflight: 30063134
11-02 07:15:38.958 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.974 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30063156(from 30063156153809)
11-02 07:15:38.975 24766 24766 I GeckoVsyncSource: Event inflight: 30063151
11-02 07:15:38.976 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:38.991 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30063172(from 30063172852103)
11-02 07:15:38.991 24766 24766 I GeckoVsyncSource: Event inflight: 30063167
11-02 07:15:38.991 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:39.007 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30063189(from 30063189550406)
11-02 07:15:39.008 24766 24766 I GeckoVsyncSource: Event inflight: 30063184
11-02 07:15:39.009 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:39.024 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30063206(from 30063206248753)
11-02 07:15:39.025 24766 24766 I GeckoVsyncSource: Event inflight: 30063201
11-02 07:15:39.025 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:39.041 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30063222(from 30063222947167)
11-02 07:15:39.041 24766 24766 I GeckoVsyncSource: Event inflight: 30063217
11-02 07:15:39.042 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:39.057 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30063239(from 30063239645551)
11-02 07:15:39.058 24766 24766 I GeckoVsyncSource: Event inflight: 30063234
11-02 07:15:39.058 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:39.074 24766 24766 I GeckoVsyncSource: Event inflight: 30063251
11-02 07:15:39.075 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:39.076 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30063256(from 30063256343712)
11-02 07:15:39.091 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30063273(from 30063273041838)
11-02 07:15:39.091 24766 24766 I GeckoVsyncSource: Event inflight: 30063268
11-02 07:15:39.091 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:39.108 24766 24766 I GeckoVsyncSource: Event inflight: 30063284
11-02 07:15:39.108 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30063289(from 30063289740280)
11-02 07:15:39.108 24766 24888 I GeckoVsyncSource: Vsync waiting for inflight event 30063284
11-02 07:15:39.108 24766 24766 I GeckoVsyncSource: Event inflight: 0
11-02 07:15:39.124 24766 24888 I GeckoVsyncSource: Vsync timestamp: 30063306(from 30063306437565)
11-02 07:15:39.124 24766 24766 I GeckoVsyncSource: Event inflight: 30063301

Comment 95

[Kartikaya Gupta (email:[e-mail])]

Oh shoot, I accidentally left in the change from the previous hacky fix where I delayed the vsync handling by a fixed 2ms. That being said, the output you pasted above is basically what I was expecting to see, so I'm still not sure what's wrong here. New try push with the 2ms delay removed:

https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&revision=b695ecb95caa56d746ac66cd0b15b285420336b4

Please include full logging this time, I want to correlate the "waiting for inflight event" messages with the sampling stuff.

Comment 96

[Mark]

:) that explains it then

Latest Try build failed?

Comment 97

[Kartikaya Gupta (email:[e-mail])]

Whoops. https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&selectedJob=209370588&revision=243633fbd0beb9d4e7926d933191b651f633eacc

Comment 98

[Mark]

Same test:- fairly janky drag scroll on first screenful, hardware vsync, mozilla.org, faster Sony phone. Hope that's enough, I can give you more if you want it :)

11-02 15:15:07.393  5453  5604 I GeckoVsyncSource: Vsync timestamp: 32071515(from 32071515582090)
11-02 15:15:07.394  5453  5453 W GeckoNPZC: Received touch event y=434.11835 at t=32071510
11-02 15:15:07.394  5453  5604 I GeckoVsyncSource: Notifying vsync at 32071516
11-02 15:15:07.394  5453  5453 I GeckoVsyncSource: Event inflight: 32071510
11-02 15:15:07.394  5453  5453 I Gecko   : APZ untransformed 323 -> 334 using APZ offsets 110.500000 233.000000 233.000000 233.000000
11-02 15:15:07.394  5453  5600 I Gecko   : APZSampling at 41520.289984 -> sampleTime 41536.575036 6:238.500000 3:0.000000
11-02 15:15:07.394  5453  5453 I GeckoVsyncSource: Event inflight: 0
11-02 15:15:07.410  5453  5604 I GeckoVsyncSource: Vsync timestamp: 32071532(from 32071532277728)
11-02 15:15:07.410  5453  5453 W GeckoNPZC: Received touch event y=424.32062 at t=32071527
11-02 15:15:07.410  5453  5604 I GeckoVsyncSource: Notifying vsync at 32071533
11-02 15:15:07.410  5453  5453 I GeckoVsyncSource: Event inflight: 32071527
11-02 15:15:07.411  5453  5600 I Gecko   : APZSampling at 41537.194880 -> sampleTime 41553.415140 6:238.500000 3:0.000000
11-02 15:15:07.412  5453  5453 I Gecko   : APZ untransformed 313 -> 323 using APZ offsets 110.500000 238.500000 238.500000 238.500000
11-02 15:15:07.412  5453  5453 I GeckoVsyncSource: Event inflight: 0
11-02 15:15:07.427  5453  5604 I GeckoVsyncSource: Vsync timestamp: 32071548(from 32071548973583)
11-02 15:15:07.427  5453  5453 W GeckoNPZC: Received touch event y=414.24124 at t=32071543
11-02 15:15:07.427  5453  5604 I GeckoVsyncSource: Notifying vsync at 32071549
11-02 15:15:07.427  5453  5453 I GeckoVsyncSource: Event inflight: 32071543
11-02 15:15:07.428  5453  5453 I Gecko   : APZ untransformed 303 -> 313 using APZ offsets 110.500000 243.500000 238.500000 243.500000
11-02 15:15:07.428  5453  5453 I GeckoVsyncSource: Event inflight: 0
11-02 15:15:07.428  5453  5600 I Gecko   : APZSampling at 41553.949984 -> sampleTime 41570.155869 6:248.500000 3:0.000000
11-02 15:15:07.444  5453  5604 I GeckoVsyncSource: Vsync timestamp: 32071565(from 32071565669624)
11-02 15:15:07.444  5453  5453 W GeckoNPZC: Received touch event y=404.26852 at t=32071560
11-02 15:15:07.444  5453  5604 I GeckoVsyncSource: Notifying vsync at 32071566
11-02 15:15:07.444  5453  5453 I GeckoVsyncSource: Event inflight: 32071560
11-02 15:15:07.444  5453  5453 I Gecko   : APZ untransformed 293 -> 303 using APZ offsets 110.500000 248.500000 248.500000 248.500000
11-02 15:15:07.444  5453  5600 I Gecko   : APZSampling at 41570.569620 -> sampleTime 41586.858161 6:253.500000 3:0.000000
11-02 15:15:07.444  5453  5453 I GeckoVsyncSource: Event inflight: 0
11-02 15:15:07.460  5453  5604 I GeckoVsyncSource: Vsync timestamp: 32071582(from 32071582364611)
11-02 15:15:07.461  5453  5604 I GeckoVsyncSource: Notifying vsync at 32071583
11-02 15:15:07.461  5453  5453 W GeckoNPZC: Received touch event y=392.15524 at t=32071577
11-02 15:15:07.461  5453  5453 I GeckoVsyncSource: Event inflight: 32071577
11-02 15:15:07.461  5453  5453 I Gecko   : APZ untransformed 281 -> 293 using APZ offsets 110.500000 253.500000 253.500000 253.500000
11-02 15:15:07.461  5453  5453 I GeckoVsyncSource: Event inflight: 0
11-02 15:15:07.462  5453  5600 I Gecko   : APZSampling at 41587.797120 -> sampleTime 41603.502744 6:259.500000 3:0.000000
11-02 15:15:07.477  5453  5453 W GeckoNPZC: Received touch event y=380.11035 at t=32071594
11-02 15:15:07.477  5453  5453 I GeckoVsyncSource: Event inflight: 32071594
11-02 15:15:07.478  5453  5604 I GeckoVsyncSource: Vsync timestamp: 32071599(from 32071599060940)
11-02 15:15:07.478  5453  5604 I GeckoVsyncSource: Vsync waiting for inflight event 32071594
11-02 15:15:07.478  5453  5453 I Gecko   : APZ untransformed 269 -> 281 using APZ offsets 110.500000 259.500000 259.500000 259.500000
11-02 15:15:07.478  5453  5453 I GeckoVsyncSource: Event inflight: 0
11-02 15:15:07.479  5453  5604 I GeckoVsyncSource: Notifying vsync at 32071601
11-02 15:15:07.479  5453  5600 I Gecko   : APZSampling at 41605.397276 -> sampleTime 41621.616234 6:265.500000 3:0.000000
11-02 15:15:07.494  5453  5604 I GeckoVsyncSource: Vsync timestamp: 32071615(from 32071615756697)
11-02 15:15:07.494  5453  5453 W GeckoNPZC: Received touch event y=369.2026 at t=32071610
11-02 15:15:07.494  5453  5604 I GeckoVsyncSource: Notifying vsync at 32071616
11-02 15:15:07.494  5453  5453 I GeckoVsyncSource: Event inflight: 32071610
11-02 15:15:07.494  5453  5453 I Gecko   : APZ untransformed 258 -> 269 using APZ offsets 110.500000 265.500000 265.500000 265.500000
11-02 15:15:07.494  5453  5453 I GeckoVsyncSource: Event inflight: 0
11-02 15:15:07.495  5453  5600 I Gecko   : APZSampling at 41621.148943 -> sampleTime 41636.948942 6:271.000000 3:0.000000
11-02 15:15:07.510  5453  5604 I GeckoVsyncSource: Vsync timestamp: 32071632(from 32071632452416)
11-02 15:15:07.511  5453  5604 I GeckoVsyncSource: Notifying vsync at 32071633
11-02 15:15:07.511  5453  5600 I Gecko   : APZSampling at 41637.282328 -> sampleTime 41653.559931 6:271.000000 3:0.000000
11-02 15:15:07.511  5453  5453 W GeckoNPZC: Received touch event y=358.1359 at t=32071627
11-02 15:15:07.511  5453  5453 I GeckoVsyncSource: Event inflight: 32071627
11-02 15:15:07.512  5453  5453 I Gecko   : APZ untransformed 247 -> 258 using APZ offsets 110.500000 271.000000 271.000000 271.000000
11-02 15:15:07.512  5453  5453 I GeckoVsyncSource: Event inflight: 0
11-02 15:15:07.527  5453  5453 W GeckoNPZC: Received touch event y=346.14276 at t=32071644
11-02 15:15:07.528  5453  5453 I GeckoVsyncSource: Event inflight: 32071644
11-02 15:15:07.528  5453  5604 I GeckoVsyncSource: Vsync timestamp: 32071649(from 32071649148981)
11-02 15:15:07.528  5453  5604 I GeckoVsyncSource: Vsync waiting for inflight event 32071644
11-02 15:15:07.528  5453  5453 I Gecko   : APZ untransformed 235 -> 247 using APZ offsets 110.500000 276.500000 271.000000 276.500000
11-02 15:15:07.528  5453  5453 I GeckoVsyncSource: Event inflight: 0
11-02 15:15:07.529  5453  5604 I GeckoVsyncSource: Notifying vsync at 32071651
11-02 15:15:07.530  5453  5600 I Gecko   : APZSampling at 41655.960870 -> sampleTime 41671.867067 6:282.500000 3:0.000000
11-02 15:15:07.544  5453  5604 I GeckoVsyncSource: Vsync timestamp: 32071665(from 32071665845154)
11-02 15:15:07.544  5453  5604 I GeckoVsyncSource: Notifying vsync at 32071666
11-02 15:15:07.544  5453  5453 W GeckoNPZC: Received touch event y=334.13162 at t=32071660
11-02 15:15:07.544  5453  5453 I GeckoVsyncSource: Event inflight: 32071660
11-02 15:15:07.544  5453  5453 I Gecko   : APZ untransformed 223 -> 235 using APZ offsets 110.500000 282.500000 282.500000 282.500000
11-02 15:15:07.545  5453  5453 I GeckoVsyncSource: Event inflight: 0
11-02 15:15:07.545  5453  5600 I Gecko   : APZSampling at 41671.068474 -> sampleTime 41686.751598 6:288.500000 3:0.000000
11-02 15:15:07.561  5453  5604 I GeckoVsyncSource: Vsync timestamp: 32071682(from 32071682541890)
11-02 15:15:07.561  5453  5604 I GeckoVsyncSource: Notifying vsync at 32071683
11-02 15:15:07.561  5453  5600 I Gecko   : APZSampling at 41687.392953 -> sampleTime 41703.698681 6:288.500000 3:0.000000
11-02 15:15:07.561  5453  5453 W GeckoNPZC: Received touch event y=324.29413 at t=32071677
11-02 15:15:07.561  5453  5453 I GeckoVsyncSource: Event inflight: 32071677
11-02 15:15:07.562  5453  5453 I Gecko   : APZ untransformed 213 -> 223 using APZ offsets 110.500000 288.500000 288.500000 288.500000
11-02 15:15:07.562  5453  5453 I GeckoVsyncSource: Event inflight: 0
11-02 15:15:07.577  5453  5604 I GeckoVsyncSource: Vsync timestamp: 32071699(from 32071699237678)
11-02 15:15:07.577  5453  5604 I GeckoVsyncSource: Notifying vsync at 32071700
11-02 15:15:07.577  5453  5453 W GeckoNPZC: Received touch event y=315.29034 at t=32071694
11-02 15:15:07.578  5453  5453 I GeckoVsyncSource: Event inflight: 32071694
11-02 15:15:07.578  5453  5453 I Gecko   : APZ untransformed 204 -> 213 using APZ offsets 110.500000 293.500000 288.500000 293.500000
11-02 15:15:07.578  5453  5453 I GeckoVsyncSource: Event inflight: 0
11-02 15:15:07.578  5453  5600 I Gecko   : APZSampling at 41704.145245 -> sampleTime 41720.483942 6:298.000000 3:0.000000
11-02 15:15:07.594  5453  5604 I GeckoVsyncSource: Vsync timestamp: 32071715(from 32071715933345)
11-02 15:15:07.594  5453  5604 I GeckoVsyncSource: Notifying vsync at 32071716
11-02 15:15:07.594  5453  5453 W GeckoNPZC: Received touch event y=306.43726 at t=32071710
11-02 15:15:07.594  5453  5453 I GeckoVsyncSource: Event inflight: 32071710
11-02 15:15:07.594  5453  5453 I Gecko   : APZ untransformed 195 -> 204 using APZ offsets 110.500000 298.000000 298.000000 298.000000
11-02 15:15:07.594  5453  5600 I Gecko   : APZSampling at 41720.668734 -> sampleTime 41737.099202 6:302.500000 3:0.000000
11-02 15:15:07.595  5453  5453 I GeckoVsyncSource: Event inflight: 0

Comment 99

[Kartikaya Gupta (email:[e-mail])]

11-02 15:15:07.410  5453  5604 I GeckoVsyncSource: Vsync timestamp: 32071532(from 32071532277728)
11-02 15:15:07.410  5453  5453 W GeckoNPZC: Received touch event y=424.32062 at t=32071527

There's a problem right there: we are getting the vsync with a later timestamp (32071532) delivered to us before the touch event with the earlier timestamp (32071527). 5ms earlier in fact. WTF, Android? I'm not sure what to do about this now.

Comment 100

[Kartikaya Gupta (email:[e-mail])]

To be clear, the vsync is arriving at the correct time (the actual system clock is in the "notifying vsync" log line). It's the touch event that's delayed by 5ms, so we get it after we get the vsync tick.

Comment 101

[Kartikaya Gupta (email:[e-mail])]

Ah the timestamp on the event is the event resampling time from Android's input resampling algorithm. And I guess the race is because we're using two different Choreographers - the vsync has its own dedicated Looper/Choreographer while the input is coming on the java UI thread. So I'll have to try either using a single Choreographer for both things (i.e. make vsync use the Java UI thread one) or force an artificial delay on the vsync which is pretty hacky. I don't see any other options.

Comment 102

[Mark]

Naive suggestions

1. why not hold the touch event over to the next frame, i.e. add a 16 ms delay to the touch event? That would solve the problem but would introduce latency. I know people get very angry about more latency ... but there’s a bunch already plus drag slop.

2. instead of making the vsync use the Java UI thread as you are suggesting, could you not do it the other way round ie have a single Looper/Choreographer doing the vsync + touch event handling and sending the touch events off to UI and/or APZ? Then everything would stay in sync. (I presume the reason is:- it's insanely complicated!).

You don’t need to give detailed replies to these ... a simple “no” will suffice ;)


Tests on vsync delay

Some food for thought on the “delay” case if you want to go that way. I was worried that the delay might vary from device to device or might even be time varying (i.e. the vsync and touch events might roll past each other). But it doesn’t seem to be the case. So the delay might be a hack but I think it would be a highly effective hack.

I looked across my stable of half a dozen cheapish phones ranging from prehistoric Moto E1 up to my fairly current Xperia X Compact and the delay between vsync and touch event never seems to exceed 3 ms on the slowest phones and never seems to exceed 2 ms on my faster Xperia X Compact. I tried reboots etc to see if I could make that delay get bigger but apparently not.

When I use the build with the 2 ms delay I see dramatic improvement in drag scrolling on all my phones. On the faster Xperia X Compact scrolling is “perfect” with no jank either to my eye or seen in the logging (i.e. no duplicate scroll offsets). On my slower phones it’s dramatically improved but there is still the very occasional jank & duplicate scroll offset but it’s really only once or twice per screenful of vigorous drag. 

The only thing I haven’t tried is a phone with a high DPI display - they push a lot of pixels - perhaps you could check your phone?

So I think if you were to go down the delay route 2 ms would get you close, 3 ms would get “perfection" and you shouldn’t need anything too fancy because it’s not a hugely time varying delay (but you might want to monitor it with some kind of simple delay locked loop?). Not elegant, but the pay off could be worth it.


PS

I put the Oct 22 build with the overcompositing fix and the 2 ms vsync delay onto my prehistoric Moto E1 (Snapdragon 200, 1.2 GHz dual core). I turned on OMTP and the scrolling is actually really good and streets ahead of Chrome Beta on the same device. It made me LOL. Of course, Fennec page loading is excruciatingly slow but I know that’s fairly high up Mozilla’s To Do list ;)

Comment 103

[Kartikaya Gupta (email:[e-mail])]

(In reply to Mark from comment #102)
> 1. why not hold the touch event over to the next frame, i.e. add a 16 ms
> delay to the touch event? That would solve the problem but would introduce
> latency. I know people get very angry about more latency ... but there’s a
> bunch already plus drag slop.

It's an option, but I'd like to avoid the latency hit.

> 2. instead of making the vsync use the Java UI thread as you are suggesting,
> could you not do it the other way round ie have a single
> Looper/Choreographer doing the vsync + touch event handling and sending the
> touch events off to UI and/or APZ? Then everything would stay in sync. (I
> presume the reason is:- it's insanely complicated!).

Yeah, this is harder because we can decide which thread to receive vsync notifications on, but we can't decide which thread to get touch events on. Android always delivers them on the java UI thread.

But I talked with :snorp and he said that we don't need to be concerned about the embedding application blocking the java UI thread, so I'll just go with the solution that moves vsync delivery to the java UI thread, and see if that fixes the problem.

Comment 104

[Kartikaya Gupta (email:[e-mail])]

Try this: https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&revision=f03c791994bc55f9f4e85c680d42df57b9b3c65b

Comment 105

[Mark]

Nailed it. Brilliant. I tried on both my fast Sony, my dog slow Moto E1, and my intermediate BQ and drag scrolling is great. Better than using software vsync @ 60fps. Really good.

No issues so far - I'm sure I'll eventually find a nit to pick though :)

I looked at geckoview_example.apk, that looks great too. So this fix should help Focus too.

Thanks!

Comment 106

[Kartikaya Gupta (email:[e-mail])]

Attachment: Bug 1432019 - Move the vsync notifications to the java UI thread. r?snorp

This ensures that the vsync notifications don't race ahead of the touch
events, which can result in jank if the APZ sampling happens before the
touch events update the scroll position.

Comment 107

[Kartikaya Gupta (email:[e-mail])]

\o/ Thanks for all the testing! It's really insane how much effort you put into this :)

Comment 108

[Mark]

Way back you said
> I don't see how disabling paint skipping could possibly improve jankiness of scroll.
etc
I'd crawl a mile on broken glass to prove you wrong :)

Anyway it's fun, great way to learn about browsers.

Comment 109

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/4383166b5e24
Move the vsync notifications to the java UI thread. r=snorp

Comment 110

[Chris Peterson [:cpeterson]]

Kats, does this problem affect all Fennec/GeckoView users or only those that tweak the paint skipping prefs? Do you think we should uplift this fix to 64 Beta? Your patch is small but concurrency changes are always risky. :) We have a little over four weeks remaining in the 64 Beta cycle.

Comment 111

[Kartikaya Gupta (email:[e-mail])]

(In reply to Chris Peterson [:cpeterson] from comment #110)
> Kats, does this problem affect all Fennec/GeckoView users or only those that
> tweak the paint skipping prefs?

If affects all Fennec/GeckoView users.

> Do you think we should uplift this fix to 64
> Beta? Your patch is small but concurrency changes are always risky. :) We
> have a little over four weeks remaining in the 64 Beta cycle.

I agree that concurrency changes tend to be risky, I'd rather let it ride the trains given the relatively small amount of time we have left for 64 beta.

Comment 112

[Chris Peterson [:cpeterson]]

(In reply to Kartikaya Gupta (email:[e-mail]) from comment #111)
> I agree that concurrency changes tend to be risky, I'd rather let it ride
> the trains given the relatively small amount of time we have left for 64
> beta.

Sounds good. Setting status-firefox64=wontfix.

Comment 113

[Arthur Iakab [arthur_iakab]]

https://hg.mozilla.org/mozilla-central/rev/4383166b5e24

Comment 114

[Mark]

Fixed on Nightly 2018-11-08. 

Drags looking very smooth indeed, on both my fast Sony and slow BQ Aquaris  :)

Comment 115

[Kartikaya Gupta (email:[e-mail])]

Yay! Thanks for proving me wrong :)

Comment 116

[Liz Henry (:lizzard) (relman/hg->git project)]

Adding this to 65 beta release notes, "Improved performance: Scrolling is faster and more responsive"

Comment 117

[James Willcox (:snorp) ([e-mail]) (he/him)]

(In reply to Liz Henry (:lizzard) (needinfo? me) from comment #116)
> Adding this to 65 beta release notes, "Improved performance: Scrolling is
> faster and more responsive"

"...and this time we really mean it"