Closed Bug 1578042 Opened 1 year ago Closed 2 months ago

Skipped frame count is inaccurate, at least on non-WebRender macOS: We're dropping *more* frames than we think we are

Categories

(Core :: Audio/Video: Playback, defect, P3)

All
macOS
defect

Tracking

()

RESOLVED FIXED
mozilla80
Tracking Status
firefox80 --- fixed

People

(Reporter: mstange, Assigned: mstange)

References

Details

Attachments

(4 files, 5 obsolete files)

47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review

On my machine, if I play a 60FPS YouTube video such as https://www.youtube.com/watch?v=8PmM6SUn7Es in full screen mode, and have the FPS overlay enabled (layers.acceleration.draw-fps), the FPS overlay hovers around 52FPS. This must mean that about 8 video frames do not make it to the screen, each second. But the dropped frame count in YouTube's "Stats for nerds" overlay does not go up.

Here's a profile: https://perfht.ml/34eK9UH

You can see plenty of "NoCompositorScreenshot because nothing changed" markers: Those are frames where the composite was aborted because the image layer's image index hasn't changed since the last composite.
But there are no corresponding "Video frames dropped" markers.

Please note that there is also an extension called devtools-media-panel which gives you way more debug information about dropped frames in various stages. Maybe that helps to figure out which code is responsible for the frame drops.

:drno, do you know who should look at this?

Flags: needinfo?(drno)

Probably a dupe of bug 1579127. Markus, what is the refresh rate of your screen? I assume it's lower than 60fps, maybe 30fps?

Flags: needinfo?(drno) → needinfo?(mstange)

Markus does it work for you now? As such marking as a dupe?

Still need to test.

This will probably be important for the ongoing video quality work.

Priority: -- → P3

This is still happening both with and without WebRender.

Profile with WebRender: https://share.firefox.dev/3ePwBUs

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #3)

Probably a dupe of bug 1579127. Markus, what is the refresh rate of your screen? I assume it's lower than 60fps, maybe 30fps?

No, my screen refresh rate is also 60fps. And the problem is still occurring even after bug 1579127 got fixed.

Flags: needinfo?(mstange.moz)

I looked into this a bit. There are two reasons why this loop in ImageComposite::ChooseImageIndex does not record dropped frames for me on the VP9 60fps kurzgesagt YouTube videos:

  1. The timestamps on the TimedImages seem to increase by integer milliseconds only. So for some frames, it increases by 16.0ms, and for the others by 17.0ms. Since the target frame delta is 16.6667ms, this means that the check in ImageComposite::IsImagesUpdateRateFasterThanCompositedRate never considers 16.0ms images as "dropped".

  2. And even if a 17.0ms frame is dropped, mLastChosenImageIndex does not increase by more than one because the old frame was already removed from mImages. Here's an example:

    • mLastFrameID is 1251
    • mLastChosenImageIndex is 0
    • mImages[0].mFrameID is 1252 (!!)
    • mImages[1].mFrameID is 1253
    • result is 1

    So the current frame ID goes up by 2, but mLastChosenImageIndex goes only up by 1, so the dropped frame check misses the drop.

I'll try to find out why remove the current frame from mImages when it's still in use.

Assignee: nobody → mstange.moz
Status: NEW → ASSIGNED

