Intermittent Assertion failure: [GFX1]: Texture deallocated too late during shutdown, at /builds/worker/checkouts/gecko/gfx/2d/Logging.h:756
Categories
(Core :: WebRTC: Audio/Video, defect, P5)
Tracking
()
| Tracking | Status | |
|---|---|---|
| firefox83 | --- | fixed |
People
(Reporter: intermittent-bug-filer, Assigned: pehrsons)
References
Details
(Keywords: intermittent-failure)
Attachments
(1 file)
Filed by: nbeleuzu [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=298606594&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/bM8IumQkTPOLE0JQ0LMkaQ/runs/0/artifacts/public/logs/live_backing.log
[task 2020-04-21T11:50:21.600Z] 11:50:21 INFO - PID 15965 | SharedThreadPool in xpcom-shutdown-threads. Waiting for pools "CubebOperation"
[task 2020-04-21T11:50:21.743Z] 11:50:21 INFO - PID 15965 | [Child 16472, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp, line 475
[task 2020-04-21T11:50:21.744Z] 11:50:21 INFO - PID 15965 | [GFX1]: Texture deallocated too late during shutdown
[task 2020-04-21T11:50:21.745Z] 11:50:21 INFO - PID 15965 | Assertion failure: [GFX1]: Texture deallocated too late during shutdown, at /builds/worker/checkouts/gecko/gfx/2d/Logging.h:756
[task 2020-04-21T11:50:21.765Z] 11:50:21 INFO - STDOUT: Initializing stack-fixing for the first stack frame, this may take a while...
[task 2020-04-21T11:50:23.474Z] 11:50:23 INFO - mozcrash ...
[task 2020-04-21T11:50:23.475Z] 11:50:23 INFO - mozcrash Copy/paste: /builds/worker/fetches/minidump_stackwalk/minidump_stackwalk /tmp/tmpomegOI/minidumps/6b872ea2-2839-94e9-6b79-c13093f2a17d.dmp /builds/worker/workspace/build/symbols
[task 2020-04-21T11:50:31.181Z] 11:50:31 INFO - mozcrash Saved minidump as /builds/worker/workspace/build/blobber_upload_dir/6b872ea2-2839-94e9-6b79-c13093f2a17d.dmp
[task 2020-04-21T11:50:31.231Z] 11:50:31 INFO - PROCESS-CRASH | /mediacapture-record/MediaRecorder-error.html | application crashed [@ mozilla::gfx::Log<1, mozilla::gfx::CriticalLogger>::WriteLog(std::string const&)]
[task 2020-04-21T11:50:31.232Z] 11:50:31 INFO - Crash dump filename: /tmp/tmpomegOI/minidumps/6b872ea2-2839-94e9-6b79-c13093f2a17d.dmp
[task 2020-04-21T11:50:31.233Z] 11:50:31 INFO - Operating system: Linux
[task 2020-04-21T11:50:31.235Z] 11:50:31 INFO - CPU: amd64
[task 2020-04-21T11:50:31.236Z] 11:50:31 INFO - family 6 model 62 stepping 4
[task 2020-04-21T11:50:31.236Z] 11:50:31 INFO - 4 CPUs
[task 2020-04-21T11:50:31.236Z] 11:50:31 INFO -
[task 2020-04-21T11:50:31.236Z] 11:50:31 INFO - GPU: UNKNOWN
[task 2020-04-21T11:50:31.236Z] 11:50:31 INFO -
[task 2020-04-21T11:50:31.237Z] 11:50:31 INFO - Crash reason: SIGSEGV /SEGV_MAPERR
[task 2020-04-21T11:50:31.237Z] 11:50:31 INFO - Crash address: 0x0
[task 2020-04-21T11:50:31.237Z] 11:50:31 INFO - Process uptime: not available
[task 2020-04-21T11:50:31.237Z] 11:50:31 INFO -
[task 2020-04-21T11:50:31.237Z] 11:50:31 INFO - Thread 0 (crashed)
[task 2020-04-21T11:50:31.237Z] 11:50:31 INFO - 0 libxul.so!mozilla::gfx::Log<1, mozilla::gfx::CriticalLogger>::WriteLog(std::string const&) [Logging.h:c159181ff5d00814ffa6c1648dc22002b70da9ed : 757 + 0x25]
[task 2020-04-21T11:50:31.237Z] 11:50:31 INFO - rax = 0x00007fc5e78fc6e7 rdx = 0x0000000000000000
[task 2020-04-21T11:50:31.238Z] 11:50:31 INFO - rcx = 0x0000564d67575e30 rbx = 0x00007fc5e78fc68f
[task 2020-04-21T11:50:31.238Z] 11:50:31 INFO - rsi = 0x00007fc5f3a5c8b0 rdi = 0x00007fc5f3a5b680
[task 2020-04-21T11:50:31.238Z] 11:50:31 INFO - rbp = 0x00007ffc2068cbd0 rsp = 0x00007ffc2068cbc0
[task 2020-04-21T11:50:31.238Z] 11:50:31 INFO - r8 = 0x00007fc5f3a5c8b0 r9 = 0x00007fc5f4b5b780
[task 2020-04-21T11:50:31.238Z] 11:50:31 INFO - r10 = 0x0000000000000000 r11 = 0x0000000000000000
[task 2020-04-21T11:50:31.238Z] 11:50:31 INFO - r12 = 0x0000000000000000 r13 = 0x00007ffc2068ce40
[task 2020-04-21T11:50:31.239Z] 11:50:31 INFO - r14 = 0x00007ffc2068cbf0 r15 = 0x00007fc5d88d2c10
[task 2020-04-21T11:50:31.239Z] 11:50:31 INFO - rip = 0x00007fc5e166e27b
[task 2020-04-21T11:50:31.239Z] 11:50:31 INFO - Found by: given as instruction pointer in context
[task 2020-04-21T11:50:31.240Z] 11:50:31 INFO - 1 libxul.so!mozilla::gfx::Log<1, mozilla::gfx::CriticalLogger>::Flush() [Logging.h:c159181ff5d00814ffa6c1648dc22002b70da9ed : 279 + 0x8]
[task 2020-04-21T11:50:31.240Z] 11:50:31 INFO - rbx = 0x00007ffc2068cc70 rbp = 0x00007ffc2068cc10
[task 2020-04-21T11:50:31.240Z] 11:50:31 INFO - rsp = 0x00007ffc2068cbe0 r12 = 0x0000000000000000
[task 2020-04-21T11:50:31.240Z] 11:50:31 INFO - r13 = 0x00007ffc2068ce40 r14 = 0x00007ffc2068cbf0
[task 2020-04-21T11:50:31.241Z] 11:50:31 INFO - r15 = 0x00007fc5d88d2c10 rip = 0x00007fc5e166e1af
[task 2020-04-21T11:50:31.242Z] 11:50:31 INFO - Found by: call frame info
[task 2020-04-21T11:50:31.243Z] 11:50:31 INFO - 2 libxul.so!mozilla::gfx::Log<1, mozilla::gfx::CriticalLogger>::~Log() [Logging.h:c159181ff5d00814ffa6c1648dc22002b70da9ed : 272 + 0xe]
[task 2020-04-21T11:50:31.243Z] 11:50:31 INFO - rbx = 0x00007ffc2068cc70 rbp = 0x00007ffc2068cc30
[task 2020-04-21T11:50:31.244Z] 11:50:31 INFO - rsp = 0x00007ffc2068cc20 r12 = 0x0000000000000000
[task 2020-04-21T11:50:31.245Z] 11:50:31 INFO - r13 = 0x00007ffc2068ce40 r14 = 0x00007ffc2068ce78
[task 2020-04-21T11:50:31.246Z] 11:50:31 INFO - r15 = 0x00007fc5d88d2c10 rip = 0x00007fc5e166de90
[task 2020-04-21T11:50:31.246Z] 11:50:31 INFO - Found by: call frame info
[task 2020-04-21T11:50:31.247Z] 11:50:31 INFO - 3 libxul.so!mozilla::layers::DeallocateTextureClient(mozilla::layers::TextureDeallocParams) [TextureClient.cpp:c159181ff5d00814ffa6c1648dc22002b70da9ed : 500 + 0x5]
[task 2020-04-21T11:50:31.248Z] 11:50:31 INFO - rbx = 0x00007ffc2068cc70 rbp = 0x00007ffc2068ce20
[task 2020-04-21T11:50:31.248Z] 11:50:31 INFO - rsp = 0x00007ffc2068cc40 r12 = 0x0000000000000000
[task 2020-04-21T11:50:31.248Z] 11:50:31 INFO - r13 = 0x00007ffc2068ce40 r14 = 0x00007ffc2068ce78
[task 2020-04-21T11:50:31.248Z] 11:50:31 INFO - r15 = 0x00007fc5d88d2c10 rip = 0x00007fc5e1767718
[task 2020-04-21T11:50:31.248Z] 11:50:31 INFO - Found by: call frame info
| Comment hidden (Intermittent Failures Robot) |
Updated•5 years ago
|
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
Comment 8•5 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Comment 9•5 years ago
|
||
New occurrence: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=314634225&repo=autoland&lineNumber=14750
| Comment hidden (Intermittent Failures Robot) |
| Assignee | ||
Comment 11•5 years ago
|
||
I see a MediaStreamTrack on the stack. Pernosco also caught a couple of these for me, which is how I found this bug.
| Assignee | ||
Comment 12•5 years ago
|
||
To avoid leaking graphics resources (Images) past thread-shutdown.
Comment 13•5 years ago
|
||
Comment 14•5 years ago
|
||
| bugherder | ||
Comment 15•5 years ago
|
||
This is still occuring: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=318340720&repo=mozilla-central&lineNumber=4648
[task 2020-10-12T10:11:21.217Z] 10:11:21 INFO - TEST-START | /html/canvas/element/manual/the-canvas-state/2d.zero.size.canvas.html
[task 2020-10-12T10:11:21.233Z] 10:11:21 INFO - Closing window 1036
[task 2020-10-12T10:11:21.376Z] 10:11:21 INFO - PID 1272 | [Child 1387, Main Thread] WARNING: nsAppShell::Exit() called redundantly: file /builds/worker/checkouts/gecko/widget/cocoa/nsAppShell.mm:714
[task 2020-10-12T10:11:21.376Z] 10:11:21 INFO - PID 1272 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-10-12T10:11:21.376Z] 10:11:21 INFO - PID 1272 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-10-12T10:11:21.640Z] 10:11:21 INFO - PID 1272 | [1390, MainThread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp:202
[task 2020-10-12T10:11:21.640Z] 10:11:21 INFO - PID 1272 | [1390, MainThread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp:202
[task 2020-10-12T10:11:21.641Z] 10:11:21 INFO - PID 1272 | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /var/folders/z8/myw6bmsd61q1_j6xt3z534n8000017/T/tmpil321S/runtests_leaks_1177_tab_pid1390.log
[task 2020-10-12T10:11:21.641Z] 10:11:21 INFO - PID 1272 | [1390, MainThread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp:202
[task 2020-10-12T10:11:21.641Z] 10:11:21 INFO - PID 1272 | [1390, MainThread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp:202
[task 2020-10-12T10:11:21.641Z] 10:11:21 INFO - PID 1272 | [1390, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp:246
[task 2020-10-12T10:11:21.937Z] 10:11:21 INFO - PID 1272 | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2020-10-12T10:11:21.937Z] 10:11:21 INFO - PID 1272 | [Child 1390, Main Thread] WARNING: Could not get the program name for a cubeb stream.: 'NS_SUCCEEDED(rv)', file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:378
[task 2020-10-12T10:11:22.092Z] 10:11:22 INFO - PID 1272 | [Child 1387, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:511
[task 2020-10-12T10:11:22.092Z] 10:11:22 INFO - PID 1272 | [GFX1]: Texture deallocated too late during shutdown
[task 2020-10-12T10:11:22.092Z] 10:11:22 INFO - PID 1272 | Assertion failure: [GFX1]: Texture deallocated too late during shutdown, at /builds/worker/checkouts/gecko/gfx/2d/Logging.h:754
[task 2020-10-12T10:11:22.092Z] 10:11:22 INFO - STDOUT: Initializing stack-fixing for the first stack frame, this may take a while...
[task 2020-10-12T10:11:22.408Z] 10:11:22 INFO - mozcrash .
[task 2020-10-12T10:11:22.408Z] 10:11:22 INFO - mozcrash Copy/paste: /Users/cltbld/tasks/task_1602496464/fetches/minidump_stackwalk/minidump_stackwalk /var/folders/z8/myw6bmsd61q1_j6xt3z534n8000017/T/tmpil321S/minidumps/0DF72B38-B21D-40C8-B8B4-4EB59C03428F.dmp /Users/cltbld/tasks/task_1602496464/build/symbols
[task 2020-10-12T10:11:22.423Z] 10:11:22 INFO - mozcrash Saved minidump as /Users/cltbld/tasks/task_1602496464/build/blobber_upload_dir/0DF72B38-B21D-40C8-B8B4-4EB59C03428F.dmp
[task 2020-10-12T10:11:22.426Z] 10:11:22 INFO - PROCESS-CRASH | /html/canvas/element/manual/the-canvas-state/2d.zero.size.canvas.html | application crashed [None]
[task 2020-10-12T10:11:22.426Z] 10:11:22 INFO - Crash dump filename: /var/folders/z8/myw6bmsd61q1_j6xt3z534n8000017/T/tmpil321S/minidumps/0DF72B38-B21D-40C8-B8B4-4EB59C03428F.dmp
[task 2020-10-12T10:11:22.426Z] 10:11:22 INFO - stderr from minidump_stackwalk:
[task 2020-10-12T10:11:22.426Z] 10:11:22 INFO - 2020-10-12 10:11:22: minidump_stackwalk.cc:135: ERROR: Minidump /var/folders/z8/myw6bmsd61q1_j6xt3z534n8000017/T/tmpil321S/minidumps/0DF72B38-B21D-40C8-B8B4-4EB59C03428F.dmp could not be read
[task 2020-10-12T10:11:22.426Z] 10:11:22 WARNING - Found a crash dump; should change status from OK to CRASH but this causes instability
[task 2020-10-12T10:11:22.427Z] 10:11:22 INFO - TEST-OK | /html/canvas/element/manual/the-canvas-state/2d.zero.size.canvas.html | took 1214ms
Andreas can you take a look?
| Assignee | ||
Comment 16•5 years ago
|
||
I fixed a case of a member of SourceMediaTrack being released too late. This is something in ImageBitmapRenderingContext:
[task 2020-10-12T10:11:23.919Z] 10:11:23 INFO - Closing window 1042
[task 2020-10-12T10:11:32.483Z] 10:11:32 INFO - PID 1272 | #01: mozilla::gfx::Log<1, mozilla::gfx::CriticalLogger>::Flush() [gfx/2d/Logging.h:279]
[task 2020-10-12T10:11:32.483Z] 10:11:32 INFO - PID 1272 | #02: mozilla::layers::DeallocateTextureClient(mozilla::layers::TextureDeallocParams) [gfx/layers/client/TextureClient.cpp:523]
[task 2020-10-12T10:11:32.483Z] 10:11:32 INFO - PID 1272 | #03: mozilla::layers::TextureClient::Destroy() [gfx/layers/client/TextureClient.cpp:625]
[task 2020-10-12T10:11:32.484Z] 10:11:32 INFO - PID 1272 | #04: mozilla::layers::TextureClient::~TextureClient() [gfx/layers/client/TextureClient.cpp:804]
[task 2020-10-12T10:11:32.484Z] 10:11:32 INFO - PID 1272 | #05: mozilla::layers::TextureClient::~TextureClient() [gfx/layers/client/TextureClient.cpp:798]
[task 2020-10-12T10:11:32.484Z] 10:11:32 INFO - PID 1272 | #06: mozilla::AtomicRefCountedWithFinalize<mozilla::layers::TextureClient>::Release() [gfx/layers/AtomicRefCountedWithFinalize.h:152]
[task 2020-10-12T10:11:32.484Z] 10:11:32 INFO - PID 1272 | #07: mozilla::layers::TextureClientHolder::Release() [gfx/layers/client/TextureClientRecycleAllocator.cpp:23]
[task 2020-10-12T10:11:32.485Z] 10:11:32 INFO - PID 1272 | #08: mozilla::layers::TextureClientRecycleAllocator::Destroy() [gfx/layers/client/TextureClientRecycleAllocator.cpp:217]
[task 2020-10-12T10:11:32.486Z] 10:11:32 INFO - PID 1272 | #09: mozilla::layers::CompositableClient::~CompositableClient() [gfx/layers/client/CompositableClient.cpp:50]
[task 2020-10-12T10:11:32.486Z] 10:11:32 INFO - PID 1272 | #10: mozilla::layers::ImageClientSingle::~ImageClientSingle() [gfx/layers/client/ImageClient.h:93]
[task 2020-10-12T10:11:32.486Z] 10:11:32 INFO - PID 1272 | #11: mozilla::layers::SharedPlanarYCbCrImage::~SharedPlanarYCbCrImage() [gfx/layers/ipc/SharedPlanarYCbCrImage.cpp:44]
[task 2020-10-12T10:11:32.487Z] 10:11:32 INFO - PID 1272 | #12: mozilla::layers::SharedPlanarYCbCrImage::~SharedPlanarYCbCrImage() [gfx/layers/ipc/SharedPlanarYCbCrImage.cpp:42]
[task 2020-10-12T10:11:32.488Z] 10:11:32 INFO - PID 1272 | #13: mozilla::dom::ImageBitmapRenderingContext::~ImageBitmapRenderingContext() [dom/canvas/ImageBitmapRenderingContext.cpp:19] <----
[task 2020-10-12T10:11:32.488Z] 10:11:32 INFO - PID 1272 | #14: mozilla::dom::ImageBitmapRenderingContext::cycleCollection::DeleteCycleCollectable(void*) [dom/canvas/ImageBitmapRenderingContext.h:48]
[task 2020-10-12T10:11:32.489Z] 10:11:32 INFO - PID 1272 | #15: SnowWhiteKiller::MaybeKillObject(SnowWhiteKiller::SnowWhiteObject&) [xpcom/base/nsCycleCollector.cpp:2432]
[task 2020-10-12T10:11:32.489Z] 10:11:32 INFO - PID 1272 | #16: SnowWhiteKiller::~SnowWhiteKiller() [xpcom/base/nsCycleCollector.cpp:2417]
[task 2020-10-12T10:11:32.489Z] 10:11:32 INFO - PID 1272 | #17: nsCycleCollector::FreeSnowWhite(bool) [xpcom/base/nsCycleCollector.cpp:2607]
[task 2020-10-12T10:11:32.489Z] 10:11:32 INFO - PID 1272 | #18: nsCycleCollector::BeginCollection(ccType, nsICycleCollectorListener*) [xpcom/base/nsCycleCollector.cpp:3583]
[task 2020-10-12T10:11:32.491Z] 10:11:32 INFO - PID 1272 | #19: nsCycleCollector::Collect(ccType, js::SliceBudget&, nsICycleCollectorListener*, bool) [xpcom/base/nsCycleCollector.cpp:3409]
[task 2020-10-12T10:11:32.491Z] 10:11:32 INFO - PID 1272 | #20: nsCycleCollector::ShutdownCollect() [xpcom/base/nsCycleCollector.cpp:3352]
[task 2020-10-12T10:11:32.491Z] 10:11:32 INFO - PID 1272 | #21: nsCycleCollector::Shutdown(bool) [xpcom/base/nsCycleCollector.cpp:3644]
[task 2020-10-12T10:11:32.491Z] 10:11:32 INFO - PID 1272 | #22: nsCycleCollector_shutdown(bool) [xpcom/base/nsCycleCollector.cpp:3957]
[task 2020-10-12T10:11:32.492Z] 10:11:32 INFO - PID 1272 | #23: mozilla::ShutdownXPCOM(nsIServiceManager*) [xpcom/build/XPCOMInit.cpp:723]
Looking at its members, it's probably mImage.
If captureStream() was involved fixing this would be on me, but I don't see any test like that. This is wpt and if there's coverage for captureStream it's in mediacapture-fromelement. I'll file a new bug.
| Comment hidden (Intermittent Failures Robot) |
Description
•