1223636 - TraceLogger: Assertion failure: id == nextTextId, at js/src/vm/TraceLoggingGraph.cpp:584

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[Wei Wu [:wuwei UTC+8]]

Caught this when I was testing my patch for bug 1221844.
Seems like that the assumption is not true now.
I'm working on this.

>   582	    fprintf(stderr, "id = %u\n", id);
>   583	    // Assume ids are given in order. Which is currently true.
>   584	    MOZ_ASSERT(id == nextTextId);

id = 0
...
id = 54
extraTextId->count() == 0
extraTextId->count() == 1
// so id==55 was missing
textId == 56
id = 56
Assertion failure: id == nextTextId, at js/src/vm/TraceLoggingGraph.cpp:584
Segmentation fault (core dumped)

Comment 1

[Wei Wu [:wuwei UTC+8]]

OK, this is caused by Attachment 8632760 [details] [diff] (Bug 1182428).

> -    js::TraceLoggerEvent event(logger, TraceLogger_AnnotateScripts, options);
> |
> V
> +    AutoCompilationTraceLogger(ExclusiveContext* cx, const TraceLoggerTextId id);

The third parameter ReadOnlyCompileOptions was accidentally removed, and unfortunately there is a ctor of TraceLoggerEvent which accepts two parameters accepted it. When BytecodeCompiler was invoked, 'TraceLogger_AnnotatedScripts' was added into extraTextId.

Comment 2

[Wei Wu [:wuwei UTC+8]]

Attachment: bug1223636.patch

Fix it.

Comment 3

[Wei Wu [:wuwei UTC+8]]

It might be good to add some DEBUG checks in 'TraceLoggerThread::getOrCreateEventPayload(TraceLoggerTextId textId)'.

I would like to submit a subsequent patch if needed.

Comment 4

[Hannes Verschore [:h4writer]]

Attachment: Don't take extraTextId.count() as the next TextId

In most cases extraTextId.count() agrees with what should be the nextTextId. But not when we use TraceLoggerEvent for a 'predefined' textId (i.e. textId < TraceLogger_Last). In that case we add a 'pseudo' extraTextId.

This happens whenever one of the "Scripts" ids is disabled or in the case that you found, where we accidentally forgot to add the script information.

Could you test if this (without your patch). Fix the issue too?

Comment 5

[Hannes Verschore [:h4writer]]

Comment on attachment 8685999 [details] [diff] [review]
bug1223636.patch

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

::: js/src/frontend/BytecodeCompiler.cpp
@@ +30,5 @@
>  
>  class MOZ_STACK_CLASS AutoCompilationTraceLogger
>  {
>    public:
> +    AutoCompilationTraceLogger(ExclusiveContext* cx, const TraceLoggerTextId id, const ReadOnlyCompileOptions& options);

Stylenit: I think this is longer than 100 characters. Can you break the line at the ,?

@@ +116,5 @@
>      RootedScript script;
>      Maybe<BytecodeEmitter> emitter;
>  };
>  
> +AutoCompilationTraceLogger::AutoCompilationTraceLogger(ExclusiveContext* cx, const TraceLoggerTextId id, const ReadOnlyCompileOptions& options)

Stylenit: same.

@@ +130,5 @@
>                                     const ReadOnlyCompileOptions& options,
>                                     SourceBufferHolder& sourceBuffer,
>                                     Handle<ScopeObject*> enclosingStaticScope,
>                                     TraceLoggerTextId logId)
> +  : traceLogger(cx, logId, options),

