1498643 - Measure mutex contention rates

Status: NEW

(Core :: XPCOM, enhancement)

Description

[Randell Jesup [:jesup] (needinfo me)]

It would be nice to measure (and flag in automation?) mutex contention rates; though this can't be done easily without some impact on performance.  The impact might not be measurable, though.

Note that average contention rate/time isn't very interesting; rate/acquire is more interesting, but even more so bursts of contention (high contention for a time), and total number of locks/contentions.

Comment 1

[Randell Jesup [:jesup] (needinfo me)]

Attachment: Hacky patch to dump contention rates in non-e10s (or with sandboxing off) NOT FOR CHECKIN

Comment 2

[Randell Jesup [:jesup] (needinfo me)]

Attachment: Lock run with cnn, arstechnica, small gdoc

Highlights: 
CNN, ArsTechnica, smaller gdoc:
Mutex ThrottledEventQueue: 64/2543 ( 2.517%)
Mutex WorkerPrivate Mutex: 29/2433 ( 1.192%)
Mutex [nsThreadPool.mMutex]: 335/6093 ( 5.498%)
Mutex [nsThreadPool.mMutex]: 38/1847 ( 2.057%)
Mutex BackgroundHangManager: 54063/1556358 ( 3.474%)
Mutex MediaTimer Monitor: 3/101 ( 2.970%)


Mozilla Login, Large (150 pages) gdoc and some typing
Mutex DecodePoolImpl: 18/694 ( 2.594%)
Mutex mozilla.resistFingerprinting.LRUCache: 0/42292 ( 0.000%) (no contention, but a lot of traffic)
Mutex BackgroundHangManager: 17829/361221 ( 4.936%)

Comment 3

[Randell Jesup [:jesup] (needinfo me)]

Note if using the hack, it will only dump main process unless you turn off e10s or sandboxing
It uses fprintf(stderr...)

Comment 4

[Randell Jesup [:jesup] (needinfo me)]

Attachment: Longer session with watching several videos on cnn and an ad on ars

Highest use:
Mutex ProtocolEventTargetMutex: 0/18612 ( 0.000%)
Mutex nsUrlClassifierPrefixSet.mLock: 0/19263 ( 0.000%)
Mutex nsUrlClassifierPrefixSet.mLock: 0/19263 ( 0.000%)
Mutex nsUrlClassifierPrefixSet.mLock: 0/19263 ( 0.000%)
Mutex nsUrlClassifierPrefixSet.mLock: 0/19263 ( 0.000%)
Mutex nsUrlClassifierPrefixSet.mLock: 0/19263 ( 0.000%)
Mutex nsUrlClassifierPrefixSet.mLock: 0/19299 ( 0.000%)
Mutex VariableLengthPrefixSet.mLock: 0/19299 ( 0.000%)
Mutex nsUrlClassifierPrefixSet.mLock: 0/19300 ( 0.000%)
Mutex nsUrlClassifierPrefixSet.mLock: 0/19300 ( 0.000%)
Mutex VariableLengthPrefixSet.mLock: 0/19301 ( 0.000%)
Mutex VariableLengthPrefixSet.mLock: 0/19301 ( 0.000%)
Mutex nsUrlClassifierPrefixSet.mLock: 0/19302 ( 0.000%)
Mutex TaskQueue::Queue: 60/19656 ( 0.305%)
Mutex Atom Sub-Table Lock: 0/19661 ( 0.000%)
Mutex nsUrlClassifierPrefixSet.mLock: 0/22053 ( 0.000%)
Mutex nsUrlClassifierPrefixSet.mLock: 0/22074 ( 0.000%)
Mutex Atom Sub-Table Lock: 0/23396 ( 0.000%)
Mutex Atom Sub-Table Lock: 0/24183 ( 0.000%)
Mutex ThreadEventQueue: 17/24306 ( 0.070%)
Mutex RefreshTickLock: 0/25119 ( 0.000%)
Mutex ThreadEventQueue: 238/25161 ( 0.946%)
Mutex transaction lock: 0/26777 ( 0.000%)
Mutex Atom Sub-Table Lock: 0/27634 ( 0.000%)
Mutex CurrentVRTaskMonitor: 0/27772 ( 0.000%)
Mutex CurrentCompositeTaskMonitor: 7/27830 ( 0.025%)
Mutex mozilla.ipc.MessageChannel.mMonitor: 623/27908 ( 2.232%)
Mutex TaskQueue::Queue: 373/33900 ( 1.100%)
Mutex Atom Sub-Table Lock: 0/34522 ( 0.000%)
Mutex MediaCache.mMonitor: 286/35346 ( 0.809%)
Mutex ThreadEventQueue: 131/37475 ( 0.350%)
Mutex TaskQueue::Queue: 33/38319 ( 0.086%)
Mutex mozilla.ipc.MessageChannel.mMonitor: 527/40022 ( 1.317%)
Mutex AudioStream: 12/42348 ( 0.028%)
Mutex TaskQueue::Queue: 90/43095 ( 0.209%)
Mutex TaskQueue::Queue: 30/44535 ( 0.067%)
Mutex nsSocketTransport.mLock: 0/45076 ( 0.000%)
Mutex nsSocketTransport.mLock: 0/56257 ( 0.000%)
Mutex [nsThreadPool.mMutex]: 113/70531 ( 0.160%)
Mutex mozilla.ipc.MessageChannel.mMonitor: 351/75653 ( 0.464%)
Mutex CacheIOThread: 1704/108636 ( 1.569%)
Mutex [nsThreadPool.mMutex]: 1095/114086 ( 0.960%)
Mutex TaskQueue::Queue: 66/137390 ( 0.048%)
Mutex TaskQueue::Queue: 130/142681 ( 0.091%)
Mutex nsTimerImpl::mMutex: 0/329547 ( 0.000%)
Mutex mozilla.resistFingerprinting.LRUCache: 0/341390 ( 0.000%)
Mutex nsTimerImpl::mMutex: 0/380966 ( 0.000%)
Mutex [nsThreadPool.mMutex]: 19207/456714 ( 4.205%)
Mutex TimerEventAllocator: 42/458486 ( 0.009%)
Mutex TimerThread.mMonitor: 8567/1007883 ( 0.850%)
Mutex BackgroundHangManager: 114106/2968441 ( 3.844%)

Comment 5

[Randell Jesup [:jesup] (needinfo me)]

217K mutexes; ~160K of them MozPromise's used in video playback

Comment 6

[Randell Jesup [:jesup] (needinfo me)]

Attachment: Hacky patch to dump contention rates in non-e10s (or with sandboxing off) NOT FOR CHECKIN

updated to capture lock contention on Windows

Comment 7

[Randell Jesup [:jesup] (needinfo me)]

Note: it also now dumps the contention to XPCOM logs (MOZ_LOG=Mutex:4) as well as fprintf (which perhaps can be dropped).  Note that many mutexes are destroyed too late in Content process shutdown to get logged (and in Opt builds we may just kill the process after it's disconnected).  So you can measure contention in e10s, but you may miss some stuff - but in non-e10s you'll miss some IPC locks

Comment 8

[Randell Jesup [:jesup] (needinfo me)]

Attachment: WIP: Bug 1498643: Mutex Contention hack