Closed Bug 1333984 Opened 3 years ago Closed Last year

Analyze runnable frequency telemetry from bug 1331804

Categories

(Core :: DOM: Core & HTML, defect, P2)

defect

Tracking

()

RESOLVED WONTFIX

People

(Reporter: billm, Assigned: billm)

References

Details

I would like to look at which runnables run most often. Might as well see which ones take the longest too, although that's not as relevant to the labeling work.
Here are results from last weekend:
https://gist.github.com/bill-mccloskey/41130211c988151cbb1bef2735f00953
I divided the frequency numbers by one million so they're a little easier to compare.

Here are the top few, with annotations. The ones without any comment are unlabeled runnables without a bug filed. I made sure the top ten have bugs filed.

 (u'PCompositorBridge::Msg_DidComposite', 36314),  # bug 1333968
 (u'PVsync::Msg_Notify', 19854),                   # bug 1333962
 (u'anonymous runnable', 18029),                   # this is the unknown bucket
 (u'setInterval', 17212),                          # already labeled
 (u'setTimeout', 13120),                           # already labeled
 (u'AbstractThread::Runner', 10603),               # already labeled (I think?) by bug 1314833
 (u'non-nsINamed runnable', 4842),                 # another unknown bucket
 (u'PHttpChannel::Msg_OnTransportAndData', 3485),  # already labeled
 (u'nsInputStreamReadyEvent', 3182),               # just filed bug 1335601
 (u'PBrowser::Msg_RealMouseMoveEvent', 2523),      # already labeled
 (u'CCTimerFired', 2419),
 (u'PostMessageEvent', 2408),                      # already labeled
 (u'Anonymous interface timer', 2141),             # another unknown bucket
 (u'LayerActivityTracker', 1964),
 (u'ProxyReleaseEvent', 1874),                     # bug 1333974 (mostly?)
 (u'PJavaScript::Msg_Get', 1867),
 (u'AsyncEventDispatcher', 1707),                  # already labeled
 (u'PHttpChannel::Msg_OnProgress', 1229),          # already labeled
 (u'LogMessageRunnable', 1057),                    # already labeled
 (u'Anonymous callback timer', 954),               # another unknown bucket
 (u'PTexture::Msg___delete__', 887),
 (u'HTMLMediaElement::DispatchAsyncEvent', 796),   # already labeled
 (u'PHttpChannel::Msg_SetPriority', 588),          # already labeled
 (u'PBrowser::Msg_AsyncMessage', 506),             # already labeled
 (u'Anonymous timer', 488),                        # another unknown bucket