This seems incorrect. IIUC the logId is TraceLogger_ParserCompileScript here. Which we do not handle as a 'script' actually:
https://dxr.mozilla.org/mozilla-central/source/js/src/vm/TraceLogging.cpp#408
(Didn't you get any debug errors due to it?)

Now what do we want to do? Do we indeed want to record the script nexto the event here? Or not?

@@ +780,5 @@
>             .setColumn(lazy->column())
>             .setNoScriptRval(false)
>             .setSelfHostingMode(false);
>  
> +    AutoCompilationTraceLogger traceLogger(cx, TraceLogger_ParserCompileLazy, options);

Same issue as above. This will result in recording the script nexto the event. Do we want to do this? (or was this a quick fix? This shouldn't be needed anymore).

Comment 6

[Wei Wu [:wuwei UTC+8]]

It's a bit late (in my timezone) so I would provide a quick reply and upload a patch tomorrow.

(In reply to Hannes Verschore [:h4writer] from comment #5)
> Comment on attachment 8685999 [details] [diff] [review]
> bug1223636.patch
> 
> Review of attachment 8685999 [details] [diff] [review]:
> -----------------------------------------------------------------
> @@ +130,5 @@
> >                                     const ReadOnlyCompileOptions& options,
> >                                     SourceBufferHolder& sourceBuffer,
> >                                     Handle<ScopeObject*> enclosingStaticScope,
> >                                     TraceLoggerTextId logId)
> > +  : traceLogger(cx, logId, options),
> 
> This seems incorrect. IIUC the logId is TraceLogger_ParserCompileScript
> here. Which we do not handle as a 'script' actually:
> https://dxr.mozilla.org/mozilla-central/source/js/src/vm/TraceLogging.cpp#408
> (Didn't you get any debug errors due to it?)

Yes the patch passed all tests:
```
export TLLOG=Default,IonCompiler
export TLOPTIONS=EnableMainThread,EnableOffThread,EnableGraph
cd js/src/octane
../_DBG.OBJ/dist/bin/js run.js
../_DBG.OBJ/js/src/jsapi-tests/jsapt-tests
```

Indeed logId is 'TraceLogger_ParserCompileScript', and it is used in
https://dxr.mozilla.org/mozilla-central/source/js/src/frontend/BytecodeCompiler.cpp#125
and the error was actually caused by
https://dxr.mozilla.org/mozilla-central/source/js/src/frontend/BytecodeCompiler.cpp#123

 
> Now what do we want to do? Do we indeed want to record the script nexto the
> event here? Or not?
> 
> @@ +780,5 @@
> >             .setColumn(lazy->column())
> >             .setNoScriptRval(false)
> >             .setSelfHostingMode(false);
> >  
> > +    AutoCompilationTraceLogger traceLogger(cx, TraceLogger_ParserCompileLazy, options);
> 
> Same issue as above. This will result in recording the script nexto the
> event. Do we want to do this? (or was this a quick fix? This shouldn't be
> needed anymore).

ok the interface is confusing :(
https://dxr.mozilla.org/mozilla-central/source/js/src/frontend/BytecodeCompiler.cpp#123
https://dxr.mozilla.org/mozilla-central/source/js/src/frontend/BytecodeCompiler.cpp#125


(In reply to Hannes Verschore [:h4writer] from comment #4)
> Created attachment 8687223 [details] [diff] [review]
> Don't take extraTextId.count() as the next TextId
> 
> In most cases extraTextId.count() agrees with what should be the nextTextId.
> But not when we use TraceLoggerEvent for a 'predefined' textId (i.e. textId
> < TraceLogger_Last). In that case we add a 'pseudo' extraTextId.
> 
> This happens whenever one of the "Scripts" ids is disabled or in the case
> that you found, where we accidentally forgot to add the script information.
> 
> Could you test if this (without your patch). Fix the issue too?

Sure I'll test it tomorrow, leaving the ni? open :)

Comment 7

[Wei Wu [:wuwei UTC+8]]

Comment on attachment 8687223 [details] [diff] [review]
Don't take extraTextId.count() as the next TextId

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

Yes, this patch fixed the assertion failure :)
(and then you might hit another failure when logging file is bigger than 100MB, which is irrelevant with this bug. see bug 1223767 for more details.)

I think we can separate the issue into two parts:
(1) We accidentally forgot to add the script information in BytecodeCompiler; and
(2) If we do want to add 'general' events w/o script info, tracelogger should be ok with it.

The previous patch(attachment 8685999 [details] [diff] [review]) fixed (1), leaving (2) untouched. (for the correction of the patch, see comment #6.)
Since they are two separate issues, it would be good to file a new bug. I'll file a new bug for (1).

IIUC this patch is supposed to fix (2), leaving (1) untouched. I'm afraid this solution is not a good idea, for it makes the logic more complicated.
I'll try to explain this, once I confirmed my understanding of logic in BaselineCompiler.cpp/BaselineJIT.cpp.

Comment 8

[Wei Wu [:wuwei UTC+8]]

Comment on attachment 8685999 [details] [diff] [review]
bug1223636.patch

nit-fixed version has been moved to Attachment #8687546 [details] [diff] (bug 1224810).

Comment 9

[Wei Wu [:wuwei UTC+8]]

Attachment: bug1223636v3.patch

(In reply to Wei Wu [:wuwei UTC+8] from comment #7)
> Comment on attachment 8687223 [details] [diff] [review]
> Don't take extraTextId.count() as the next TextId
> 
> Review of attachment 8687223 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Yes, this patch fixed the assertion failure :)

the definition of extraTextId looks confusing if we put predefined textId into extraTextId, 

turns out we just need the payloads for three scripts-related events. The better way might be create global payload(s) for the scenario where TraceLogger_Scripts/_InlinedScripts/_AnnotateScripts is disabled.

Comment 10

[Wei Wu [:wuwei UTC+8]]

Btw indeed we must assert id == nextTextId, for textid is used for indexing event strings in tl-dict.x.tl. might be good to add a comment?

Comment 11

[Hannes Verschore [:h4writer]]

Comment on attachment 8687764 [details] [diff] [review]
bug1223636v3.patch

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

Like discussed on IRC:

- TraceLoggerEvent can be used with arbitrary "textId", normally mostly for new textIds, but also predefined textIds
as a result having predefined payloads for those doesn't really help
- ExtraTextId might just be wrongly named

Comment 12

[Wei Wu [:wuwei UTC+8]]

oops I've made some wrong assumptions based on the name of 'extraTextId' :(
As discussed on IRC, transferred this bug to h4writer.

Comment 13

[Hannes Verschore [:h4writer]]

Attachment: Don't take extraTextId.count() as the next TextId

Small fixes. In the code it is assumed that extraTextId will only contain EventPayloads from items that need to hold a string. But we sometimes also put payloads in there of predefined textIds. (e.g. textIds where the string is statically known).
As a result nextTextId cannot be know by doing count(extraTextId). I've introduced a new variable keeping the information now.

Comment 14

[Benjamin Bouvier [:bbouvier] (inactive)]

Comment on attachment 8688473 [details] [diff] [review]
Don't take extraTextId.count() as the next TextId

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

Yep, looks good to me.

Comment 15

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/1c11dc31c6b5

Comment 16

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/1c11dc31c6b5