1334194 - Don't differentiate between thread kinds in the trace logger

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[Brian Hackett [Laid off!]]

Attachment: patch

Currently, the trace logger differentiates between activity occurring on runtime main threads vs. other threads.  After bug 1323066 there will no longer be a single main thread in a runtime, and there won't really be a permanent (i.e. fixed per thread) distinction between foreground and background threads (where a foreground thread has exclusive access to some zone group and a background thread doesn't).

This patch removes the distinction between different kinds of threads from the trace logger.  Since each thread interacting with the JS engine should have a JSContext (with a few exceptions like threads calling JS_RequestInterruptCallback), this just uses the trace logger on the context instead of a thread id map.  I also had to fix some places where we were running things on helper threads without actually having a JSContext for the thread.

Comment 1

[Brian Hackett [Laid off!]]

Attachment: patch

This is the same patch as before except that the helper threads changes have been removed.  They are not necessary after bug 1334845.

Comment 2

[Hannes Verschore [:h4writer]]

Sorry for the bad timing. But I had to land a quick fix in bug 1334129. As a result this won't apply cleanly anymore. Though I don't think it changes the logic too much. The mainThreadLoggers now became a LinkedList.

My distinction between mainthread and helperthread was more to make it possible for people to only log the (js) executing thread VS compilation thread / GC / parsing thread. Is there another way to make this distinction? Making it possible for people to log only the "executing thread" and not be overwhelmed with information?

Comment 3

[Hannes Verschore [:h4writer]]

Comment on attachment 8831483 [details] [diff] [review]
patch

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

No big objects against this patch. If this doesn't cause slowdowns when TraceLogger is disabled?

