1298831 - Get tracelogger working in E10S opt build

Status: NEW

(Core :: JavaScript Engine, defect, P3)

Description

[Hannes Verschore [:h4writer]]

Bug 1273855 fixed the bug that we would overwrite the same directory. But there is still an issue left in e10s OPT builds. On debug builds we close the content child decently, but on OPT builds we just forceful close it. I didn't notice this, because I was testing on DEBUG builds. But as a result not all data gets written to the required files.

Comment 1

[Hannes Verschore [:h4writer]]

@billm: given bug 1254829 comment 20, I'm directing this question to you. Though feel free to forward to somebody better.

Tracelogger is an 'internal' tool to trace which functions get called, which JS engine is used, how many times does a script get compiled, how long did the compilation take, which passes took the longest, how long took parsing, are we mostly in JS or do we go to VM calls, ...
See: https://github.com/h4writer/tracelogger

Now this is mostly used to look into JS shell performance, but it also works in the browser. It takes up a fixed amount of memory and put everything in that memory and when that is full it writes it to the disk. That means that on shutdown we need to make sure everything gets flushed. (Since that only happens when memory is full or on shutdown). Now we can use TraceLogger for the Chrome, but not for the Content process anymore, since we don't call deconstructors anymore in e10s on the Content process.

How we can fix this?

1) Is there still some code that get called before forcing the content child to die? To make sure I can flush that information?
2) Can I adjust the code to still run the destruction code (in opt builds), when TraceLogging is enabled? (Which doesn't happen for regular code).
...

Comment 2

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

This is the code that runs when the child process shuts down:
http://searchfox.org/mozilla-central/rev/064025c802c22cd5ad122746733cbd34ea47393c/dom/ipc/ContentChild.cpp#3001

You can either listen for the "content-child-shutdown" notification (maybe in XPConnect?) or modify this code directly. The observer notification is probably a better place to do it.

Comment 3

[Hannes Verschore [:h4writer]]

Attachment: WIP

Comment 4

[Hannes Verschore [:h4writer]]

Attachment: Patch

Thanks for the quick info.

This patch makes it possible to use TraceLogger in e10s again. By destroying the TraceLogger we flush the data it is still keeping. This way looked simplest/easiest/cleanest to me.

Comment 5

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

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

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

::: dom/ipc/ContentChild.cpp
@@ +3023,5 @@
>      Unused << RecvGatherProfile();
>    }
>  #endif
>  
> +  // Destroy the datastructures used by TraceLogger. That wil make us flush

"datastructures" should be two words. And s/wil/will/.

::: js/public/Initialization.h
@@ +122,5 @@
>  extern JS_PUBLIC_API(void)
>  JS_ShutDown(void);
>  
> +/**
> + * Destroy the resources hold by Tracelogger. This will cause it to flush

s/hold/held/.

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/6e9706730af8
Still flush the TraceLogger traces whenever using QuickExit to kill the content process, r=billm

Comment 7

[Sebastian Hengst [:aryx] (needinfo on intermittent or backout)]

Backed out for crashing in js::TraceLoggerThread:

https://hg.mozilla.org/integration/mozilla-inbound/rev/5da57d448e07

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=6e9706730af84fb7121e1dc0cbf00bb0906e5efa
Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=35310796&repo=mozilla-inbound

05:17:10     INFO -  TEST-START | test_about_pages.py TestAboutPages.test_back_forward
05:17:14     INFO -  mozcrash Downloading symbols from: https://queue.taskcluster.net/v1/task/elBBkPb3TfKu_bUt5hE5FA/artifacts/public/build/firefox-51.0a1.en-US.linux-i686.crashreporter-symbols.zip
05:17:42     INFO -  mozcrash Copy/paste: /builds/slave/test/build/linux32-minidump_stackwalk /tmp/tmpAEfkaG.mozrunner/minidumps/7a6444f9-bdf4-2ab8-56f93993-4c4f1e6f.dmp /tmp/tmpaGsZbw
05:17:55     INFO -  mozcrash Saved minidump as /builds/slave/test/build/blobber_upload_dir/7a6444f9-bdf4-2ab8-56f93993-4c4f1e6f.dmp
05:17:55     INFO -  mozcrash Saved app info as /builds/slave/test/build/blobber_upload_dir/7a6444f9-bdf4-2ab8-56f93993-4c4f1e6f.extra
05:17:55    ERROR -  PROCESS-CRASH | test_about_pages.py TestAboutPages.test_back_forward | application crashed [@ js::TraceLoggerThread::getOrCreateEventPayload]
05:17:55     INFO -  Crash dump filename: /tmp/tmpAEfkaG.mozrunner/minidumps/7a6444f9-bdf4-2ab8-56f93993-4c4f1e6f.dmp
05:17:55     INFO -  Operating system: Linux
05:17:55     INFO -                    0.0.0 Linux 3.2.0-76-generic-pae #111-Ubuntu SMP Tue Jan 13 22:34:29 UTC 2015 i686
05:17:55     INFO -  CPU: x86
05:17:55     INFO -       GenuineIntel family 6 model 62 stepping 4
05:17:55     INFO -       1 CPU
05:17:55     INFO -  Crash reason:  SIGSEGV
05:17:55     INFO -  Crash address: 0xfa845fb5
05:17:55     INFO -  Process uptime: not available
05:17:55     INFO -  Thread 0 (crashed)
05:17:55     INFO -   0  libxul.so!js::TraceLoggerThread::getOrCreateEventPayload [HashTable.h:6e9706730af8 : 1376 + 0xe]
05:17:55     INFO -      eip = 0xb5d3c60f   esp = 0xbfd6a330   ebp = 0xbfd6a368   ebx = 0xb76161ac
05:17:55     INFO -      esi = 0xfa845fb5   edi = 0x01b7df7c   eax = 0x05279e74   ecx = 0xe5e5e5e5
05:17:55     INFO -      edx = 0x36fbef9e   efl = 0x00210203
05:17:55     INFO -      Found by: given as instruction pointer in context
05:17:55     INFO -   1  libxul.so!js::TraceLoggerThread::getOrCreateEventPayload [TraceLogging.cpp:6e9706730af8 : 406 + 0xf]
05:17:55     INFO -      eip = 0xb5d3cad7   esp = 0xbfd6a370   ebp = 0xbfd6a3c8   ebx = 0xb76161ac
05:17:55     INFO -      esi = 0x0000001c   edi = 0x00000000
05:17:55     INFO -      Found by: call frame info
05:17:55     INFO -   2  libxul.so!js::TraceLoggerEvent::TraceLoggerEvent [TraceLogging.cpp:6e9706730af8 : 465 + 0x27]
05:17:55     INFO -      eip = 0xb5d3cf10   esp = 0xbfd6a3d0   ebp = 0xbfd6a3f8   ebx = 0xb76161ac
05:17:55     INFO -      esi = 0x0000001c   edi = 0x00000000
05:17:55     INFO -      Found by: call frame info
05:17:55     INFO -   3  libxul.so!Interpret [Interpreter.cpp:6e9706730af8 : 1745 + 0x24]
05:17:55     INFO -      eip = 0xb60c04ba   esp = 0xbfd6a400   ebp = 0xbfd6a718   ebx = 0xb76161ac
05:17:55     INFO -      esi = 0xac8afe70   edi = 0xbfd6a490
05:17:55     INFO -      Found by: call frame info
05:17:55     INFO -   4  libxul.so!js::RunScript [Interpreter.cpp:6e9706730af8 : 400 + 0xa]
05:17:55     INFO -      eip = 0xb60cc14e   esp = 0xbfd6a720   ebp = 0xbfd6a788   ebx = 0xb76161ac
05:17:55     INFO -      esi = 0xabc05000   edi = 0xbfd6a748
05:17:55     INFO -      Found by: call frame info
05:17:55     INFO -   5  libxul.so!js::InternalCallOrConstruct [Interpreter.cpp:6e9706730af8 : 472 + 0xf]
05:17:55     INFO -      eip = 0xb60cc312   esp = 0xbfd6a790   ebp = 0xbfd6a808   ebx = 0xb76161ac
05:17:55     INFO -      esi = 0x00000000   edi = 0xabc05000
05:17:55     INFO -      Found by: call frame info
05:17:55     INFO -   6  libxul.so!InternalCall [Interpreter.cpp:6e9706730af8 : 499 + 0x15]
05:17:55     INFO -      eip = 0xb60cc67a   esp = 0xbfd6a810   ebp = 0xbfd6a848   ebx = 0xb76161ac
05:17:55     INFO -      esi = 0x9a741bc0   edi = 0xffffff8c
05:17:55     INFO -      Found by: call frame info
05:17:55     INFO -   7  libxul.so!js::Call [Interpreter.cpp:6e9706730af8 : 518 + 0x8]
05:17:55     INFO -      eip = 0xb60cc747   esp = 0xbfd6a850   ebp = 0xbfd6a858   ebx = 0xb76161ac
05:17:55     INFO -      esi = 0xbfd6a898   edi = 0xbfd6a8c0
05:17:55     INFO -      Found by: call frame info
05:17:55     INFO -   8  libxul.so!JS_CallFunctionValue [jsapi.cpp:6e9706730af8 : 2776 + 0x24]
05:17:55     INFO -      eip = 0xb5f778e1   esp = 0xbfd6a860   ebp = 0xbfd6a918   ebx = 0xb76161ac
05:17:55     INFO -      esi = 0x9cf71b80   edi = 0xbfd6a8c0
05:17:55     INFO -      Found by: call frame info
05:17:55     INFO -   9  libxul.so!nsXPCWrappedJSClass::CallMethod [XPCWrappedJSClass.cpp:6e9706730af8 : 1211 + 0xc]
05:17:55     INFO -      eip = 0xb42f5a32   esp = 0xbfd6a920   ebp = 0xbfd6ab68   ebx = 0xb76161ac
05:17:55     INFO -      esi = 0xbfd6a9e8   edi = 0x80004005
05:17:55     INFO -      Found by: call frame info
05:17:55     INFO -  10  libxul.so!nsXPCWrappedJS::CallMethod [XPCWrappedJS.cpp:6e9706730af8 : 613 + 0x13]
05:17:55     INFO -      eip = 0xb42f6595   esp = 0xbfd6ab70   ebp = 0xbfd6aba8   ebx = 0xb76161ac
05:17:55     INFO -      esi = 0x9aa91540   edi = 0x00000003
05:17:55     INFO -      Found by: call frame info
05:17:55     INFO -  11  libxul.so!PrepareAndDispatch [xptcstubs_gcc_x86_unix.cpp:6e9706730af8 : 60 + 0x1c]
05:17:55     INFO -      eip = 0xb3d79571   esp = 0xbfd6abb0   ebp = 0xbfd6ac78   ebx = 0xb76161ac
05:17:55     INFO -      esi = 0xbfd6ac88   edi = 0xbfd6abe0
05:17:55     INFO -      Found by: call frame info
05:17:55     INFO -  12  libxul.so!nsTimerImpl::Fire [nsTimerImpl.cpp:6e9706730af8 : 529 + 0x12]
05:17:55     INFO -      eip = 0xb3d76422   esp = 0xbfd6ac80   ebp = 0xbfd6ad08   ebx = 0xb76161ac
05:17:55     INFO -      esi = 0x9e452044   edi = 0x9a911ac0
05:17:55     INFO -      Found by: call frame info
05:17:55     INFO -  13  libxul.so!nsTimerEvent::Run [TimerThread.cpp:6e9706730af8 : 286 + 0x7]
05:17:55     INFO -      eip = 0xb3d74ca5   esp = 0xbfd6ad10   ebp = 0xbfd6ad58   ebx = 0xb76161ac
05:17:55     INFO -      esi = 0x9e452044   edi = 0x00000000
05:17:55     INFO -      Found by: call frame info
05:17:55     INFO -  14  libxul.so!nsThread::ProcessNextEvent [nsThread.cpp:6e9706730af8 : 1058 + 0x6]
05:17:55     INFO -      eip = 0xb3d72b27   esp = 0xbfd6ad60   ebp = 0xbfd6adc8   ebx = 0xb76161ac
05:17:55     INFO -      esi = 0xb22666a0   edi = 0x00000000
05:17:55     INFO -      Found by: call frame info
05:17:55     INFO -  15  libxul.so!NS_ProcessNextEvent [nsThreadUtils.cpp:6e9706730af8 : 290 + 0x10]
05:17:55     INFO -      eip = 0xb3d8baad   esp = 0xbfd6add0   ebp = 0xbfd6ae08   ebx = 0xb76161ac
05:17:55     INFO -      esi = 0xb2234550   edi = 0xbfd6b020
05:17:55     INFO -      Found by: call frame info
05:17:55     INFO -  16  libxul.so!mozilla::ipc::MessagePump::Run [MessagePump.cpp:6e9706730af8 : 96 + 0xc]
05:17:55     INFO -      eip = 0xb404fc6c   esp = 0xbfd6ae10   ebp = 0xbfd6ae58   ebx = 0xb76161ac
05:17:55     INFO -      esi = 0xb2234550   edi = 0xbfd6b020
05:17:55     INFO -      Found by: call frame info
05:17:55     INFO -  17  libxul.so!MessageLoop::RunInternal [message_loop.cc:6e9706730af8 : 232 + 0x6]
05:17:55     INFO -      eip = 0xb40390c2   esp = 0xbfd6ae60   ebp = 0xbfd6ae78   ebx = 0xb76161ac
05:17:55     INFO -      esi = 0xbfd6b020   edi = 0xb22666a0
05:17:55     INFO -      Found by: call frame info
05:17:55     INFO -  18  libxul.so!MessageLoop::Run [message_loop.cc:6e9706730af8 : 225 + 0x8]
05:17:55     INFO -      eip = 0xb40391bc   esp = 0xbfd6ae80   ebp = 0xbfd6aea8   ebx = 0xb76161ac
05:17:55     INFO -      esi = 0xbfd6b020   edi = 0xb22666a0
05:17:55     INFO -      Found by: call frame info
05:17:55     INFO -  19  libxul.so!nsBaseAppShell::Run [nsBaseAppShell.cpp:6e9706730af8 : 156 + 0xe]
05:17:55     INFO -      eip = 0xb5194123   esp = 0xbfd6aeb0   ebp = 0xbfd6aec8   ebx = 0xb76161ac
05:17:55     INFO -      esi = 0xabb48c40   edi = 0xb22666a0
05:17:55     INFO -      Found by: call frame info
05:17:55     INFO -  20  libxul.so!XRE_RunAppShell [nsEmbedFunctions.cpp:6e9706730af8 : 844 + 0x9]
05:17:55     INFO -      eip = 0xb585aab9   esp = 0xbfd6aed0   ebp = 0xbfd6af08   ebx = 0xb76161ac
05:17:55     INFO -      esi = 0xbfd6aeec   edi = 0xbfd6afd0
05:17:55     INFO -      Found by: call frame info
05:17:55     INFO -  21  libxul.so!mozilla::ipc::MessagePumpForChildProcess::Run [MessagePump.cpp:6e9706730af8 : 269 + 0x5]
05:17:55     INFO -      eip = 0xb404fd1e   esp = 0xbfd6af10   ebp = 0xbfd6af38   ebx = 0xb76161ac
05:17:55     INFO -      esi = 0xbfd6b020   edi = 0xbfd6afd0
05:17:55     INFO -      Found by: call frame info
05:17:55     INFO -  22  libxul.so!MessageLoop::RunInternal [message_loop.cc:6e9706730af8 : 232 + 0x6]
05:17:55     INFO -      eip = 0xb40390c2   esp = 0xbfd6af40   ebp = 0xbfd6af58   ebx = 0xb76161ac
05:17:55     INFO -      esi = 0xbfd6b020   edi = 0xbfd6afd0
05:17:55     INFO -      Found by: call frame info
05:17:55     INFO -  23  libxul.so!MessageLoop::Run [message_loop.cc:6e9706730af8 : 225 + 0x8]
05:17:55     INFO -      eip = 0xb40391bc   esp = 0xbfd6af60   ebp = 0xbfd6af88   ebx = 0xb76161ac
05:17:55     INFO -      esi = 0xbfd6b020   edi = 0xbfd6afd0
05:17:55     INFO -      Found by: call frame info
05:17:55     INFO -  24  libxul.so!XRE_InitChildProcess [nsEmbedFunctions.cpp:6e9706730af8 : 674 + 0x9]
05:17:55     INFO -      eip = 0xb585b343   esp = 0xbfd6af90   ebp = 0xbfd6b118   ebx = 0xb76161ac
05:17:55     INFO -      esi = 0xbfd6b020   edi = 0xbfd6afd0
05:17:55     INFO -      Found by: call frame info
05:17:55     INFO -  25  plugin-container!content_process_main [plugin-container.cpp:6e9706730af8 : 197 + 0x10]
05:17:55     INFO -      eip = 0x0804f7f1   esp = 0xbfd6b120   ebp = 0xbfd6b168   ebx = 0x08089564
05:17:55     INFO -      esi = 0xb22360a8   edi = 0xbfd6b148
05:17:55     INFO -      Found by: call frame info
05:17:55     INFO -  26  plugin-container!main [MozillaRuntimeMain.cpp:6e9706730af8 : 18 + 0xa]
05:17:55     INFO -      eip = 0x0804edf5   esp = 0xbfd6b170   ebp = 0xbfd6b188   ebx = 0xb380eff4
05:17:55     INFO -      esi = 0x00000000   edi = 0x00000000
05:17:55     INFO -      Found by: call frame info
05:17:55     INFO -  27  libc-2.15.so + 0x194d3
05:17:55     INFO -      eip = 0xb36834d3   esp = 0xbfd6b190   ebp = 0x00000000
05:17:55     INFO -      Found by: previous frame's frame pointer
05:17:55     INFO -  28  plugin-container!__libc_csu_fini + 0x10
05:17:55     INFO -      eip = 0x08077560   esp = 0xbfd6b194   ebp = 0x00000000
05:17:55     INFO -      Found by: stack scanning
05:17:55     INFO -  29  libc-2.15.so + 0x194d3
05:17:55     INFO -      eip = 0xb36834d3   esp = 0xbfd6b1a0   ebp = 0x00000000
05:17:55     INFO -      Found by: stack scanning
05:17:55     INFO -  30  libc-2.15.so + 0x1a4ff4
05:17:55     INFO -      eip = 0xb380eff4   esp = 0xbfd6b1c8   ebp = 0x00000000
05:17:55     INFO -      Found by: stack scanning
05:17:55     INFO -  31  plugin-container + 0x7094
05:17:55     INFO -      eip = 0x0804f094   esp = 0xbfd6b1f0   ebp = 0x00000000
05:17:55     INFO -      Found by: stack scanning
05:17:55     INFO -  32  ld-2.15.so + 0x146b0
05:17:55     INFO -      eip = 0xb77056b0   esp = 0xbfd6b1f8   ebp = 0x00000000
05:17:55     INFO -      Found by: stack scanning
05:17:55     INFO -  33  libc-2.15.so + 0x193e9
05:17:55     INFO -      eip = 0xb36833e9   esp = 0xbfd6b1fc   ebp = 0x00000000
05:17:55     INFO -      Found by: stack scanning
05:17:55     INFO -  34  ld-2.15.so + 0x20ff4
05:17:55     INFO -      eip = 0xb7711ff4   esp = 0xbfd6b200   ebp = 0x00000000
05:17:55     INFO -      Found by: stack scanning
05:17:55     INFO -  35  plugin-container + 0x7094
05:17:55     INFO -      eip = 0x0804f094   esp = 0xbfd6b208   ebp = 0x00000000
05:17:55     INFO -      Found by: stack scanning
05:17:55     INFO -  36  plugin-container!_start + 0x21
05:17:55     INFO -      eip = 0x0804f0b5   esp = 0xbfd6b210   ebp = 0x00000000
05:17:55     INFO -      Found by: stack scanning
05:17:55     INFO -  37  plugin-container!init [replace_malloc.c:6e9706730af8 : 133 + 0x5]
05:17:55     INFO -      eip = 0x0804edda   esp = 0xbfd6b214   ebp = 0x00000000
05:17:55     INFO -      Found by: stack scanning
05:17:55     INFO -  38  plugin-container!__libc_csu_fini + 0x10
05:17:55     INFO -      eip = 0x08077560   esp = 0xbfd6b220   ebp = 0xbfd6b234
05:17:55     INFO -      Found by: stack scanning
05:17:55     INFO -  39  0xbfd6b86f
05:17:55     INFO -      eip = 0xbfd6b86f   esp = 0xbfd6b23c   ebp = 0xbfd6b7ad
05:17:55     INFO -      Found by: previous frame's frame pointer
05:17:55     INFO -  40  0x2f73646c
05:17:55     INFO -      eip = 0x2f73646c   esp = 0xbfd6b7b5   ebp = 0x6975622f
05:17:55     INFO -      Found by: previous frame's frame pointer

Comment 8

[Steve Fink [:sfink] [:s:]]

I haven't looked at what's going on here, but once you do figure it out, I'll probably want to generalize this to JS::NotifyImpendingShutdown or something so that I can use it to flush out the minor GC logging too, and perhaps some other logging that is supposed to print shutdown totals. (I just happened to stumble across the minor GC logging issue, and recognized that it's the same sort of issue.)

Comment 9

[Hannes Verschore [:h4writer]]

I think bug 1300515 is the culprit for the backout. Running a try build now.