(In reply to Markus Stange [:mstange] from comment #8)

I'll try to find out why remove the current frame from mImages when it's still in use.

This is done in the video sink because that frame is already in the past.

In order to address the second point, I think mLastChosenImageIndex needs to be a Maybe<>, in order to have a way to express that "none of the images in mImages have ever been chosen".

jya, you wrote the code in question, and I'm trying to understand it completely. One question that I still have is how the "offscreen video" mechanism is supposed to work. Matt asked a question about it in https://phabricator.services.mozilla.com/D2176#46559 but I don't think you addressed it - specifically the "and notify that we dropped 40 frames" part. Can you take a look at the question and answer it here?

Furthermore, there is a third issue why we might miss frame skips: ChooseImageIndex is sometimes called outside of a composition (for example during SetDisplayList in WR), and this code considers a frame as presented once it's been chosen. But frames that are chosen outside of a composition may never be presented.

Flags: needinfo?(jyavenard)

My hunch is that the answer is: "we don't report dropped frames for offscreen videos that move back onscreen because we don't detect dropped frames for onscreen videos properly either". Really, ChooseImageIndex and SetImages have no way to know why ChooseImageIndex was never called for a given frame; it could be because the video isn't shown or because the composite was delayed, and there's no way to detect the difference. And we do want to report dropped frames for delayed composites.

And more importantly, that means that once we fix this code to properly detect dropped frames, then we will also report dropped frames for offscreen videos once they come back onscreen.

This also adjusts the time delta check to use floored milliseconds.
In 60fps WebM videos, the video frame durations are 16.0, 17.0, 17.0, 16.0, 17.0, 17.0, ...
so we need to consider frames with 16.0ms as displayable even when the target
frame duration is 16.67ms, otherwise we gloss over one third of the frames when
counting potentially dropped frames.

Depends on D82634

Here's a profile with this patch: https://share.firefox.dev/2ZLgKQp
This profile is of playing test 20 ("VP9.1080p60@1X") on https://yttest.prod.mozaws.net/2019/main.html?test_type=playbackperf-test .

The test is now reporting 80-130 dropped frames rather than 1-10 on my machine.

(In reply to Markus Stange [:mstange] from comment #9)

(In reply to Markus Stange [:mstange] from comment #8)

I'll try to find out why remove the current frame from mImages when it's still in use.

This is done in the video sink because that frame is already in the past.

In order to address the second point, I think mLastChosenImageIndex needs to be a Maybe<>, in order to have a way to express that "none of the images in mImages have ever been chosen".

jya, you wrote the code in question, and I'm trying to understand it completely. One question that I still have is how the "offscreen video" mechanism is supposed to work. Matt asked a question about it in https://phabricator.services.mozilla.com/D2176#46559 but I don't think you addressed it - specifically the "and notify that we dropped 40 frames" part. Can you take a look at the question and answer it here?

TBH, I don't fully recall either.
My code only modified the logic that measured if a frames got dropped or not; it didn't modify the behaviour on which frame was supposed to be return at a given time

It attempted to determine if a frame got dropped by looking at the frameID and we detected a gap since the last time it was called it, surely those frames had been dropped.
It avoided the issue with non-painted frames because if the video was hidden and stayed hidden because when the frames got in and out of the queue: the code wasn't called, so we didn't account for them as dropped.
When the video would switch back in view, yes unnecessarily frames would be reported as dropped even though they weren't

The rationale was that it was better to report more dropped frame than we actually had than none at all. This was mostly relevant on the Amazon Fire's Tablet where Twitch playback that heavily relies on the dropped frame value to adjust the resolution was bad. We didn't reported any dropped frames and so they kept feeding us 1080p on a device that couldn't play it.

The core issue is that we don't know on why a frame wasn't composited. That information isn't available at present, and really it's something we need.
Unless we know, the amount of dropped frames is going to be an approximation anyway.

There's another issue we must avoid which Chrome suffers (or at least used to suffer from).
If you display a 60fps on a 30fps screen ; will you report 50% of the frames being dropped? Or 60Hz on a 50Hz screen (common in PAL countries)
Chrome at some stage did.

It seems that with those changes we would too. I don't think we should.
Frames dropped is a way to determine the inability of the machine to render content smoothly, as-in it's too slow.
I still want to watch 1080p content @ 60Hz on my 50Hz screen, because it certainly looks nicer than 720p@30Hz which will be the next resolution down with YouTube.

Flags: needinfo?(jyavenard)

This also makes it so that UpdateBias for non-WebRender is only called when the
video frame changes. This mirrors the recent change that we made for WebRender
in bug 1652181. Non-WebRender only calls UpdateCompositedFrame when it actually
draws the video onto the screen, so when the video is the only thing that was
updating, the new behavior is equivalent. But the new behavior makes more sense
if you have a 30fps video and a 60fps animation running on a 60fps screen at the
same time - now the bias won't be accidentally reset every other frame.

Depends on D82634

We also now return 0 rather than -1 from the first call to ChooseImageIndex
outside of a composition, so that static images (like canvases) default to
the correct initial frame. We don't call ChooseImageIndex for them again once
we composite them.
This is different from non-WebRender, which would call ChooseImageIndex on
canvas layers during every composition.

This introduces a behavior difference for static images when WebRender is enabled:
Those images will no longer update mLastFrameID, because UpdateCompositedFrame
will not be called during a composition for them.

Depends on D83459

This ID is different from the IDs we already have:

  • It is different from VsyncId because it doesn't skip numbers when composites
    are delayed.
  • It is different from RenderedFrameId because it also increases for no-op
    composites.
  • It is different from transaction IDs and epochs because it doesn't care about
    the content side, it just looks at compositing.

It is currently not implemented for non-WR. In non-WR the video frame drop
detection wouldn't properly work anyway, because UpdateCompositedFrame is not
called on every composite for non-WR.

Depends on D82635

This currently only works for WebRender. In non-WR, no frame drops are reported.

There are two reasons why it doesn't work for non-WR:

  • Non-WR currently does not increment the composition opportunity ID.
  • In non-WR, UpdateCompositedFrame is only called for videos when they are
    drawn. But this detection relies on it being called on every composite, if
    the video is part of the on-screen scene. (WR does that.)

To make this detection work for non-WR as well, we would need to address both
of those points. The latter point is somewhat tricky because non-WR calls
ChooseImageIndex many times throughout a composite, and we would need to choose
a point in the composite at which to "lock in" the image for that composite and
cache the image index on the ImageHost somewhere, and then also find a way to
reset that locked-in index in the next composite. I haven't come up with a way
to do that and I do not know if it is worth the effort.

Depends on D83462

Here's a profile that was obtained with the updated patch set: https://share.firefox.dev/3gZAlmO
It's of a 60fps YouTube video, with two "breaks": In the first break it's scrolled offscreen, and in the second break I activated a different tab.
We don't count any dropped frames during the breaks.
And we count all dropped frames correctly while the video is onscreen, even if there's a smattering of SetDisplayList calls at the same time (which also call ChooseImageIndex, but outside of a composite).

Attachment #9163407 - Attachment description: Bug 1578042 - Correctly indicate that we're not in a composition during SetDisplayList or during empty transactions, by setting a null composition timestamp, and don't call UpdateCompositedFrame outside of a composition. r=jya → Bug 1578042 - Don't call UpdateCompositedFrame outside of a composition. r=jya
Pushed by mstange@themasta.com:
https://hg.mozilla.org/integration/autoland/rev/b0d63daa5d60
Update mLastFrameID in a new method UpdateCompositedFrame. r=jya,nical
https://hg.mozilla.org/integration/autoland/rev/0306fe17b5aa
Move more logic into UpdateCompositedFrame. r=jya,nical
https://hg.mozilla.org/integration/autoland/rev/035199ba3d5a
Don't call UpdateCompositedFrame outside of a composition. r=jya,nical
https://hg.mozilla.org/integration/autoland/rev/0e658297a2ba
Improve dropped frames reporting for videos, by counting all frames in mImages that were never composited. r=jya,nical
https://hg.mozilla.org/integration/autoland/rev/e26e1db6309b
Add a CompositionOpportunityId counter and implement it for WebRender. r=nical
https://hg.mozilla.org/integration/autoland/rev/94159598ab2a
Propagate CompositionOpportunityId to ImageComposite. r=jya,nical
https://hg.mozilla.org/integration/autoland/rev/ff727e9821be
Ignore skipped frames when the video was offscreen. r=jya,nical

I've reported the insufficient mach try auto jobs in #test-selection.

Flags: needinfo?(mstange.moz)

(In reply to Markus Stange [:mstange] from comment #25)

I've reported the insufficient mach try auto jobs in #test-selection.

The test actually run on your try push (https://treeherder.mozilla.org/#/jobs?repo=try&revision=66d23b5b62227493e911a73730766eb5ec21cd3f&test_paths=devtools%2Fclient%2Faboutdebugging%2Ftest%2Fbrowser%2F&selectedTaskRun=RAjQK4_pRtO9yF3g1Gb9oA.0), but it didn't fail:

[task 2020-07-14T07:34:30.936Z] 07:34:30 INFO - TEST-START | devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_devtoolstoolbox_performance.js
[task 2020-07-14T07:34:50.229Z] 07:34:50 INFO - TEST-OK | devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_devtoolstoolbox_performance.js | took 19305ms

Maybe it is actually an intermittent issue? Or maybe it depends on the order of tests?

Thanks for checking! It is possible that I made a change after the try push that broke things. I will check.

Actually I'll try implementing the new frame drop counting code for non-WebRender as well. At the moment, these numbers are recorded by the opt-raptor-youtube-playback-firefox-e10s ytp job on treeherder (example graph), and I don't want to lose coverage while this test only runs on non-WebRender.

Depends on: 1653679

Comment on attachment 9162037 [details]
Bug 1578042 - Update mLastFrameID in a new method UpdateCompositedFrame. r=jya

Revision D82634 was moved to bug 1653679. Setting attachment 9162037 [details] to obsolete.

Attachment #9162037 - Attachment is obsolete: true

Comment on attachment 9163406 [details]
Bug 1578042 - Move more logic into UpdateCompositedFrame. r=jya

Revision D83459 was moved to bug 1653679. Setting attachment 9163406 [details] to obsolete.

Attachment #9163406 - Attachment is obsolete: true

Comment on attachment 9163407 [details]
Bug 1578042 - Don't call UpdateCompositedFrame outside of a composition. r=jya

Revision D83460 was moved to bug 1653679. Setting attachment 9163407 [details] to obsolete.

Attachment #9163407 - Attachment is obsolete: true

Comment on attachment 9163408 [details]
Bug 1578042 - Add a CompositionOpportunityId counter and implement it for WebRender. r=jya,nical

Revision D83461 was moved to bug 1653679. Setting attachment 9163408 [details] to obsolete.

Attachment #9163408 - Attachment is obsolete: true

Comment on attachment 9163409 [details]
Bug 1578042 - Propagate CompositionOpportunityId to ImageComposite. r=jya

Revision D83462 was moved to bug 1653679. Setting attachment 9163409 [details] to obsolete.

Attachment #9163409 - Attachment is obsolete: true
Attachment #9164522 - Attachment description: Bug 1578042 - Call UpdateCompositedFrame from ChooseImageIndex so that it works for non-WebRender too. r=nical → Bug 1578042 - Call UpdateCompositedFrame from ChooseImageIndex so that the frame drop detection works for non-WebRender too. r=nical

I got this wrong when I added non-WebRender support in the patch that added
the CompositionOpportunityId counter. I forgot that EndTransaction is not only
called when we composite, but also, who would have thought, when we process a
transaction.
We only want to increment mCompositionOpportunityId when we're actually about
to composite.

Depends on D83463

Pushed by mstange@themasta.com:
https://hg.mozilla.org/integration/autoland/rev/57f65280709f
Improve dropped frames reporting for videos, by counting all frames in mImages that were never composited. r=jya,nical
https://hg.mozilla.org/integration/autoland/rev/3fbf9c0203dd
Ignore skipped frames when the video was offscreen. r=jya,nical
https://hg.mozilla.org/integration/autoland/rev/e32e69b9bdc4
Move mCompositionOpportunityId incrementing from EndTransaction to UpdateAndRender. r=nical
https://hg.mozilla.org/integration/autoland/rev/24d56f3c7678
Call UpdateCompositedFrame from ChooseImageIndex so that the frame drop detection works for non-WebRender too. r=nical
Duplicate of this bug: 1549720

Backed out 4 changesets (bug 1578042) for test_memory_usage.py crash

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&group_state=expanded&searchStr=windows%2C7%2Cshippable%2Copt%2Care%2Cwe%2Cslim%2Cyet%2Ctests%2Cby%2Ctaskcluster%2Ctest-windows7-32-shippable%2Fopt-awsy-tp6-e10s%2Csy-tp6&fromchange=9a37a0e7de35daa6572a1499556a9e814cff7bc8&tochange=bd8f0e3a63c466f951cebfab14023f8751ee845c&selectedTaskRun=AF6THK0wT7qj5jY7R81JCg.0

Backout link: https://hg.mozilla.org/integration/autoland/rev/bd8f0e3a63c466f951cebfab14023f8751ee845c

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=310451020&repo=autoland&lineNumber=1113

...
[task 2020-07-20T21:40:32.060Z] 21:40:32     INFO - loading https://yandex.ru/search/?text=barack%20obama&lr=10115
[task 2020-07-20T21:40:34.990Z] 21:40:34     INFO - loaded!
[task 2020-07-20T21:40:50.000Z] 21:40:50     INFO - starting checkpoint TabsOpen...
[task 2020-07-20T21:40:50.697Z] 21:40:50     INFO - checkpoint created, stored in Z:\\task_1595279336\\build\\tests\\results\\memory-report-TabsOpen-0.json.gz
[task 2020-07-20T21:41:20.705Z] 21:41:20     INFO - starting checkpoint TabsOpenSettled...
[task 2020-07-20T21:41:21.372Z] 21:41:21     INFO - checkpoint created, stored in Z:\\task_1595279336\\build\\tests\\results\\memory-report-TabsOpenSettled-0.json.gz
[task 2020-07-20T21:41:21.372Z] 21:41:21     INFO - starting gc...
[task 2020-07-20T21:41:21.687Z] 21:41:21     INFO - gc done!
[task 2020-07-20T21:41:21.687Z] 21:41:21     INFO - starting checkpoint TabsOpenForceGC...
[task 2020-07-20T21:41:23.359Z] 21:41:23     INFO - checkpoint created, stored in Z:\\task_1595279336\\build\\tests\\results\\memory-report-TabsOpenForceGC-0.json.gz
[task 2020-07-20T21:41:23.361Z] 21:41:23     INFO - closing window: 40
[task 2020-07-20T21:41:24.127Z] 21:41:24     INFO - closing window: 42
[task 2020-07-20T21:41:24.209Z] 21:41:24     INFO - closing window: 44
[task 2020-07-20T21:41:24.324Z] 21:41:24     INFO - closing window: 46
[task 2020-07-20T21:41:24.939Z] 21:41:24     INFO - mozcrash Downloading symbols from: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/aJs0x0R-RK-16ZXjV2Qumg/artifacts/public/build/target.crashreporter-symbols.zip
[task 2020-07-20T21:41:29.785Z] 21:41:29     INFO - mozcrash Copy/paste: Z:/task_1595279336/fetches\minidump_stackwalk\minidump_stackwalk.exe c:\users\task_1595279336\appdata\local\temp\tmpkzxpqb.profile\minidumps\9a3c7046-3802-4337-936f-2538b3d4b397.dmp c:\users\task_1595279336\appdata\local\temp\tmpcfn0q8
[task 2020-07-20T21:41:42.855Z] 21:41:42     INFO - mozcrash Saved minidump as Z:\task_1595279336\build\blobber_upload_dir\9a3c7046-3802-4337-936f-2538b3d4b397.dmp
[task 2020-07-20T21:41:42.858Z] 21:41:42     INFO - mozcrash Saved app info as Z:\task_1595279336\build\blobber_upload_dir\9a3c7046-3802-4337-936f-2538b3d4b397.extra
[task 2020-07-20T21:41:42.966Z] 21:41:42     INFO - PROCESS-CRASH | awsy/test_memory_usage.py TestMemoryUsage.test_open_tabs | application crashed [@ InvalidArrayIndex_CRASH(unsigned int, unsigned int)]
[task 2020-07-20T21:41:42.966Z] 21:41:42     INFO - Mozilla crash reason: ElementAt(aIndex = 0, aLength = 0)
[task 2020-07-20T21:41:42.967Z] 21:41:42     INFO - Crash dump filename: c:\users\task_1595279336\appdata\local\temp\tmpkzxpqb.profile\minidumps\9a3c7046-3802-4337-936f-2538b3d4b397.dmp
[task 2020-07-20T21:41:42.967Z] 21:41:42     INFO - Operating system: Windows NT
[task 2020-07-20T21:41:42.967Z] 21:41:42     INFO -                   6.1.7601 Service Pack 1
[task 2020-07-20T21:41:42.967Z] 21:41:42     INFO - CPU: x86
[task 2020-07-20T21:41:42.967Z] 21:41:42     INFO -      GenuineIntel family 6 model 63 stepping 2
[task 2020-07-20T21:41:42.967Z] 21:41:42     INFO -      8 CPUs
[task 2020-07-20T21:41:42.967Z] 21:41:42     INFO - 
[task 2020-07-20T21:41:42.967Z] 21:41:42     INFO - GPU: UNKNOWN
[task 2020-07-20T21:41:42.967Z] 21:41:42     INFO - 
[task 2020-07-20T21:41:42.967Z] 21:41:42     INFO - Crash reason:  EXCEPTION_BREAKPOINT
[task 2020-07-20T21:41:42.967Z] 21:41:42     INFO - Crash address: 0x53074251
[task 2020-07-20T21:41:42.967Z] 21:41:42     INFO - Process uptime: 492 seconds
[task 2020-07-20T21:41:42.967Z] 21:41:42     INFO - 
[task 2020-07-20T21:41:42.967Z] 21:41:42     INFO - Thread 27 (crashed)
[task 2020-07-20T21:41:42.967Z] 21:41:42     INFO -  0  xul.dll!InvalidArrayIndex_CRASH(unsigned int, unsigned int) [nsTArray.cpp:626dd9d4a4fbc4b0c9fd7eca639ff2cc01046579 : 27 + 0x23]
[task 2020-07-20T21:41:42.967Z] 21:41:42     INFO -     eip = 0x53074251   esp = 0x0c75f0d0   ebp = 0x0c75f0d0   ebx = 0x00000000
[task 2020-07-20T21:41:42.967Z] 21:41:42     INFO -     esi = 0x263d9440   edi = 0x22821788   eax = 0x6ad18d1c   ecx = 0x0000001d
[task 2020-07-20T21:41:42.967Z] 21:41:42     INFO -     edx = 0x00000029   efl = 0x00000212
[task 2020-07-20T21:41:42.967Z] 21:41:42     INFO -     Found by: given as instruction pointer in context
[task 2020-07-20T21:41:42.968Z] 21:41:42     INFO -  1  xul.dll!mozilla::layers::ImageComposite::CountSkippedFrames(mozilla::layers::ImageComposite::TimedImage const*) [ImageComposite.cpp:626dd9d4a4fbc4b0c9fd7eca639ff2cc01046579 : 305 + 0x1c]
[task 2020-07-20T21:41:42.968Z] 21:41:42     INFO -     eip = 0x53bc139e   esp = 0x0c75f0d8   ebp = 0x0c75f13c
[task 2020-07-20T21:41:42.968Z] 21:41:42     INFO -     Found by: call frame info
[task 2020-07-20T21:41:42.968Z] 21:41:42     INFO -  2  xul.dll!mozilla::layers::ImageComposite::SetImages(nsTArray<mozilla::layers::ImageComposite::TimedImage>&&) [ImageComposite.cpp:626dd9d4a4fbc4b0c9fd7eca639ff2cc01046579 : 149 + 0x7]
[task 2020-07-20T21:41:42.968Z] 21:41:42     INFO -     eip = 0x53bc0f29   esp = 0x0c75f144   ebp = 0x0c75f154   ebx = 0x22b7aac0
[task 2020-07-20T21:41:42.968Z] 21:41:42     INFO -     esi = 0x263d9440   edi = 0x0c75f18c
[task 2020-07-20T21:41:42.968Z] 21:41:42     INFO -     Found by: call frame info
[task 2020-07-20T21:41:42.968Z] 21:41:42     INFO -  3  xul.dll!mozilla::layers::ImageHost::UseTextureHost(nsTArray<mozilla::layers::CompositableHost::TimedTexture> const&) [ImageHost.cpp:626dd9d4a4fbc4b0c9fd7eca639ff2cc01046579 : 64 + 0x10]
[task 2020-07-20T21:41:42.968Z] 21:41:42     INFO -     eip = 0x53bc1693   esp = 0x0c75f15c   ebp = 0x0c75f1c4   esi = 0x263d9400
[task 2020-07-20T21:41:42.968Z] 21:41:42     INFO -     edi = 0x00000078
[task 2020-07-20T21:41:42.968Z] 21:41:42     INFO -     Found by: call frame info
[task 2020-07-20T21:41:42.968Z] 21:41:42     INFO -  4  xul.dll!mozilla::layers::CompositableParentManager::ReceiveCompositableUpdate(mozilla::layers::CompositableOperationDetail const&, mozilla::NotNull<mozilla::layers::CompositableHost *>) [CompositableTransactionParent.cpp:626dd9d4a4fbc4b0c9fd7eca639ff2cc01046579 : 177 + 0xd]
[task 2020-07-20T21:41:42.968Z] 21:41:42     INFO -     eip = 0x53bec77c   esp = 0x0c75f1cc   ebp = 0x0c75f310   ebx = 0x0c75f250
[task 2020-07-20T21:41:42.968Z] 21:41:42     INFO -     esi = 0x00000080   edi = 0x127fb700
[task 2020-07-20T21:41:42.968Z] 21:41:42     INFO -     Found by: call frame info
[task 2020-07-20T21:41:42.968Z] 21:41:42     INFO -  5  xul.dll!mozilla::layers::ImageBridgeParent::RecvUpdate(nsTArray<mozilla::layers::CompositableOperation>&&, nsTArray<mozilla::layers::OpDestroy>&&, unsigned long long const&) [ImageBridgeParent.cpp:626dd9d4a4fbc4b0c9fd7eca639ff2cc01046579 : 198 + 0x1e]
[task 2020-07-20T21:41:42.968Z] 21:41:42     INFO -     eip = 0x53c0b5cf   esp = 0x0c75f318   ebp = 0x0c75f388   ebx = 0x0c75f320
[task 2020-07-20T21:41:42.968Z] 21:41:42     INFO -     esi = 0x0c75f320   edi = 0x21b04a10
[task 2020-07-20T21:41:42.968Z] 21:41:42     INFO -     Found by: call frame info
[task 2020-07-20T21:41:42.968Z] 21:41:42     INFO -  6  xul.dll!mozilla::layers::PImageBridgeParent::OnMessageReceived(IPC::Message const&) [PImageBridgeParent.cpp: : 377 + 0x1b]
[task 2020-07-20T21:41:42.969Z] 21:41:42     INFO -     eip = 0x5362445e   esp = 0x0c75f390   ebp = 0x0c75f4a4   ebx = 0x13082c48
[task 2020-07-20T21:41:42.969Z] 21:41:42     INFO -     esi = 0x0f7347d0   edi = 0x0c75f428
[task 2020-07-20T21:41:42.969Z] 21:41:42     INFO -     Found by: call frame info
[task 2020-07-20T21:41:42.969Z] 21:41:42     INFO -  7  xul.dll!mozilla::ipc::MessageChannel::DispatchMessage(IPC::Message&&) [MessageChannel.cpp:626dd9d4a4fbc4b0c9fd7eca639ff2cc01046579 : 2074 + 0x70]
[task 2020-07-20T21:41:42.969Z] 21:41:42     INFO -     eip = 0x5352be14   esp = 0x0c75f4ac   ebp = 0x0c75f724   ebx = 0x0f734848
[task 2020-07-20T21:41:42.969Z] 21:41:42     INFO -     esi = 0x0c75f4b0   edi = 0x00000001
[task 2020-07-20T21:41:42.969Z] 21:41:42     INFO -     Found by: call frame info
[task 2020-07-20T21:41:42.969Z] 21:41:42     INFO -  8  xul.dll!mozilla::ipc::MessageChannel::MessageTask::Run() [MessageChannel.cpp:626dd9d4a4fbc4b0c9fd7eca639ff2cc01046579 : 1953 + 0xc3]
[task 2020-07-20T21:41:42.969Z] 21:41:42     INFO -     eip = 0x5352cc8e   esp = 0x0c75f72c   ebp = 0x0c75f754   ebx = 0x21687eb0
[task 2020-07-20T21:41:42.969Z] 21:41:42     INFO -     esi = 0x13082c40   edi = 0x13082c10
[task 2020-07-20T21:41:42.969Z] 21:41:42     INFO -     Found by: call frame info
[task 2020-07-20T21:41:42.969Z] 21:41:42     INFO -  9  xul.dll!nsThread::ProcessNextEvent(bool, bool*) [nsThread.cpp:626dd9d4a4fbc4b0c9fd7eca639ff2cc01046579 : 1234 + 0x6]
[task 2020-07-20T21:41:42.969Z] 21:41:42     INFO -     eip = 0x5286c1fa   esp = 0x0c75f75c   ebp = 0x0c75fcec   ebx = 0xffffffff
[task 2020-07-20T21:41:42.969Z] 21:41:42     INFO -     esi = 0x00000000   edi = 0x00863ec0
[task 2020-07-20T21:41:42.969Z] 21:41:42     INFO -     Found by: call frame info
[task 2020-07-20T21:41:42.969Z] 21:41:42     INFO - 10  xul.dll!mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) [MessagePump.cpp:626dd9d4a4fbc4b0c9fd7eca639ff2cc01046579 : 302 + 0x2a]
[task 2020-07-20T21:41:42.969Z] 21:41:42     INFO -     eip = 0x5286aa12   esp = 0x0c75fcf4   ebp = 0x0c75fd48   ebx = 0x002fe201
[task 2020-07-20T21:41:42.969Z] 21:41:42     INFO -     esi = 0x0f44fdc0   edi = 0x00000000
[task 2020-07-20T21:41:42.969Z] 21:41:42     INFO -     Found by: call frame info
[task 2020-07-20T21:41:42.969Z] 21:41:42     INFO - 11  xul.dll!MessageLoop::RunHandler() [message_loop.cc:626dd9d4a4fbc4b0c9fd7eca639ff2cc01046579 : 327 + 0x8]
[task 2020-07-20T21:41:42.969Z] 21:41:42     INFO -     eip = 0x5350ac04   esp = 0x0c75fd50   ebp = 0x0c75fd80   ebx = 0x002fe2ec
[task 2020-07-20T21:41:42.970Z] 21:41:42     INFO -     esi = 0x0c75fdb0   edi = 0x0c75fdb0
[task 2020-07-20T21:41:42.970Z] 21:41:42     INFO -     Found by: call frame info
[task 2020-07-20T21:41:42.970Z] 21:41:42     INFO - 12  xul.dll!MessageLoop::Run() [message_loop.cc:626dd9d4a4fbc4b0c9fd7eca639ff2cc01046579 : 309 + 0x5]
[task 2020-07-20T21:41:42.970Z] 21:41:42     INFO -     eip = 0x5284a561   esp = 0x0c75fd88   ebp = 0x0c75fda0   ebx = 0x002fe2ec
[task 2020-07-20T21:41:42.970Z] 21:41:42     INFO -     esi = 0x00863ec0   edi = 0x0c75fdb0
[task 2020-07-20T21:41:42.970Z] 21:41:42     INFO -     Found by: call frame info
[task 2020-07-20T21:41:42.970Z] 21:41:42     INFO - 13  xul.dll!static nsThread::ThreadFunc(void*) [nsThread.cpp:626dd9d4a4fbc4b0c9fd7eca639ff2cc01046579 : 447 + 0x7]
[task 2020-07-20T21:41:42.970Z] 21:41:42     INFO -     eip = 0x530bd31e   esp = 0x0c75fda8   ebp = 0x0c75fe80
[task 2020-07-20T21:41:42.970Z] 21:41:42     INFO -     Found by: call frame info
[task 2020-07-20T21:41:42.970Z] 21:41:42     INFO - 14  nss3.dll!_PR_NativeRunThread(void*) [pruthr.c:626dd9d4a4fbc4b0c9fd7eca639ff2cc01046579 : 399 + 0x6]
[task 2020-07-20T21:41:42.970Z] 21:41:42     INFO -     eip = 0x696057c6   esp = 0x0c75fe88   ebp = 0x0c75fea8   ebx = 0x0eff8190
[task 2020-07-20T21:41:42.970Z] 21:41:42     INFO -     esi = 0x0eff8190   edi = 0x0081d44c
[task 2020-07-20T21:41:42.970Z] 21:41:42     INFO -     Found by: call frame info
[task 2020-07-20T21:41:42.970Z] 21:41:42     INFO - 15  nss3.dll!pr_root(void*) [w95thred.c:626dd9d4a4fbc4b0c9fd7eca639ff2cc01046579 : 139 + 0x7]
[task 2020-07-20T21:41:42.970Z] 21:41:42     INFO -     eip = 0x695f798d   esp = 0x0c75feb0   ebp = 0x0c75feb4   ebx = 0x0038bfe0
[task 2020-07-20T21:41:42.970Z] 21:41:42     INFO -     esi = 0x695f7980   edi = 0x0038bfe0
[task 2020-07-20T21:41:42.970Z] 21:41:42     INFO -     Found by: call frame info
[task 2020-07-20T21:41:42.970Z] 21:41:42     INFO - 16  ucrtbase.dll!__RtlConvertUlongToLargeInteger + 0x8489
[task 2020-07-20T21:41:42.971Z] 21:41:42     INFO -     eip = 0x6aace16f   esp = 0x0c75febc   ebp = 0x0c75fef0
[task 2020-07-20T21:41:42.971Z] 21:41:42     INFO -     Found by: call frame info
[task 2020-07-20T21:41:42.971Z] 21:41:42     INFO - 17  kernel32.dll! ?? ?? ::FNODOBFM::`string' + 0x46
[task 2020-07-20T21:41:42.971Z] 21:41:42     INFO -     eip = 0x75ddef3c   esp = 0x0c75fef8   ebp = 0x0c75fefc
[task 2020-07-20T21:41:42.971Z] 21:41:42     INFO -     Found by: previous frame's frame pointer
[task 2020-07-20T21:41:42.971Z] 21:41:42     INFO - 18  ntdll.dll!__RtlUserThreadStart + 0x27
[task 2020-07-20T21:41:42.971Z] 21:41:42     INFO -     eip = 0x77813618   esp = 0x0c75ff04   ebp = 0x0c75ff3c
[task 2020-07-20T21:41:42.971Z] 21:41:42     INFO -     Found by: previous frame's frame pointer
[task 2020-07-20T21:41:42.971Z] 21:41:42     INFO - 19  ntdll.dll!_RtlUserThreadStart + 0x1b
[task 2020-07-20T21:41:42.971Z] 21:41:42     INFO -     eip = 0x778135eb   esp = 0x0c75ff44   ebp = 0x0c75ff54
[task 2020-07-20T21:41:42.971Z] 21:41:42     INFO -     Found by: call frame info
[task 2020-07-20T21:41:42.971Z] 21:41:42     INFO - 
Flags: needinfo?(mstange.moz)

This loop wasn't taking the mImages.Length() == 0 case very well: for (size_t i = 0; i < mImages.Length() - 1; i++) {
I'm adding an mImages.IsEmpty() check to the relevant patch.

Flags: needinfo?(mstange.moz)
Pushed by mstange@themasta.com:
https://hg.mozilla.org/integration/autoland/rev/8ab99078da80
Improve dropped frames reporting for videos, by counting all frames in mImages that were never composited. r=jya,nical
https://hg.mozilla.org/integration/autoland/rev/d06b2e855360
Ignore skipped frames when the video was offscreen. r=jya,nical
https://hg.mozilla.org/integration/autoland/rev/2929bbf453ed
Move mCompositionOpportunityId incrementing from EndTransaction to UpdateAndRender. r=nical
https://hg.mozilla.org/integration/autoland/rev/2445f3f46ca3
Call UpdateCompositedFrame from ChooseImageIndex so that the frame drop detection works for non-WebRender too. r=nical
You need to log in before you can comment on or make changes to this bug.