1227028 - TraceLogger: jit-test FAILURE: tests/coverage/bug1214548.js

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[Wei Wu [:wuwei UTC+8]]

$../_DBG.OBJ/dist/bin/js -f lib/prologue.js -f tests/coverage/bug1214548.js 
Assertion failure: textId < uint32_t(1 << 31), at /gecko-dev/js/src/vm/TraceLoggingGraph.h:148
Segmentation fault (core dumped)

$env | grep TL
TLLOG=Default,IonCompiler
TLOPTIONS=EnableMainThread,EnableOffThread,EnableGraph

(gdb) bt
#0  0x00000000005503ae in TraceLoggerGraph::TreeEntry::setTextId (this=0x7fcc49aa08b8, textId=3857049061) at /gecko-dev/js/src/vm/TraceLoggingGraph.h:148
#1  0x000000000054f71b in TraceLoggerGraph::startEventInternal (this=0x7fcc54425150, id=3857049061, timestamp=30972806451) at /gecko-dev/js/src/vm/TraceLoggingGraph.cpp:377
#2  0x000000000054f423 in TraceLoggerGraph::startEvent (this=0x7fcc54425150, id=3857049061, timestamp=30972806451) at /gecko-dev/js/src/vm/TraceLoggingGraph.cpp:326
#3  0x0000000000550048 in TraceLoggerGraph::log (this=0x7fcc54425150, events=...) at /gecko-dev/js/src/vm/TraceLoggingGraph.cpp:570
#4  0x0000000000543500 in js::TraceLoggerThread::~TraceLoggerThread (this=0x7fcc544171e0, __in_chrg=<optimized out>) at /gecko-dev/js/src/vm/TraceLogging.cpp:186
#5  0x0000000000545d36 in js_delete<js::TraceLoggerThread> (p=0x7fcc544171e0) at ../../dist/include/js/Utility.h:370
#6  0x0000000000544c91 in js::TraceLoggerThreadState::~TraceLoggerThreadState (this=0x7fcc544950e0, __in_chrg=<optimized out>) at /gecko-dev/js/src/vm/TraceLogging.cpp:591
#7  0x0000000000545b31 in js_delete<js::TraceLoggerThreadState> (p=0x7fcc544950e0) at ../../dist/include/js/Utility.h:370
#8  0x0000000000543249 in js::DestroyTraceLoggerThreadState () at /gecko-dev/js/src/vm/TraceLogging.cpp:126
#9  0x0000000000542b9c in JS_ShutDown () at /gecko-dev/js/src/vm/Initialization.cpp:130
#10 0x0000000000449692 in main (argc=5, argv=0x7fff61e1a498, envp=0x7fff61e1a4c8) at /gecko-dev/js/src/shell/js.cpp:6889
(gdb)

Comment 1

[Hannes Verschore [:h4writer]]

Attachment: Patch

When we hit the memory limit, we will try to flush everything. Seems there were still some bugs in there. (Now this happens sooner since we max at 200mb).

3 fixes in this patch:

1) The assignment operator is to fix the following construct:

> traceloggerField = TraceLoggerEvent(logger, TraceLogger_Scripts, script);

In that case we increased the use of the payload for the TraceLoggerEvent, but not for 'traceloggerField'. As a result when TraceLoggerEvent went out of scope, the usage dropped to 0 again.

2) IonScript doesn't delete, but only free IonScript. As a result the deconstructor on the traceLoggerScriptEvent_ field wasn't called.

3) The pointerMap points to Payloads, but we didn't remove the ones we deleted in textIdPayloads.

Comment 2

[Wei Wu [:wuwei UTC+8]]

Great! This should also fix Bug 1227033, hopefully.
btw you might want to check Bug 1227032 and Bug 1227034.

Comment 3

[Wei Wu [:wuwei UTC+8]]

Got some invalid free from valgrind, which might be related (could be false positive):

