Closed Bug 1615121 Opened 4 years ago Closed 4 years ago

Intermittent GECKO(1119) | SUMMARY: ThreadSanitizer: data race /builds/worker/workspace/build/src/netwerk/cache2/CacheEntry.cpp:1436:33 in mozilla::net::CacheEntry::MetaDataReady()

Categories

(Core :: Networking: Cache, defect, P2)

Product:
Core
Component:
Networking: Cache
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla80
Tracking Flags:
Tracking Status
firefox80 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: mayhemer)

References

(Blocks 1 open bug)

Details

(Whiteboard: [necko-triaged])

Attachments

(1 file)

Bug 1615121 - Keep CacheEntry.mLock when reading its mState to prevent a race, r=michal
47 bytes, text/x-phabricator-request
Details | Review

This occurred on autoland, did not show up in previous try pushes. It looks like a race on mState in CacheEntry::MetaDataReady vs. CacheEntry::Purge.

Michal?

Flags: needinfo?(michal.novotny)
Priority: P5 → P2
Whiteboard: [necko-triaged]
Flags: needinfo?(michal.novotny) → needinfo?(honzab.moz)
Assignee: nobody → honzab.moz
Status: NEW → ASSIGNED

Unfortunately, the try run shows a problem:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=288769153&repo=try&lineNumber=7334

[task 2020-02-13T17:39:43.962Z] 17:39:43     INFO - GECKO(624) | ###!!! ERROR: Potential deadlock detected:
[task 2020-02-13T17:39:43.962Z] 17:39:43     INFO - GECKO(624) | === Cyclical dependency starts at
[task 2020-02-13T17:39:43.962Z] 17:39:43     INFO - GECKO(624) | --- Mutex : CacheStorageService.mLock calling context
[task 2020-02-13T17:39:43.963Z] 17:39:43     INFO - GECKO(624) |   [stack trace unavailable]
[task 2020-02-13T17:39:43.963Z] 17:39:43     INFO - GECKO(624) | --- Next dependency:
[task 2020-02-13T17:39:43.964Z] 17:39:43     INFO - GECKO(624) | --- Mutex : CacheEntry calling context
[task 2020-02-13T17:39:43.964Z] 17:39:43     INFO - GECKO(624) |   [stack trace unavailable]
[task 2020-02-13T17:39:43.964Z] 17:39:43     INFO - GECKO(624) | --- Next dependency:
[task 2020-02-13T17:39:43.964Z] 17:39:43     INFO - GECKO(624) | --- Mutex : CacheEntry (currently acquired)
[task 2020-02-13T17:39:43.964Z] 17:39:43     INFO - GECKO(624) |  calling context
[task 2020-02-13T17:39:43.964Z] 17:39:43     INFO - GECKO(624) |   [stack trace unavailable]
[task 2020-02-13T17:39:43.964Z] 17:39:43     INFO - GECKO(624) | === Cycle completed at
[task 2020-02-13T17:39:43.965Z] 17:39:43     INFO - GECKO(624) | --- Mutex : CacheStorageService.mLock calling context
[task 2020-02-13T17:39:43.965Z] 17:39:43     INFO - GECKO(624) |   [stack trace unavailable]
[task 2020-02-13T17:39:43.965Z] 17:39:43     INFO - GECKO(624) | Deadlock may happen for some other execution
[task 2020-02-13T17:39:43.966Z] 17:39:43     INFO - GECKO(624) | [Parent 7600, Cache2 I/O] WARNING: Potential deadlock detected:
[task 2020-02-13T17:39:43.966Z] 17:39:43     INFO - GECKO(624) | Cyclical dependency starts at
[task 2020-02-13T17:39:43.966Z] 17:39:43     INFO - GECKO(624) | Mutex : CacheStorageService.mLock
[task 2020-02-13T17:39:43.967Z] 17:39:43     INFO - GECKO(624) | Next dependency:
[task 2020-02-13T17:39:43.967Z] 17:39:43     INFO - GECKO(624) | Mutex : CacheEntry
[task 2020-02-13T17:39:43.968Z] 17:39:43     INFO - GECKO(624) | Next dependency:
[task 2020-02-13T17:39:43.968Z] 17:39:43     INFO - GECKO(624) | Mutex : CacheEntry (currently acquired)
[task 2020-02-13T17:39:43.968Z] 17:39:43     INFO - GECKO(624) | Cycle completed at
[task 2020-02-13T17:39:43.968Z] 17:39:43     INFO - GECKO(624) | Mutex : CacheStorageService.mLock
[task 2020-02-13T17:39:43.969Z] 17:39:43     INFO - GECKO(624) | Deadlock may happen for some other execution
[task 2020-02-13T17:39:43.969Z] 17:39:43     INFO - GECKO(624) | : file z:/build/build/src/xpcom/threads/BlockingResourceBase.cpp, line 250

