JS_TriggerOperationCallback is being called during SunSpider tests

RESOLVED FIXED

Status

()

Core
JavaScript Engine
RESOLVED FIXED
8 years ago
8 years ago

People

(Reporter: Robert Sayre, Assigned: Igor Bukanov)

Tracking

unspecified
x86
Mac OS X
Points:
---

Firefox Tracking Flags

(blocking2.0 betaN+)

Details

(Whiteboard: fixed-in-tracemonkey)

Attachments

(2 attachments, 2 obsolete attachments)

(Reporter)

Description

8 years ago
I found that we occasionally get very high variance on some SunSpider tests. Usually in string-tagcloud and string-validate-input, sometimes in regex-dna.

Here are the individual scores from a recent SunSpider run:

  string-tagcloud:       [81,78,79,79,160,79,170,78,78,162]
  string-validate-input: [113,21,108,21,21,21,21,21,21,22]

We get a tagcloud average score of 104.4ms, when we should get an 80 or so. We get a validate-input average score of 39.0ms when we should get a 21 or so.

I've discovered that JS_TriggerOperationCallback is being called repeatedly during some runs of the test, and that matches up with the outlier test scores. I will attach a log.
(Reporter)

Updated

8 years ago
Assignee: general → igor
(Reporter)

Comment 1

8 years ago
Created attachment 458847 [details]
Log of test run

I added printfs to JS_TriggerOperationCallback, JS_GC, and CycleCollector::BeginCollection. I also added printfs to the SunSpider harness to record starting and stopping of tests.

The log shows occasional bursts of 32 calls to JS_TriggerOperationCallback, while tests are executing.
(Reporter)

Updated

8 years ago
blocking2.0: --- → betaN+
(Reporter)

Comment 2

8 years ago
Adding more windows gets some really bad stuff to happen:

"string-validate-input":[24,21,20,21,20,21,21,375,21,20]

a 350ms delay is going to be user visible jankiness, so we have to fix this for sure.
(Reporter)

Comment 3

8 years ago
here's where it comes from:

#0  JS_TriggerOperationCallback (cx=0x116b83e80) at /Users/sayrer/dev/tracemonkey/js/src/jsapi.cpp:4862
#1  in js_TriggerAllOperationCallbacks at /Users/sayrer/dev/tracemonkey/js/src/jscntxt.cpp:1939
#2  in JSContext::checkMallocGCPressure at /Users/sayrer/dev/tracemonkey/js/src/jscntxt.cpp:2193
#3  in JSScope::create at jscntxt.h:1982
#4  in js_GetMutableScope