> ==11524== Invalid free() / delete / delete[] / realloc()
> ==11524==    at 0x4C2C2BC: operator delete(void*) (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
> ==11524==    by 0x54D469: mozilla::DefaultDelete<TraceLoggerGraph>::operator()(TraceLoggerGraph*) const (UniquePtr.h:482)
> ==11524==    by 0x54B7C3: mozilla::UniquePtr<TraceLoggerGraph, mozilla::DefaultDelete<TraceLoggerGraph> >::reset(TraceLoggerGraph*) (UniquePtr.h:309)
> ==11524==    by 0x54B866: mozilla::UniquePtr<TraceLoggerGraph, mozilla::DefaultDelete<TraceLoggerGraph> >::operator=(decltype(nullptr)) (UniquePtr.h:279)
> ==11524==    by 0x547912: js::TraceLoggerThread::~TraceLoggerThread() (TraceLogging.cpp:184)
> ==11524==    by 0x54A12B: void js_delete<js::TraceLoggerThread>(js::TraceLoggerThread const*) (Utility.h:370)
> ==11524==    by 0x54908E: js::TraceLoggerThreadState::~TraceLoggerThreadState() (TraceLogging.cpp:588)
> ==11524==    by 0x549F6A: void js_delete<js::TraceLoggerThreadState>(js::TraceLoggerThreadState const*) (Utility.h:370)
> ==11524==    by 0x547664: js::DestroyTraceLoggerThreadState() (TraceLogging.cpp:126)
> ==11524==    by 0x546FB8: JS_ShutDown() (Initialization.cpp:130)
> ==11524==    by 0x44D18E: main (js.cpp:6889)
> ==11524==  Address 0x62251a0 is not stack'd, malloc'd or (recently) free'd
> ==11524== 
> ==11524== 
> ==11524== HEAP SUMMARY:
> ==11524==     in use at exit: 0 bytes in 0 blocks
> ==11524==   total heap usage: 0 allocs, 2 frees, 0 bytes allocated
> ==11524== 
> ==11524== All heap blocks were freed -- no leaks are possible
> ==11524== 
> ==11524== For counts of detected and suppressed errors, rerun with: -v
> ==11524== ERROR SUMMARY: 2 errors from 1 contexts (suppressed: 0 from 0)

Comment 4

[Wei Wu [:wuwei UTC+8]]

(In reply to Wei Wu [:w :wuwei UTC+8] from comment #3)
> Got some invalid free from valgrind, which might be related (could be false
> positive):
> 
> > ==11524== Invalid free() / delete / delete[] / realloc()
> > ==11524==    at 0x4C2C2BC: operator delete(void*) (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
> > ==11524==    by 0x54D469: mozilla::DefaultDelete<TraceLoggerGraph>::operator()(TraceLoggerGraph*) const (UniquePtr.h:482)
> > ==11524==    by 0x54B7C3: mozilla::UniquePtr<TraceLoggerGraph, mozilla::DefaultDelete<TraceLoggerGraph> >::reset(TraceLoggerGraph*) (UniquePtr.h:309)
> > ==11524==    by 0x54B866: mozilla::UniquePtr<TraceLoggerGraph, mozilla::DefaultDelete<TraceLoggerGraph> >::operator=(decltype(nullptr)) (UniquePtr.h:279)
> > ==11524==    by 0x547912: js::TraceLoggerThread::~TraceLoggerThread() (TraceLogging.cpp:184)
> > ==11524==    by 0x54A12B: void js_delete<js::TraceLoggerThread>(js::TraceLoggerThread const*) (Utility.h:370)
> > ==11524==    by 0x54908E: js::TraceLoggerThreadState::~TraceLoggerThreadState() (TraceLogging.cpp:588)
> > ==11524==    by 0x549F6A: void js_delete<js::TraceLoggerThreadState>(js::TraceLoggerThreadState const*) (Utility.h:370)
> > ==11524==    by 0x547664: js::DestroyTraceLoggerThreadState() (TraceLogging.cpp:126)
> > ==11524==    by 0x546FB8: JS_ShutDown() (Initialization.cpp:130)
> > ==11524==    by 0x44D18E: main (js.cpp:6889)
> > ==11524==  Address 0x62251a0 is not stack'd, malloc'd or (recently) free'd
> > ==11524== 
> > ==11524== 
> > ==11524== HEAP SUMMARY:
> > ==11524==     in use at exit: 0 bytes in 0 blocks
> > ==11524==   total heap usage: 0 allocs, 2 frees, 0 bytes allocated
> > ==11524== 
> > ==11524== All heap blocks were freed -- no leaks are possible
> > ==11524== 
> > ==11524== For counts of detected and suppressed errors, rerun with: -v
> > ==11524== ERROR SUMMARY: 2 errors from 1 contexts (suppressed: 0 from 0)

bad news: reproduced after the patch applied.
the patch doesn't fix Bug 1227032 yet.

Comment 5

[Benjamin Bouvier [:bbouvier] (inactive)]

Comment on attachment 8692047 [details] [diff] [review]
Patch

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

Yes indeed. Thinking about it, should we also worry about the copy ctor or the move ctor/assignment operator?
Maybe it'd be worth to delete the copy ctor, just to be sure the move ctor/assignment operator is actually used (as it does the right thing, copying the pointer without touching the uses).
I think maps/arrays will try to use the copy ctor only if the move ctor can't be used, so it should be fine, but needs confirmation by trying :)

::: js/src/jit/Ion.cpp
@@ +1252,5 @@
>  IonScript::Destroy(FreeOp* fop, IonScript* script)
>  {
>      script->unlinkFromRuntime(fop);
> +    // Frees the potential event we have set.
> +    script->traceLoggerScriptEvent_ = TraceLoggerEvent();

iiuc, the BaselineScript::Destroy using fop->delete_, we're all good there?

::: js/src/vm/TraceLogging.cpp
@@ +188,5 @@
>      }
>  
>      if (textIdPayloads.initialized()) {
> +        for (TextIdHashMap::Range r = textIdPayloads.all(); !r.empty(); r.popFront()) {
> +            MOZ_ASSERT(r.front().value()->uses() == 0);

Maybe this could go into ~TraceLoggerEventPayload instead, or in addition to here? Probably more bugs could be caught this way.

@@ +193,2 @@
>              js_delete(r.front().value());
> +        }

If I understand correctly the code (only skimmed at it very quickly, so I might be very wrong), the PointerHashMap contains a subset of the elements which are in the TextIdHashMap. Is that right?

If so, could we first delete the payloads in the PointerHashMap (every time we delete one, we also withdraw it from the TextIdHashMap), and then only delete the remaining payloads in TextIdHashMap? This way, we are sure not to miss any payload.

::: js/src/vm/TraceLogging.h
@@ +110,5 @@
>      bool hasPayload() const {
>          return !!payload_;
>      }
> +
> +    TraceLoggerEvent& operator=( const TraceLoggerEvent& other );

style nit: no spaces after ( and before )

Comment 7

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/7683aae0caff

Comment 8

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/7683aae0caff