> (u'ProxyReleaseEvent', 1874),                     # bug 1333974 (mostly?)
Yeah, one drawback of my patch is that it improves the labeling, but not the names. Specifying a name at the call site might be a little annoying to implement, and I'm not sure what the naming schema should be.
(In reply to Andrew McCreight [:mccr8] from comment #2)
> > (u'ProxyReleaseEvent', 1874),                     # bug 1333974 (mostly?)
> Yeah, one drawback of my patch is that it improves the labeling, but not the
> names. Specifying a name at the call site might be a little annoying to
> implement, and I'm not sure what the naming schema should be.

You can use SetName to change the runnable name. That could happen in ::ProxyRelease. It could take a name parameter.
The information in comment comment 1 seems not accurate to me if the call site of nsIEventTarget::Dispatch() was not taken into account in bug 1331804.
Ideally, it will be more accurate to have all runnable named by
1. Replacing all NewRunnable with the one in bug 1333997.
2. Naming each concrete Runnable class in its constructor.

In addition, it seems that we didn't filter out the main-thread runnables of parent process in nsThread::ProcessNextEvent() in bug 1331804.

Shall we fix these and then run the analysis again?
Flags: needinfo?(wmccloskey)
(In reply to Bevis Tseng[:bevistseng][:btseng] from comment #4)
> The information in comment comment 1 seems not accurate to me if the call
> site of nsIEventTarget::Dispatch() was not taken into account in bug 1331804.
> Ideally, it will be more accurate to have all runnable named by
> 1. Replacing all NewRunnable with the one in bug 1333997.
> 2. Naming each concrete Runnable class in its constructor.
Oh, "non-nsINamed runnable", and "Anonymous XXX timer" in comment 1 has to be addressed as well.
(In reply to Bevis Tseng[:bevistseng][:btseng] from comment #4)
> The information in comment comment 1 seems not accurate to me if the call
> site of nsIEventTarget::Dispatch() was not taken into account in bug 1331804.
> Ideally, it will be more accurate to have all runnable named by
> 1. Replacing all NewRunnable with the one in bug 1333997.
> 2. Naming each concrete Runnable class in its constructor.
> 
> In addition, it seems that we didn't filter out the main-thread runnables of
> parent process in nsThread::ProcessNextEvent() in bug 1331804.
> 
> Shall we fix these and then run the analysis again?

Per offline discussion, the list in comment 1 shall be good enough to keep labeling tasks moving. We could revisit this later if needed.
Flags: needinfo?(wmccloskey)
Well, I do want to try to collect more data, so I'll keep this on me for now.
Flags: needinfo?(wmccloskey)
Here are the top unlabeled runnables in a quick test run that I did:

   1553 Running anon(/home/billm/ws/gecko/dom/base/nsDocument.cpp:1244)
    685 Running anon(/home/billm/ws/gecko/image/IDecodingTask.cpp:90)
    662 Running anon(/home/billm/ws/gecko/js/xpconnect/src/XPCJSContext.cpp:177)
    397 Running anon(/home/billm/ws/gecko/image/IDecodingTask.cpp:56)
    297 Running anon(/home/billm/ws/gecko/dom/storage/Storage.cpp:236)
    290 Running anon(/home/billm/ws/gecko/parser/html/nsHtml5RefPtr.h:66)
    209 Running anon(/home/billm/ws/gecko/image/ProgressTracker.cpp:195)
    113 Running anon(/home/billm/ws/gecko/layout/base/PresShell.cpp:6224)
     90 Running anon(/home/billm/ws/gecko/layout/base/nsDocumentViewer.cpp:2145)
     78 Running anon(/home/billm/ws/gecko/image/imgRequestProxy.cpp:352)
     72 Running anon(/home/billm/ws/gecko/dom/media/mediasource/SourceBuffer.cpp:362)
     70 Running anon(/home/billm/ws/gecko/parser/html/nsHtml5StreamParser.cpp:1375)
     67 Running anon(/home/billm/ws/gecko/dom/xbl/nsBindingManager.cpp:352)

This still misses a lot of stuff (timers and things dispatched by Dispatch), so I'll keep working on it next week.
I filed bug 1339224 and bug 1339289 to improve the data we're getting here.
Flags: needinfo?(wmccloskey)
Now that more naming bugs have landed, I re-ran my analysis:
https://gist.github.com/bill-mccloskey/41130211c988151cbb1bef2735f00953

"anonymous runnable" is still disappointingly high, but it has gone down. We now also have a classification of runnables based on whether they're labeled. Labeled runnables have names ending in "(labeled)". Here's the new top list:

[(u'PCompositorBridge::Msg_DidComposite', 24298),
 (u'setTimeout(labeled)', 12796),
 (u'PVsync::Msg_Notify', 12042),
 (u'setInterval(labeled)', 11911),
 (u'AbstractThread::Runner(labeled)', 10056),
 (u'anonymous runnable', 9801),
 (u'PHttpChannel::Msg_OnTransportAndData(labeled)', 2537),
 (u'non-nsINamed runnable', 2508),
 (u'nsInputStreamReadyEvent', 2270),
 (u'AsyncEventDispatcher(labeled)', 2241),
 (u'PBrowser::Msg_RealMouseMoveEvent(labeled)', 2044),
 (u'CCTimerFired(labeled)', 2018),
 (u'LayerActivityTracker', 1396),
 (u'AsyncFreeSnowWhite', 1216),
 (u'PJavaScript::Msg_Get', 1184),
 (u'Anonymous_interface_timer', 1126),
 (u'PostMessageEvent(labeled)', 1036),
 (u'ProxyReleaseEvent', 1015),
 (u'PHttpChannel::Msg_OnProgress(labeled)', 938),
 (u'LogMessageRunnable(labeled)', 850),
 (u'MediaStreamGraphStableStateRunnable', 774),
 (u'HTMLMediaElement::DispatchAsyncEvent(labeled)', 690),
 (u'PTexture::Msg___delete__', 671),
 (u'TelemetryIPCAccumulator::IPCTimerFired', 616),
 (u'PHttpChannel::Msg_SetPriority(labeled)', 439),
 (u'ChannelMediaResource::DoNotifyDataReceived', 384),
 (u'PHttpChannel::Msg_DeleteSelf(labeled)', 373),
 (u'PHttpChannel::Msg_OnStopRequest(labeled)', 361),
 (u'PHttpChannel::Msg_OnStartRequest(labeled)', 361),
 (u'Anonymous_observer_timer', 357),
 (u'SHMEM_DESTROYED_MESSAGE', 326),
 (u'PAPZ::Msg_RequestContentRepaint', 316),
 (u'ProgressTracker::AsyncNotifyRunnable', 307),
 ...]
I re-ran the analysis again. Unfortunately, it's not any better in terms of anonymous runnables.
https://gist.github.com/bill-mccloskey/897f18b79adf252a820d875558d76d9e

[(u'PCompositorBridge::Msg_DidComposite', 21802),
 (u'setInterval(labeled)', 13635),
 (u'PVsync::Msg_Notify', 12420),
 (u'AbstractThread::Runner(labeled)', 10636),
 (u'setTimeout(labeled)', 7854),
 (u'anonymous runnable', 6515),
 (u'Canceled_timer(labeled)', 4041),
 (u'non-nsINamed runnable', 2508),
 (u'CCTimerFired(labeled)', 2271),
 (u'MediaCache::UpdateEvent(labeled)', 2159),
 (u'IMENotificationSender', 2149),
 (u'PHttpChannel::Msg_OnTransportAndData(labeled)', 2121),
 (u'AsyncEventDispatcher(labeled)', 1991),
 (u'nsInputStreamReadyEvent', 1875),
 (u'PBrowser::Msg_RealMouseMoveEvent(labeled)', 1645),
 (u'LayerActivityTracker', 1402),
 (u'PJavaScript::Msg_Get', 1188),
 (u'AsyncFreeSnowWhite', 1084),
 (u'PostMessageEvent(labeled)', 1001),
 (u'ProxyReleaseEvent', 851),
 ...]
Bill, is this covered in all the other meta bugs?
Flags: needinfo?(wmccloskey)
(In reply to Milan Sreckovic [:milan] from comment #12)
> Bill, is this covered in all the other meta bugs?

Do you mean, "Are all the runnables listed here covered by bugs?" It depends on how far down the list you go. But the top ones all have bugs or are already fixed, except for the CPOW stuff (PJavaScript::Foo), which will be gone in 57 when legacy extensions go away.
Flags: needinfo?(wmccloskey)
Priority: -- → P1
I think we're good for 57 here so marking as P2 to indicate we'll do this (again) in the coming months.
Priority: P1 → P2
We can just not do this, right, Nika?
Flags: needinfo?(nika)
Status: NEW → RESOLVED
Closed: Last year
Flags: needinfo?(nika)
Resolution: --- → WONTFIX
Component: DOM → DOM: Core & HTML
You need to log in before you can comment on or make changes to this bug.