Give names to Anonymous_interface_timer

RESOLVED FIXED in Firefox 56

Status

()

enhancement
RESOLVED FIXED
2 years ago
3 months ago

People

(Reporter: bevis, Assigned: bevis)

Tracking

(Depends on 1 bug, Regressed 1 bug)

unspecified
mozilla56
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox56 fixed, firefox57 fixed)

Details

Attachments

(5 attachments, 1 obsolete attachment)

Anonymous_interface_timer is #2 unlabeled runnables in current telemetry ranking.
I'd like to fix this by having nsINamed implemented by each subclass of nsITimerCallback to break down this runnable from the ranking.
We could also do some local test at the same time to figure out what the common ones are before having all the subclasses named:
74 in C++:
http://searchfox.org/mozilla-central/search?q=public+nsITimerCallback&case=false&regexp=false&path=
19 in JS:
http://searchfox.org/mozilla-central/search?q=Ci.nsITimerCallback&case=false&regexp=false&path=
(In reply to Bevis Tseng [:bevis][:btseng] from comment #1)
> 19 in JS:
> http://searchfox.org/mozilla-central/search?q=Ci.
> nsITimerCallback&case=false&regexp=false&path=
It's 50+ in JS instead:
http://searchfox.org/mozilla-central/search?q=initWithCallback&case=true&regexp=false&path=
All nsITimerCallbacks in native implementation are named.
I'll do some test locally to see if we can identify the most common unlabeled nsITimerCallbacks.
Posted patch LoggingSplinter Review
Summary of today's trial of unlabeled timers:
Total : 646
UpdateTimerCallback: 168
nsAutoCompleteController: 186
Anonymous_interface_timer: 155
ThrottleTimeoutsCallback: 97
DecoderDoctorDocumentWatcher_timer: 34
nsComposerCommandsUpdater: 5

There are still more than 25% of nsITimerCallback in JS unlabeled. (Assuming that all timer callbacks in native implementation are named properly.)

I'd like to landed the patches of part 1 & part 2 first to see the usage from telemetry and spend more time to figure which nsITimerCallback in JS that increases the count of Anonymous_interface_timer.
Comment on attachment 8888722 [details] [diff] [review]
(v1) Patch Part 1: Move default implementation of SetName() to nsINamed.

This is to remove the redundant implementation in each subclass of nsINamed.
Attachment #8888722 - Flags: review?(wmccloskey)
Comment on attachment 8888723 [details] [diff] [review]
(v1) Patch Part 2: Name nsITimerCallback instances in native implementation.

All native implementation of nsITimerCallback are named in this patch.
Comment 6 shows some analysis after these callbacks are named.

There are still more than 25% of unlabeled nsITimerCallback in JS and there are 59 instances in JS to be identified, BTW. :p

Hence, I'd like to land this patch first for better analysis of these named C++ callback from the telemtry instead of testing them locally and spend more time to identify the unlabeled JS timers locally.

Treeherder result of this patch looks fine:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=bb9a2d531a0a66b1a0104e943377970dcb8096a6
Attachment #8888723 - Flags: review?(wmccloskey)
(In reply to Bevis Tseng [:bevis][:btseng] from comment #6)
> I'd like to landed the patches of part 1 & part 2 first to see the usage
> from telemetry and spend more time to figure which nsITimerCallback in JS
> that increases the count of Anonymous_interface_timer.

After further breaking down today, most of the Anonymous_interface_timer in JS comes from a single place in 
http://searchfox.org/mozilla-central/rev/3a3af33f513071ea829debdfbc628caebcdf6996/browser/components/sessionstore/content/content-sessionStore.js#785
which use the TimerCallback helper provided from Timer.jsm:
http://searchfox.org/mozilla-central/source/toolkit/modules/Timer.jsm#28
4 more bugs are filed to address the analysis of comment 6 and comment 9:
Bug 1384034 - Label UpdateTimerCallback in ServiceWorkerManager
Bug 1384035 - Label nsAutoCompleteController
Bug 1384037 - Label ThrottleTimeoutsCallback in TimeoutManager
Bug 1384041 - Label the use of setTimeout of Timer.jsm in content-sessionStore.js

DecoderDoctorDocumentWatcher_timer and nsComposerCommandsUpdater are pending because they are relatively low.
Maybe we can revisit these 2 if the naming patch is landed.
Comment on attachment 8888722 [details] [diff] [review]
(v1) Patch Part 1: Move default implementation of SetName() to nsINamed.

Review of attachment 8888722 [details] [diff] [review]:
-----------------------------------------------------------------

::: xpcom/threads/nsINamed.idl
@@ +28,5 @@
> +   *
> +   * WARNING: This value will be included in telemetry, so it should
> +   * never contain privacy sensitive information.
> +   */
> +  NS_IMETHOD SetName(const char* aName)

I don't think this is correct. In order for JS->C++ dispatch to work, XPConnect needs to be able to figure out the index of the virtual method being called within the vtable. If you make SetName virtual, and then someone inherits from nsINamed in IDL and has more virtual methods after it, then any calls to those methods from JS will be broken. I suspect this doesn't happen very often, but I still don't think we should do this.

A different way to do this would be to remove SetName entirely. At this point, I think that all runnables get their names in the Runnable constructor anyway. See bug 1378930.
Attachment #8888722 - Flags: review?(wmccloskey) → review-
Comment on attachment 8888723 [details] [diff] [review]
(v1) Patch Part 2: Name nsITimerCallback instances in native implementation.

Review of attachment 8888723 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks!
Attachment #8888723 - Flags: review?(wmccloskey) → review+
Depends on: 1378930
(In reply to Bill McCloskey (:billm) from comment #11)
> Comment on attachment 8888722 [details] [diff] [review]
> (v1) Patch Part 1: Move default implementation of SetName() to nsINamed.
> I don't think this is correct. In order for JS->C++ dispatch to work,
> XPConnect needs to be able to figure out the index of the virtual method
> being called within the vtable. If you make SetName virtual, and then
> someone inherits from nsINamed in IDL and has more virtual methods after it,
> then any calls to those methods from JS will be broken. I suspect this
> doesn't happen very often, but I still don't think we should do this.
> 
> A different way to do this would be to remove SetName entirely. At this
> point, I think that all runnables get their names in the Runnable
> constructor anyway. See bug 1378930.

Thanks for capturing this! I'll move this patch to bug 1378930 to remove the SetName from nsINamed.
Pushed by btseng@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/4b879e41eae3
Name nsITimerCallback instances in native implementation. r=billm
https://hg.mozilla.org/mozilla-central/rev/4b879e41eae3
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla56
The Anonymous_interface_timer is still the top 1 unlabeled runnable from the telemtry even in a single nightly build(20170803134456) which includes the naming patches of this bug and bug 1384041.

Reopen this bug to analyze locally again to figure out what did I miss and try to identify more.

--
Top 50 runnables from the telemtry:
[(u'TimeoutExecutor Runnable(labeled)', 11069475394),
 (u'PVsync::Msg_Notify', 9232292233),
 (u'IdleRunnable', 8851364509),
 (u'CollectorRunner(labeled)', 8229942018),
 (u'AbstractThread::Runner for AutoTaskDispatcher::TaskGroupRunnable(labeled)',
  5398180926),
 (u'AsyncEventDispatcher(labeled)', 3518259321),
 (u'PCompositorBridge::Msg_DidComposite(labeled)', 2215134134),
 (u'LayerActivityTracker(labeled)', 2175264838),
 (u'nsDocument::NotifyIntersectionObservers(labeled)', 2098544915),
 (u'PBrowser::Msg_RealMouseMoveEvent(labeled)', 2056069764),
 (u'CompleteResumeRunnable(labeled)', 2020542104),
 (u'IdleRunnableWrapper for AsyncFreeSnowWhite', 1772645636),
 (u'MediaResource::Destroy(labeled)', 1130175450),
 (u'Anonymous_interface_timer', 1091567148),
 (u'LogMessageRunnable(labeled)', 836313251),
 (u'AbstractThread::Runner for MediaStreamGraphStableStateRunnable(labeled)',
  705898309),
 (u'AbstractThread::Runner for ChannelMediaDecoder::ResourceCallback::NotifyBytesConsumed(labeled)',
  702422699),
 (u'ProgressTracker::AsyncNotifyRunnable(labeled)', 699285177),
 (u'TelemetryIPCAccumulator::IPCTimerFired(labeled)', 661786808),
 (u'dom::PostMessageEvent(labeled)', 652072565),
 (u'HTMLMediaElement::nsAsyncEventRunner(labeled)', 608446516),
 (u'StorageNotifierService::Broadcast(labeled)', 604137580),
 (u'MediaCache::UpdateEvent(labeled)', 601039524),
 (u'nsIDocument::SelectorCache(labeled)', 455058529),
 (u'ProxyReleaseEvent for nsStyleDisplay::mSpecifiedTransform(labeled)',
  445605960),
 (u'dom::PostMessageRunnable(labeled)', 419069881),
 (u'layers::DestroyTextureData(labeled)', 413338804),
 (u'PTexture::Msg___delete__(labeled)', 405442428),
 (u'net::HttpChannelChild::OnTransportAndData(labeled)', 392485428),
 (u'PAPZ::Msg_RequestContentRepaint(labeled)', 362583128),
 (u'PHttpChannel::Msg_DeleteSelf(labeled)', 324120884),
 (u'PHttpChannel::Msg_OnStartRequest(labeled)', 316164429),
 (u'AbstractThread::Runner for MozPromise::ThenValueBase::ResolveOrRejectRunnable(labeled)',
  298624428),
 (u'PContent::Msg_NotifyVisited', 278284019),
 (u'ProxyReleaseEvent for NS_ReleaseOnMainThreadSystemGroup(labeled)',
  224878260),
 (u'PContent::Msg_DispatchLocalStorageChange', 222542787),
 (u'IDecodingTask::NotifyDecodeComplete(labeled)', 219796399),
 (u'PredictorLearnRunnable(labeled)', 214740396),
 (u'XMLHttpRequest(labeled)', 199431772),
 (u'PBrowser::Msg_AsyncMessage(labeled)', 185945976),
 (u'StyleImageRequestCleanupTask', 183242364),
 (u'IdleRequestExecutor', 165839372),
 (u'non-nsINamed ThrottledEventQueue runnable(labeled)', 135201159),
 (u'PContent::Msg_DataStoragePut', 134467723)]
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
nsITimerCallback can be simplified as a JS function according to its IDL definiton.
NameUtils.jsm defines a wrapper of a JS function as a nsITimerCallback with nsINamed implemented, so all the call sites of nsITimer.initWithCallback(callback, ...) could be named by:
nsITimer.initWithCallback(NameUtils.timerCallback("callSite", callback), ...);
Attachment #8894077 - Flags: review?(wmccloskey)
Attachment #8894077 - Attachment description: (v1) Part 3: Name nsITimerCallback instances in JS implementation. → (v1) Patch Part 3: Name nsITimerCallback instances in JS implementation.
I think I would rather try to generate the names automatically if we can. This patch tries to do that. It still allows JS code to implement nsINamed automatically. But if a JS object doesn't QI to nsINamed, then we generate an implementation that returns a reasonable name.

One problem with this approach is that it returns a different nsINamed for each QI. Given how we use nsINamed (i.e., just for generating names), I don't think this should be a problem.
Attachment #8894691 - Flags: review?(mrbkap)
(In reply to Bill McCloskey (:billm) from comment #18)
> Created attachment 8894691 [details] [diff] [review]
> give names to all JS-implemented XPCOM objects
> 
> I think I would rather try to generate the names automatically if we can.
> This patch tries to do that. It still allows JS code to implement nsINamed
> automatically. But if a JS object doesn't QI to nsINamed, then we generate
> an implementation that returns a reasonable name.
> 
> One problem with this approach is that it returns a different nsINamed for
> each QI. Given how we use nsINamed (i.e., just for generating names), I
> don't think this should be a problem.

This is awesome! 
There is only one concern here:
Will the name be easier for us to identify which JS callback is queried if only the function name is provided?
As what I saw when adding patch part 3, the "notify" method of the nsITimerCallback is used several places.
Hence, we might need another patch to implement the nsINamed interface on these JS objects explicitly.
Flags: needinfo?(wmccloskey)
(In reply to Bevis Tseng [:bevis][:btseng] from comment #19)
> This is awesome! 
> There is only one concern here:
> Will the name be easier for us to identify which JS callback is queried if
> only the function name is provided?
> As what I saw when adding patch part 3, the "notify" method of the
> nsITimerCallback is used several places.
> Hence, we might need another patch to implement the nsINamed interface on
> these JS objects explicitly.

m... In addition, some of these functions are anonymous.
We'll have convert them as named functions as well.
Otherwise, we'll still see them as "unknown_JS_function" from the telemetry, won't we?
According to the patch in comment 17, there are 61 call sites of nsITimerCallback::initWithCallback in JS.
Only 20 of them are named functions which could be named automatically.
The rest of them (41) are either a JS object with "notify" function defined or a anonymous JS function which still need some trick like the patch in comment 17 to name them easily.
This fixes some issues based on Bevis's feedback. It includes the filename the script is in and it also looks at non-function stuff like { notify: ... }.
Attachment #8894691 - Attachment is obsolete: true
Attachment #8894691 - Flags: review?(mrbkap)
Flags: needinfo?(wmccloskey)
Attachment #8895014 - Flags: review?(mrbkap)
Comment on attachment 8895014 [details] [diff] [review]
give names to all JS-implemented XPCOM objects, v2

Review of attachment 8895014 [details] [diff] [review]:
-----------------------------------------------------------------

I'm pretty sure that returning strings by value is now safe and non-copying but I'm not 100% sure.

I'd love to see some tests, especially testing edge cases like nested objects leading to primitives and function names with non-ASCII characters in them.

::: js/xpconnect/src/XPCWrappedJSClass.cpp
@@ +471,5 @@
> +        return NS_OK;
> +    }
> +};
> +
> +} // anonymous namespace

Nit: if you ended the anonymous namespace after the declaration of GetFunctionName, it wouldn't need to be marked static.
Attachment #8895014 - Flags: review?(mrbkap) → review+
(In reply to Bill McCloskey (:billm) from comment #22)
> Created attachment 8895014 [details] [diff] [review]
> give names to all JS-implemented XPCOM objects, v2
> 
> This fixes some issues based on Bevis's feedback. It includes the filename
> the script is in and it also looks at non-function stuff like { notify: ...
> }.

Thanks! This is really nice!
Comment on attachment 8894077 [details] [diff] [review]
(v1) Patch Part 3: Name nsITimerCallback instances in JS implementation.

This has been covered by the patch in comment 22!
Attachment #8894077 - Flags: review?(wmccloskey)
Update the status of latest runnable analysis:
The runnable of "Anonymous_interface_timer" dropped to #230 from the top unlabeled list recently.
However, the call site of "setTimeout() in Timer.jsm" rises up to #20 unlabeled runnable in the latest telemetry analysis.

I'll see if I could break down this use case in advance locally.
Pushed by wmccloskey@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/c0c52209c8f2
Compute names for all JS-implemented XPCOM objects (r=mrbkap)
Pushed by wmccloskey@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/e46068fd54db
Compute names for all JS-implemented XPCOM objects (r=mrbkap)
https://hg.mozilla.org/mozilla-central/rev/e46068fd54db
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → FIXED
I think if we remove the code here:
http://searchfox.org/mozilla-central/rev/8d084472a955c9ef0f523c743cbad2460efd7688/toolkit/modules/Timer.jsm#35-50
and pass aCallback directly to the timer, then the JS labeling code will kick in and we'll get more useful data.
(In reply to Bill McCloskey (:billm) from comment #31)
> I think if we remove the code here:
> http://searchfox.org/mozilla-central/rev/
> 8d084472a955c9ef0f523c743cbad2460efd7688/toolkit/modules/Timer.jsm#35-50
> and pass aCallback directly to the timer, then the JS labeling code will
> kick in and we'll get more useful data.

I was thinking about that but there is one more operation to remove the timer from |gTimerTable| before calling the aCallback which avoids us to do this:
https://hg.mozilla.org/mozilla-central/annotate/380817d573cd/toolkit/modules/Timer.jsm#l29

Not sure if there is anyway to bind both Function.name and especially it's script name from JS which is more helpful for the anonymous one to the name property at:
https://hg.mozilla.org/mozilla-central/annotate/ef75a524b850/toolkit/modules/Timer.jsm#l48
Component: DOM → DOM: Core & HTML
Regressions: 1543845
You need to log in before you can comment on or make changes to this bug.