mrbkap says js_TriggerAllOperationCallbacks is bogus
(In reply to comment #3)
> mrbkap says js_TriggerAllOperationCallbacks is bogus

So, in particular: the operation callback API is mostly timing based; we only added the memory stuff in later. Further, the memory stuff is more runtime- or application-wide rather than context based. So, we end up calling an API hook on contexts that are not in requests (which, in itself, is odd) and doing the exact work that we want to do (sending memory pressure signals) N times over (where N is the number of contexts in existence). Is there any reason we couldn't introduce a second hook lowMemory or only call the branch callback once per memory pressure notification?
(Assignee)

Comment 5

8 years ago
(In reply to comment #4)
> So, we end up calling an API hook
> on contexts that are not in requests (which, in itself, is odd) and doing the
> exact work that we want to do (sending memory pressure signals) N times over
> (where N is the number of contexts in existence).

A context outside a request can enter or leave the request at any time. If, for example, a web worker needs a GC run on the main thread, triggering callback on all contexts for the main thread ensures that that GC would run. But for the typical case of the GC request from the main thread this is suboptimal. This can be fixed via either of:

1. Moving the callback to JSThread and the flag that triggers it. This avoids multiple triggers of the callback on the main thread but may require some adjustments in the API. For example, JSThread is not exposed currently but we may need to provide something like OnNewThread notification that can be used to setup the callback. 

2. If the above is not desirable, for at least the current thread the callback can be triggered for cx in the request. Then it would be necessary to ensure execution of the callback before that cx leaves or suspends its request. Doing that for non-current thread is problematic as other threads could be outside a request.

> Is there any reason we
> couldn't introduce a second hook lowMemory?

Such hock still would need to trigger the callback to suspend the requests for all running contexts so we end up again in this bug.
(Assignee)

Comment 6

8 years ago
(In reply to comment #4)
> So, in particular: the operation callback API is mostly timing based; we only
> added the memory stuff in later.

The callback is also scheduled when the GC allocator detects on trace that the GC heap size reaches the maximum. As the traced code could not tolerate the last-ditch GC, the solution for that was to ask the trace to leave ASAP via the callback trigger.
(Assignee)

Comment 7

8 years ago
Created attachment 459015 [details] [diff] [review]
v1

The patch moves operationCallbackFlag into JSThreadData while keeping the callback itself in JSContext. This way no API changes are necessary while  js_TriggerAllOperationCallbacks needs to eunumerate over few JSThreadData instances. Note that traced code does not need to do an extra cx->thread load to get the flag. The trace is thread-local so it can embed JSThreadData pointer directly.
Any speedup from the constant address load on trace?

/be
(Assignee)

Comment 9

8 years ago
(In reply to comment #8)
> Any speedup from the constant address load on trace?

I see no changes. This is not surprising since the old way of checking *cx is not much different from doing *const_address as cx is likely available in a register.
(Reporter)

Updated

8 years ago
Depends on: 580803
(Assignee)

Comment 10

8 years ago
Created attachment 459403 [details] [diff] [review]
v2

Patch that passes tests.
Attachment #459015 - Attachment is obsolete: true
Attachment #459403 - Flags: review?(mrbkap)

Comment 11

8 years ago
Comment on attachment 459403 [details] [diff] [review]
v2

I want to look at this too
Attachment #459403 - Flags: review?(gal)

Comment 12

8 years ago
Comment on attachment 459403 [details] [diff] [review]
v2

Looks great.
Attachment #459403 - Flags: review?(gal) → review+
Comment on attachment 459403 [details] [diff] [review]
v2

Nit: s/jsint/int32/ just to line up with Nanojit a bit better?

/be
(Reporter)

Comment 14

8 years ago
Comment on attachment 459403 [details] [diff] [review]
v2

This patch doesn't seem to help with variability in SunSpider.
Comment on attachment 459403 [details] [diff] [review]
v2

>diff --git a/js/src/jsapi.cpp b/js/src/jsapi.cpp
>-    JS_ATOMIC_SET(&cx->operationCallbackFlag, 1);
>+    JSThreadData *td;
>+#ifdef JS_THREADSAFE
>+    JSThread *thread = cx->thread;
>+    if (!thread)
>+        return;
>+    td = &thread->data;
>+#else
>+    td = JS_THREAD_DATA(cx);
>+#endif
>+
>+    JS_THREAD_DATA(cx)->triggerOperationCallback();

Either we don't need |td|, or you should use td instead of JS_THREAD_DATA on the last line here.
Attachment #459403 - Flags: review?(mrbkap) → review+
(Assignee)

Comment 16

8 years ago
(In reply to comment #15)
> Either we don't need |td|, or you should use td instead of JS_THREAD_DATA on
> the last line here.

Nice catch, thanks!
(Assignee)

Comment 17

8 years ago
(In reply to comment #14)
> Comment on attachment 459403 [details] [diff] [review]
> v2
> 
> This patch doesn't seem to help with variability in SunSpider.

But that can be due to the GC call. Could you check if the GC runs at all?
(Assignee)

Comment 18

8 years ago
(In reply to comment #17)
> But that can be due to the GC call. Could you check if the GC runs at all?

I mean that in the comment 0 you mentioned that JS_GC was instrumented while the callback implementation calls js_GC.
(Assignee)

Comment 19

8 years ago
Created attachment 459589 [details] [diff] [review]
v3

In v2 I have missed that js_NudgeOtherContexts and NudgeThread are no longer necessary. This version fixes that.
Attachment #459403 - Attachment is obsolete: true
Attachment #459589 - Flags: review?(mrbkap)

Updated

8 years ago
Attachment #459589 - Flags: review?(mrbkap) → review+
(Assignee)

Comment 20

8 years ago
http://hg.mozilla.org/tracemonkey/rev/cb3ed8e233b8
Whiteboard: fixed-in-tracemonkey
http://hg.mozilla.org/mozilla-central/rev/cb3ed8e233b8

Further work is going on in bug 598650
Status: NEW → RESOLVED
Last Resolved: 8 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.