::: js/src/vm/TraceLogging.cpp
@@ +815,5 @@
>              printf(
>                  "\n"
>                  "usage: TLOPTIONS=option,option,option,... where options can be:\n"
>                  "\n"
> +                "  EnableThread            Start logging each thread immediately.\n"

Can we still somehow discriminate between "executing thread" and "background running thread" and how?

@@ +901,4 @@
>  {
>      MOZ_ASSERT(initialized);
> +
> +    JSContext* cx = TlsContext.get();

How slow/fast is this? This function is quite hot. That is the reason that on the main thread I put it in cx->traceLogger.

Comment 4

[Brian Hackett [Laid off!]]

Attachment: patch

Updated patch.  This restores the main thread / helper thread distinction, and allows TraceLoggerForCurrentThread to take an optional cx, which if specified avoids the TLS lookup.

The bigger news though is that I noticed that thread local trace logger state is embedded in baseline/ion jitcode --- both TraceLoggerThread pointers, but also pointers to the payload information stored on the thread.  These behaviors aren't compatible with a multithreaded runtime.  I fixed the former by loading the current thread's logger via the current JSContext, and the latter by moving the event payload storage from TraceLoggerThread to the process wide TraceLoggerThreadState, protecting it with the existing trace logger lock.

Comment 5

[Hannes Verschore [:h4writer]]

Comment on attachment 8832438 [details] [diff] [review]
patch

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

Thanks for doing this!

Not sure I like that we now are locking every time we need to "getOrCreateEventPayload". I wanted tracelogger to not interfere on different threads.
But I cannot think of a better solution, given that contexts will change from one to another Thread we need to have 1 pool with all textids.
Also the calls should be very quickly and not happen often. As a result there should be almost no contention on the locks.

Is there are reason you have been adding the "use()". They shouldn't be needed. Are you encountering issues with that?

(I would like to see an updated patch, before r+ ing it. But I think it looks good with the issues addressed.)

::: js/src/vm/HelperThreads.cpp
@@ +1610,1 @@
>      }

A helper thread will always stay a helper thread, right? It will not suddenly start executing JS code, right?

::: js/src/vm/TraceLogging.cpp
@@ +357,4 @@
>      TextIdHashMap::AddPtr p = textIdPayloads.lookupForAdd(textId);
>      if (p) {
>          MOZ_ASSERT(p->value()->textId() == textId); // Sanity check.
> +        p->value()->use();

The definition is that getOrCreateEventPayload returns a payload that has no uses. The EventText takes care of mark it being used. This line should get removed. Else we will never delete it.

@@ +367,5 @@
>  
>      if (!textIdPayloads.add(p, textId, payload))
>          return nullptr;
>  
> +    payload->use();

ditto

@@ +380,4 @@
>      PointerHashMap::AddPtr p = pointerMap.lookupForAdd((const void*)text);
>      if (p) {
>          MOZ_ASSERT(p->value()->textId() < nextTextId); // Sanity check.
> +        p->value()->use();

ditto

@@ -385,5 @@
> -    auto guardInternalStopEvent = mozilla::MakeScopeExit([&] {
> -        stopEvent(TraceLogger_Internal);
> -        if (payload)
> -            payload->release();
> -    });

This makes sure the uses are 0 upon exiting this code. We need this.

@@ -405,5 @@
>          payload = nullptr;
>          return nullptr;
>      }
>  
> -    // Temporarily mark the payload as used. To make sure it doesn't get GC'ed.

This comment still makes sense

@@ +433,5 @@
>      if (ptr) {
>          p = pointerMap.lookupForAdd(ptr);
>          if (p) {
>              MOZ_ASSERT(p->value()->textId() < nextTextId); // Sanity check.
> +            p->value()->use();

Remove this please.

@@ -452,5 @@
> -        stopEvent(TraceLogger_Internal);
> -        if (payload)
> -            payload->release();
> -    });
> -

This needs to stay.

@@ -483,5 @@
>          payload = nullptr;
>          return nullptr;
>      }
>  
> -    // Temporarily mark the payload as used. To make sure it doesn't get GC'ed.

needs to stay

@@ +558,5 @@
>  #endif
>  
> +    if (graph.get()) {
> +        for (uint32_t otherId = graph->nextTextId(); otherId <= id; id++)
> +            graph->addTextId(otherId, maybeEventText(id));

Clever!

addTextId currently expect the ids in order. Though as follow-up bug we could adjust the output a little bit and report them out of order. that would allow to only log the relevant textids. That would mean the JS code will need to know this different encoding. Though every log file has a typeformat encoding string. We could just specify a new type and handle that a little bit different in the engine.

Can you open a follow-up bug for that?

Also if "nextTextId != id" can you log a start and stop for "TraceLogger_Internal" to indicate that spewing this information isn't part of the actual running?

Comment 6

[Brian Hackett [Laid off!]]

(In reply to Hannes Verschore [:h4writer] from comment #5)
> Is there are reason you have been adding the "use()". They shouldn't be
> needed. Are you encountering issues with that?

When TraceLoggerThreadState is multithreaded, any payload with zero uses is at risk of being collected when the logger state lock is not held.  Since all the users of getOrCreateEventPayload are TraceLoggerEvent constructors which immediately use() the payload, the changes here have the effect of moving that use() inside the lock under getOrCreateEventPayload.

Comment 7

[Hannes Verschore [:h4writer]]

(In reply to Brian Hackett (:bhackett) from comment #6)
> (In reply to Hannes Verschore [:h4writer] from comment #5)
> > Is there are reason you have been adding the "use()". They shouldn't be
> > needed. Are you encountering issues with that?
> 
> When TraceLoggerThreadState is multithreaded, any payload with zero uses is
> at risk of being collected when the logger state lock is not held.  Since
> all the users of getOrCreateEventPayload are TraceLoggerEvent constructors
> which immediately use() the payload, the changes here have the effect of
> moving that use() inside the lock under getOrCreateEventPayload.

Good point.

In that case the following also needs to get adjusted:
http://searchfox.org/mozilla-central/source/js/src/vm/TraceLogging.cpp#1104
The release() needs to happen during the lock also.

And in the constructor of TraceLoggerEvent we need to remove the use().
http://searchfox.org/mozilla-central/source/js/src/vm/TraceLogging.cpp#1097 among others

Comment 8

[Brian Hackett [Laid off!]]

(In reply to Hannes Verschore [:h4writer] from comment #7)
> In that case the following also needs to get adjusted:
> http://searchfox.org/mozilla-central/source/js/src/vm/TraceLogging.cpp#1104
> The release() needs to happen during the lock also.

It isn't required to hold the lock while use()'ing or release()'ing a payload without holding the lock --- the patch changes the use count to be atomic.  The race that needs to be prevented is between TraceLoggerThreadState::purgeUnusedPayloads and TraceLoggerThreadState::getOrCreateEventPayload in its various forms.  We need to make sure that while purgeUnusedPayloads is running, the use count of the payloads it is operating on cannot spontaneously go from zero to non-zero; this is only possible under getOrCreateEventPayload, so both methods hold the lock to avoid interfering with each other.

It is still possible during purgeUnusedPayloads for a use count to spontaneously go from non-zero to any other number, including zero.  If this happens purgeUnusedPayloads should still behave correctly and not leave the logger state in an inconsistent state.  It looks like this will be the case, though I did just notice that in the first loop in purgeUnusedPayloads the uses pruned from pointerMap are also pruned from textIdPayloads and are not deleted (since they're immediately removed from textIdPayloads the second loop will not see and remove them).  This seems like a bug, which I can fix if you want.

We could change this so that the lock is always held while modifying use counts on a payload, but it will lead to unnecessary contention between threads.  Either way, I can add documentation to TraceLogging.h describing how the payload lifetimes are handled.

> And in the constructor of TraceLoggerEvent we need to remove the use().
> http://searchfox.org/mozilla-central/source/js/src/vm/TraceLogging.cpp#1097
> among others

The patch already does this.

Comment 9

[Brian Hackett [Laid off!]]

(In reply to Hannes Verschore [:h4writer] from comment #5)
> ::: js/src/vm/HelperThreads.cpp
> @@ +1610,1 @@
> >      }
> 
> A helper thread will always stay a helper thread, right? It will not
> suddenly start executing JS code, right?

Yes, I don't think we'll ever have a need to execute JS code on helper threads, and definitely won't execute actual content scripts.

Comment 10

[Hannes Verschore [:h4writer]]

Thanks for the answers. Totally makes sense. With those in mind I'll re-review. Today or Monday

Comment 11

[Hannes Verschore [:h4writer]]

Comment on attachment 8832438 [details] [diff] [review]
patch

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

Thanks for the answers. Now I understand how this all fits together.
I took this as a clean slate review. Ignore all me previous comments.

::: js/src/vm/TraceLogging.cpp
@@ +518,5 @@
> +        if (e.front().value()->uses() == 0) {
> +            js_delete(e.front().value());
> +            e.removeFront();
> +        }
> +    }

You are correct there is a bug here.
This is solved by adjusting PointerHashMap to be a "void *" to "textId" hashmap. And while iterating the PointerHashMap immediately remove it from TextIdHashMap.
Can you do that? Or do you have a better idea here?

@@ +996,2 @@
>  {
>      payload_ = nullptr;

rm this line

@@ +1002,2 @@
>  {
>      payload_ = nullptr;

rm this line

@@ +1008,3 @@
>                                     const JS::ReadOnlyCompileOptions& compileOptions)
>  {
>      payload_ = nullptr;

rm this line

@@ +1015,2 @@
>  {
>      payload_ = nullptr;

rm this line

::: js/src/vm/TraceLogging.h
@@ +148,2 @@
>      void use() {
>          uses_++;

Just to make this obvious, can you give the "lock" as argument to this function? Since we can only run this function in a locked environment.

@@ +148,5 @@
>      void use() {
>          uses_++;
>      }
>      void release() {
>          uses_--;

Can you add a comment saying this can be done without locks?

Comment 12

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/43ac95c99af6
TraceLogger changes for multithreaded runtimes, r=h4writer.

Comment 13

[Hannes Verschore [:h4writer]]

Attachment: Follow-up patch.

I think the implementation still has a bug.

What if we iterate the pointerMap, afterwards a use decreased from 1 to 0 and we iterate the textIds. In that case we will remove the payload, but not from the pointerMap.

As fix I keep another counter that keeps track how many times a payload is in pointerMap. And only if that is also zero, we can remove the payload itself.

Comment 14

[Brian Hackett [Laid off!]]

Comment on attachment 8834903 [details] [diff] [review]
Follow-up patch.

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

Oops, yes, good catch.

Comment 15

[Hannes Verschore [:h4writer]]

Attachment: Follow-up patch 2.

Seems like I wasn't awake when doing the review. Found another issue.

Comment 16

[Brian Hackett [Laid off!]]

Comment on attachment 8835056 [details] [diff] [review]
Follow-up patch 2.

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

Oops.  Are there automated tests that exercise the trace logger or graph functionality?

Comment 17

[Hannes Verschore [:h4writer]]

(In reply to Brian Hackett (:bhackett) from comment #16)
> Comment on attachment 8835056 [details] [diff] [review]
> Follow-up patch 2.
> 
> Review of attachment 8835056 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Oops.  Are there automated tests that exercise the trace logger or graph
> functionality?

There are tests for the TraceLogger part. Not the TraceLoggerGraph part. In most cases the TraceLoggerGraph should be trivial though.

Comment 18

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/43ac95c99af6

Comment 19

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/ec2337b8a5e5
Follow-up fixes to tracelogger thread safety, r=bhackett

Comment 20

[Carsten Book [:Tomcat]]

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

Comment 21

[Hannes Verschore [:h4writer]]

Attachment: Docs don't agree with checks

We check for EnableActiveThread in the code and explain one has to use EnableCooperatingThread.