...

[task 2020-02-13T17:40:05.405Z] 17:40:05     INFO - Operating system: Windows NT
[task 2020-02-13T17:40:05.405Z] 17:40:05     INFO -                   10.0.17134 
[task 2020-02-13T17:40:05.405Z] 17:40:05     INFO - CPU: amd64
[task 2020-02-13T17:40:05.405Z] 17:40:05     INFO -      family 6 model 85 stepping 4
[task 2020-02-13T17:40:05.405Z] 17:40:05     INFO -      8 CPUs
[task 2020-02-13T17:40:05.405Z] 17:40:05     INFO - 
[task 2020-02-13T17:40:05.405Z] 17:40:05     INFO - GPU: UNKNOWN
[task 2020-02-13T17:40:05.405Z] 17:40:05     INFO - 
[task 2020-02-13T17:40:05.405Z] 17:40:05     INFO - Crash reason:  EXCEPTION_ACCESS_VIOLATION_READ
[task 2020-02-13T17:40:05.405Z] 17:40:05     INFO - Crash address: 0x76a51578
[task 2020-02-13T17:40:05.405Z] 17:40:05     INFO - Process uptime: 206 seconds
[task 2020-02-13T17:40:05.405Z] 17:40:05     INFO - 
[task 2020-02-13T17:40:05.405Z] 17:40:05     INFO - Thread 19 (crashed)
[task 2020-02-13T17:40:05.405Z] 17:40:05     INFO -  0  xul.dll!mozilla::BlockingResourceBase::Print(nsTSubstring<char>&) const [BlockingResourceBase.cpp:dce82130ce121c237ee48a275acde94f87dce505 : 124 + 0xf]
[task 2020-02-13T17:40:05.405Z] 17:40:05     INFO -     rax = 0xffffffffe5e5e5e5   rdx = 0x000000ad0085f740
[task 2020-02-13T17:40:05.406Z] 17:40:05     INFO -     rcx = 0x000002342cc84f28   rbx = 0x00000000476ee300
[task 2020-02-13T17:40:05.406Z] 17:40:05     INFO -     rsi = 0x000000ad0085f740   rdi = 0x000002342cc84f28
[task 2020-02-13T17:40:05.406Z] 17:40:05     INFO -     rbp = 0x00007ffe7ee007b0   rsp = 0x000000ad0085f6c0
[task 2020-02-13T17:40:05.406Z] 17:40:05     INFO -      r8 = 0x0000000000000009    r9 = 0x00007ffe79c5cdd8
[task 2020-02-13T17:40:05.406Z] 17:40:05     INFO -     r10 = 0x00007ffe47761642   r11 = 0x000002342c6ec4f7
[task 2020-02-13T17:40:05.406Z] 17:40:05     INFO -     r12 = 0x00007ffe47761642   r13 = 0x000000ad0085f740
[task 2020-02-13T17:40:05.406Z] 17:40:05     INFO -     r14 = 0xe5e5e5e5e5e5e5e5   r15 = 0x00007ffe4775e650
[task 2020-02-13T17:40:05.406Z] 17:40:05     INFO -     rip = 0x00007ffe3f1dc1c0
[task 2020-02-13T17:40:05.406Z] 17:40:05     INFO -     Found by: given as instruction pointer in context
[task 2020-02-13T17:40:05.406Z] 17:40:05     INFO -  1  xul.dll!mozilla::BlockingResourceBase::CheckAcquire() [BlockingResourceBase.cpp:dce82130ce121c237ee48a275acde94f87dce505 : 236 + 0x104]
[task 2020-02-13T17:40:05.406Z] 17:40:05     INFO -     rbx = 0x00000000476ee300   rbp = 0x00007ffe7ee007b0
[task 2020-02-13T17:40:05.406Z] 17:40:05     INFO -     rsp = 0x000000ad0085f710   r12 = 0x00007ffe47761642
[task 2020-02-13T17:40:05.406Z] 17:40:05     INFO -     r13 = 0x000000ad0085f740   r14 = 0xe5e5e5e5e5e5e5e5
[task 2020-02-13T17:40:05.406Z] 17:40:05     INFO -     r15 = 0x00007ffe4775e650   rip = 0x00007ffe3f1dcc22
[task 2020-02-13T17:40:05.406Z] 17:40:05     INFO -     Found by: call frame info
[task 2020-02-13T17:40:05.406Z] 17:40:05     INFO -  2  xul.dll!mozilla::OffTheBooksMutex::Lock() [BlockingResourceBase.cpp:dce82130ce121c237ee48a275acde94f87dce505 : 317 + 0xc]
[task 2020-02-13T17:40:05.406Z] 17:40:05     INFO -     rbx = 0x00000000476ee300   rbp = 0x00007ffe7ee007b0
[task 2020-02-13T17:40:05.406Z] 17:40:05     INFO -     rsp = 0x000000ad0085f7f0   r12 = 0x00007ffe47761642
[task 2020-02-13T17:40:05.406Z] 17:40:05     INFO -     r13 = 0x000000ad0085f740   r14 = 0xe5e5e5e5e5e5e5e5
[task 2020-02-13T17:40:05.407Z] 17:40:05     INFO -     r15 = 0x00007ffe4775e650   rip = 0x00007ffe3f1dd435
[task 2020-02-13T17:40:05.407Z] 17:40:05     INFO -     Found by: call frame info
[task 2020-02-13T17:40:05.407Z] 17:40:05     INFO -  3  xul.dll!mozilla::net::CacheStorageService::RemoveEntry(mozilla::net::CacheEntry*, bool) [CacheStorageService.cpp:dce82130ce121c237ee48a275acde94f87dce505 : 1105 + 0x13]
[task 2020-02-13T17:40:05.407Z] 17:40:05     INFO -     rbx = 0x00000000476ee300   rbp = 0x00007ffe7ee007b0
[task 2020-02-13T17:40:05.407Z] 17:40:05     INFO -     rsp = 0x000000ad0085f830   r12 = 0x00007ffe47761642
[task 2020-02-13T17:40:05.407Z] 17:40:05     INFO -     r13 = 0x000000ad0085f740   r14 = 0xe5e5e5e5e5e5e5e5
[task 2020-02-13T17:40:05.407Z] 17:40:05     INFO -     r15 = 0x00007ffe4775e650   rip = 0x00007ffe3f70338f
[task 2020-02-13T17:40:05.407Z] 17:40:05     INFO -     Found by: call frame info
[task 2020-02-13T17:40:05.407Z] 17:40:05     INFO -  4  xul.dll!mozilla::net::CacheEntry::Purge(unsigned int) [CacheEntry.cpp:dce82130ce121c237ee48a275acde94f87dce505 : 1670 + 0xb]
[task 2020-02-13T17:40:05.407Z] 17:40:05     INFO -     rbx = 0x00000000476ee300   rbp = 0x00007ffe7ee007b0
[task 2020-02-13T17:40:05.407Z] 17:40:05     INFO -     rsp = 0x000000ad0085f980   r12 = 0x00007ffe47761642
[task 2020-02-13T17:40:05.407Z] 17:40:05     INFO -     r13 = 0x000000ad0085f740   r14 = 0xe5e5e5e5e5e5e5e5
[task 2020-02-13T17:40:05.407Z] 17:40:05     INFO -     r15 = 0x00007ffe4775e650   rip = 0x00007ffe3f6b08eb
[task 2020-02-13T17:40:05.407Z] 17:40:05     INFO -     Found by: call frame info
[task 2020-02-13T17:40:05.407Z] 17:40:05     INFO -  5  xul.dll!mozilla::net::CacheStorageService::MemoryPool::PurgeByFrecency(bool&, unsigned int) [CacheStorageService.cpp:dce82130ce121c237ee48a275acde94f87dce505 : 1454 + 0xb]
[task 2020-02-13T17:40:05.407Z] 17:40:05     INFO -     rbx = 0x00000000476ee300   rbp = 0x00007ffe7ee007b0
[task 2020-02-13T17:40:05.407Z] 17:40:05     INFO -     rsp = 0x000000ad0085f9e0   r12 = 0x00007ffe47761642
[task 2020-02-13T17:40:05.407Z] 17:40:05     INFO -     r13 = 0x000000ad0085f740   r14 = 0xe5e5e5e5e5e5e5e5
[task 2020-02-13T17:40:05.407Z] 17:40:05     INFO -     r15 = 0x00007ffe4775e650   rip = 0x00007ffe3f704dab
[task 2020-02-13T17:40:05.407Z] 17:40:05     INFO -     Found by: call frame info
[task 2020-02-13T17:40:05.408Z] 17:40:05     INFO -  6  xul.dll!mozilla::net::CacheStorageService::MemoryPool::PurgeOverMemoryLimit() [CacheStorageService.cpp:dce82130ce121c237ee48a275acde94f87dce505 : 1404 + 0x13]
[task 2020-02-13T17:40:05.408Z] 17:40:05     INFO -     rbx = 0x00000000476ee300   rbp = 0x00007ffe7ee007b0
[task 2020-02-13T17:40:05.408Z] 17:40:05     INFO -     rsp = 0x000000ad0085fa70   r12 = 0x00007ffe47761642
[task 2020-02-13T17:40:05.408Z] 17:40:05     INFO -     r13 = 0x000000ad0085f740   r14 = 0xe5e5e5e5e5e5e5e5
[task 2020-02-13T17:40:05.408Z] 17:40:05     INFO -     r15 = 0x00007ffe4775e650   rip = 0x00007ffe3f704994
[task 2020-02-13T17:40:05.408Z] 17:40:05     INFO -     Found by: call frame info
[task 2020-02-13T17:40:05.408Z] 17:40:05     INFO -  7  xul.dll!mozilla::net::CacheStorageService::PurgeOverMemoryLimit() [CacheStorageService.cpp:dce82130ce121c237ee48a275acde94f87dce505 : 1369 + 0x5]
[task 2020-02-13T17:40:05.408Z] 17:40:05     INFO -     rbx = 0x00000000476ee300   rbp = 0x00007ffe7ee007b0
[task 2020-02-13T17:40:05.408Z] 17:40:05     INFO -     rsp = 0x000000ad0085fb00   r12 = 0x00007ffe47761642
[task 2020-02-13T17:40:05.408Z] 17:40:05     INFO -     r13 = 0x000000ad0085f740   r14 = 0xe5e5e5e5e5e5e5e5
[task 2020-02-13T17:40:05.408Z] 17:40:05     INFO -     r15 = 0x00007ffe4775e650   rip = 0x00007ffe3f70480b
[task 2020-02-13T17:40:05.408Z] 17:40:05     INFO -     Found by: call frame info
[task 2020-02-13T17:40:05.408Z] 17:40:05     INFO -  8  xul.dll!mozilla::detail::RunnableMethodImpl<mozilla::net::CacheStorageService *,void (mozilla::net::CacheStorageService::*)(),1,mozilla::RunnableKind::Standard>::Run() [nsThreadUtils.h:dce82130ce121c237ee48a275acde94f87dce505 : 1212 + 0xa]
[task 2020-02-13T17:40:05.408Z] 17:40:05     INFO -     rbx = 0x00000000476ee300   rbp = 0x00007ffe7ee007b0
[task 2020-02-13T17:40:05.408Z] 17:40:05     INFO -     rsp = 0x000000ad0085fb70   r12 = 0x00007ffe47761642
[task 2020-02-13T17:40:05.408Z] 17:40:05     INFO -     r13 = 0x000000ad0085f740   r14 = 0xe5e5e5e5e5e5e5e5
[task 2020-02-13T17:40:05.408Z] 17:40:05     INFO -     r15 = 0x00007ffe4775e650   rip = 0x00007ffe3f711b7a
[task 2020-02-13T17:40:05.408Z] 17:40:05     INFO -     Found by: call frame info
[task 2020-02-13T17:40:05.408Z] 17:40:05     INFO -  9  xul.dll!mozilla::net::CacheIOThread::LoopOneLevel(unsigned int) [CacheIOThread.cpp:dce82130ce121c237ee48a275acde94f87dce505 : 535 + 0x6]
[task 2020-02-13T17:40:05.409Z] 17:40:05     INFO -     rbx = 0x00000000476ee300   rbp = 0x00007ffe7ee007b0
[task 2020-02-13T17:40:05.409Z] 17:40:05     INFO -     rsp = 0x000000ad0085fba0   r12 = 0x00007ffe47761642
[task 2020-02-13T17:40:05.409Z] 17:40:05     INFO -     r13 = 0x000000ad0085f740   r14 = 0xe5e5e5e5e5e5e5e5
[task 2020-02-13T17:40:05.409Z] 17:40:05     INFO -     r15 = 0x00007ffe4775e650   rip = 0x00007ffe3f6e6da7
[task 2020-02-13T17:40:05.409Z] 17:40:05     INFO -     Found by: call frame info
[task 2020-02-13T17:40:05.409Z] 17:40:05     INFO - 10  xul.dll!mozilla::net::CacheIOThread::ThreadFunc() [CacheIOThread.cpp:dce82130ce121c237ee48a275acde94f87dce505 : 473 + 0x8]
[task 2020-02-13T17:40:05.409Z] 17:40:05     INFO -     rbx = 0x00000000476ee300   rbp = 0x00007ffe7ee007b0
[task 2020-02-13T17:40:05.409Z] 17:40:05     INFO -     rsp = 0x000000ad0085fc40   r12 = 0x00007ffe47761642
[task 2020-02-13T17:40:05.409Z] 17:40:05     INFO -     r13 = 0x000000ad0085f740   r14 = 0xe5e5e5e5e5e5e5e5
[task 2020-02-13T17:40:05.409Z] 17:40:05     INFO -     r15 = 0x00007ffe4775e650   rip = 0x00007ffe3f6e66ba
[task 2020-02-13T17:40:05.409Z] 17:40:05     INFO -     Found by: call frame info
[task 2020-02-13T17:40:05.409Z] 17:40:05     INFO - 11  xul.dll!static mozilla::net::CacheIOThread::ThreadFunc(void*) [CacheIOThread.cpp:dce82130ce121c237ee48a275acde94f87dce505 : 414 + 0x8]
Flags: needinfo?(honzab.moz)

There's a r+ patch which didn't land and no activity in this bug for 2 weeks.
:mayhemer, could you have a look please?
For more information, please visit auto_nag documentation.

Flags: needinfo?(honzab.moz)
Pushed by honzab.moz@firemni.cz:
https://hg.mozilla.org/integration/autoland/rev/b00050ccb953
Keep CacheEntry.mLock when reading its mState to prevent a race, r=michal,necko-reviewers

https://hg.mozilla.org/mozilla-central/rev/b00050ccb953

Status: ASSIGNED → RESOLVED
Closed: 4 years ago
status-firefox80: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla80
Flags: needinfo?(honzab.moz)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: