1480104 - Tracelogger: provide an API for the gecko profiler

Status: RESOLVED FIXED

(Core :: JavaScript Engine, enhancement)

Description

[Denis Palmeiro [:denispal]]

The existing implementation of the trace logger will periodically flush the data into many files (around 20 or so) in order to prevent any kind of race conditions from occurring.  The event and graph data is saved in a binary representation, while the dictionary and index is saved in JSON.  To integrate the trace logger with the gecko profiler, we'll need to emit everything in one big JSON file instead.

Comment 1

[Nicolas B. Pierron [:nbp]]

I will note that a big part of the reason why the TraceLogger needed many files, apart from running multiple processes, was that it had to generate a huge amount of data and keeping it in memory would cause OOM after a few seconds (based on whatever you enabled)

Comment 2

[Denis Palmeiro [:denispal]]

Attachment: Provide an API for the gecko profiler to control the JS trace logger

Bug 1480104: Provide an API for the gecko profiler to start & stop the trace logger, clear the data structures which will ultimately be invoked on both start & stop of the profiler, and emit the data as JSON to a given JSONwriter object.  Additionally, add the necessary locks when anyone is accessing the trace logger data structures since the profiler is running on a separate thread and will have the power to stop the traceLogger at any moment and clear the data structures.

Comment 3

[Denis Palmeiro [:denispal]]

I was going to open a new bug for deduplicating some of the data from the trace logger, but I think this is a better place for it so I'll close the above review for now until that part is done.

Comment 4

[Denis Palmeiro [:denispal]]

Attachment: Bug 1480104: Provide an API for the gecko profiler, introduce a string hash table to remove duplicate data, and add necessary locks and changes to support the profiler start/stop routines

There are a number of changes involved here which I'll try to summarize below:
1.  Provide API calls to start & stop the tracelogger.  These will enable and disable a set of events to trace.  
2.  Provide API calls to reset the tracelogger.  This will empty the data structures used by the trace logger so that a new tracing session can occur without previous data corrupting it.
3.  Provide API calls to write out the trace logger data in JSON.  This will write out an array of strings which acts as the trace logger event dictionary, and an array of events with timestamps.  
4.  Implement a new way of storing the event strings.  Previously, all strings were saved in the format "script:line:column".  However, this led to a lot of duplication because many events would use the same script at different locations.  Instead, we now save only the script string into a vector, and then hash it and save that into a table for reuse.  The line and column will be saved as part of the text id payloads.  Overall, this saves us about 100-150 MB of data for about a 10 second trace.  
5.  Add some necessary locks for when the gecko profiler calls some of the API routines from another thread.

Comment 5

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

Comment on attachment 9007098 [details]
Bug 1480104: Provide an API for the gecko profiler,  introduce a string hash table to remove duplicate data, and add necessary locks and changes to support the profiler start/stop routines

Steve Fink [:sfink] [:s:] has approved the revision.

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/eae95de0eabe
Provide an API for the gecko profiler,  introduce a string hash table to remove duplicate data, and add necessary locks and changes to support the profiler start/stop routines r=sfink

Comment 7

[Dorel Luca [:dluca]]

Backed out changeset eae95de0eabe (bug 1480104) for spidermonkey failure

Log:
https://treeherder.mozilla.org/logviewer.html#?job_id=201359107&repo=autoland&lineNumber=3230

[task 2018-09-25T05:53:13.935Z] TEST-PASS | js/src/jit-test/tests/TypedObject/bug1232159.js | Success (code 0, args "--no-baseline --no-ion") [0.1 s]
[task 2018-09-25T05:53:13.936Z] {"action": "test_start", "jitflags": "--no-baseline --no-ion", "pid": 5638, "source": "jittests", "test": "TypedObject/bug1232159.js", "thread": "main", "time": 1537854793.8142931}
[task 2018-09-25T05:53:13.937Z] {"action": "test_end", "extra": {"jitflags": "--no-baseline --no-ion", "pid": 5638}, "jitflags": "--no-baseline --no-ion", "message": "Success", "pid": 5638, "source": "jittests", "status": "PASS", "test": "TypedObject/bug1232159.js", "thread": "main", "time": 1537854793.93372}
[task 2018-09-25T05:53:13.964Z] Exit code: -11
[task 2018-09-25T05:53:13.965Z] FAIL - TypedObject/bug1265690.js
[task 2018-09-25T05:53:13.966Z] TEST-UNEXPECTED-FAIL | js/src/jit-test/tests/TypedObject/bug1265690.js | Unknown (code -11, args "") [0.1 s]
[task 2018-09-25T05:53:13.967Z] {"action": "test_start", "jitflags": "", "pid": 5657, "source": "jittests", "test": "TypedObject/bug1265690.js", "thread": "main", "time": 1537854793.835998}
[task 2018-09-25T05:53:13.967Z] {"action": "test_end", "extra": {"jitflags": "", "pid": 5657}, "jitflags": "", "message": "Unknown", "pid": 5657, "source": "jittests", "status": "FAIL", "test": "TypedObject/bug1265690.js", "thread": "main", "time": 1537854793.964939}
[task 2018-09-25T05:53:13.968Z] INFO exit-status     : -11
[task 2018-09-25T05:53:13.968Z] INFO timed-out       : False
[task 2018-09-25T05:53:13.974Z] Exit code: -11
[task 2018-09-25T05:53:13.974Z] FAIL - TypedObject/bug1265690.js
[task 2018-09-25T05:53:13.974Z] TEST-UNEXPECTED-FAIL | js/src/jit-test/tests/TypedObject/bug1265690.js | Unknown (code -11, args "--ion-eager --ion-offthread-compile=off") [0.1 s]
[task 2018-09-25T05:53:13.975Z] {"action": "test_start", "jitflags": "--ion-eager --ion-offthread-compile=off", "pid": 5667, "source": "jittests", "test": "TypedObject/bug1265690.js", "thread": "main", "time": 1537854793.846849}
[task 2018-09-25T05:53:13.975Z] {"action": "test_end", "extra": {"jitflags": "--ion-eager --ion-offthread-compile=off", "pid": 5667}, "jitflags": "--ion-eager --ion-offthread-compile=off", "message": "Unknown", "pid": 5667, "source": "jittests", "status": "FAIL", "test": "TypedObject/bug1265690.js", "thread": "main", "time": 1537854793.974832}
[task 2018-09-25T05:53:13.975Z] INFO exit-status     : -11
[task 2018-09-25T05:53:13.975Z] INFO timed-out       : False
[task 2018-09-25T05:53:14.000Z] TEST-PASS | js/src/jit-test/tests/TypedObject/bug1232159.js | Success (code 0, args "--baseline-eager") [0.2 s]
[task 2018-09-25T05:53:14.000Z] {"action": "test_start", "jitflags": "--baseline-eager", "pid": 5637, "source": "jittests", "test": "TypedObject/bug1232159.js", "thread": "main", "time": 1537854793.799331}
[task 2018-09-25T05:53:14.000Z] {"action": "test_end", "extra": {"jitflags": "--baseline-eager", "pid": 5637}, "jitflags": "--baseline-eager", "message": "Success", "pid": 5637, "source": "jittests", "status": "PASS", "test": "TypedObject/bug1232159.js", "thread": "main", "time": 1537854793.99365}
[task 2018-09-25T05:53:14.001Z] Exit code: -11
[task 2018-09-25T05:53:14.001Z] FAIL - TypedObject/bug1265690.js
[task 2018-09-25T05:53:14.001Z] TEST-UNEXPECTED-FAIL | js/src/jit-test/tests/TypedObject/bug1265690.js | Unknown (code -11, args "--baseline-eager") [0.1 s]
[task 2018-09-25T05:53:14.001Z] {"action": "test_start", "jitflags": "--baseline-eager", "pid": 5669, "source": "jittests", "test": "TypedObject/bug1265690.js", "thread": "main", "time": 1537854793.859916}
[task 2018-09-25T05:53:14.001Z] {"action": "test_end", "extra": {"jitflags": "--baseline-eager", "pid": 5669}, "jitflags": "--baseline-eager", "message": "Unknown", "pid": 5669, "source": "jittests", "status": "FAIL", "test": "TypedObject/bug1265690.js", "thread": "main", "time": 1537854794.001265}
[task 2018-09-25T05:53:14.001Z] INFO exit-status     : -11
[task 2018-09-25T05:53:14.001Z] INFO timed-out       : False
[task 2018-09-25T05:53:14.017Z] Exit code: -11
[task 2018-09-25T05:53:14.017Z] FAIL - TypedObject/bug1265690.js
[task 2018-09-25T05:53:14.017Z] TEST-UNEXPECTED-FAIL | js/src/jit-test/tests/TypedObject/bug1265690.js | Unknown (code -11, args "--no-baseline --no-ion") [0.1 s]
[task 2018-09-25T05:53:14.017Z] {"action": "test_start", "jitflags": "--no-baseline --no-ion", "pid": 5689, "source": "jittests", "test": "TypedObject/bug1265690.js", "thread": "main", "time": 1537854793.883312}
[task 2018-09-25T05:53:14.017Z] {"action": "test_end", "extra": {"jitflags": "--no-baseline --no-ion", "pid": 5689}, "jitflags": "--no-baseline --no-ion", "message": "Unknown", "pid": 5689, "source": "jittests", "status": "FAIL", "test": "TypedObject/bug1265690.js", "thread": "main", "time": 1537854794.017304}
[task 2018-09-25T05:53:14.017Z] INFO exit-status     : -11
[task 2018-09-25T05:53:14.017Z] INFO timed-out       : False
[task 2018-09-25T05:53:14.024Z] TEST-PASS | js/src/jit-test/tests/TypedObject/bug1369774.js | Success (code 0, args "") [0.1 s]
[task 2018-09-25T05:53:14.025Z] {"action": "test_start", "jitflags": "", "pid": 5699, "source": "jittests", "test": "TypedObject/bug1369774.js", "thread": "main", "time": 1537854793.90466}
[task 2018-09-25T05:53:14.025Z] {"action": "test_end", "extra": {"jitflags": "", "pid": 5699}, "jitflags": "", "message": "Success", "pid": 5699, "source": "jittests", "status": "PASS", "test": "TypedObject/bug1369774.js", "thread": "main", "time": 1537854794.024194}
[task 2018-09-25T05:53:14.028Z] Exit code: -11
[task 2018-09-25T05:53:14.028Z] FAIL - TypedObject/bug1265690.js
[task 2018-09-25T05:53:14.028Z] TEST-UNEXPECTED-FAIL | js/src/jit-test/tests/TypedObject/bug1265690.js | Unknown (code -11, args "--ion-eager --ion-offthread-compile=off --ion-check-range-analysis --ion-extra-checks --no-sse3 --no-threads") [0.2 s]
[task 2018-09-25T05:53:14.029Z] {"action": "test_start", "jitflags": "--ion-eager --ion-offthread-compile=off --ion-check-range-analysis --ion-extra-checks --no-sse3 --no-threads", "pid": 5668, "source": "jittests", "test": "TypedObject/bug1265690.js", "thread": "main", "time": 1537854793.857256}
[task 2018-09-25T05:53:14.029Z] {"action": "test_end", "extra": {"jitflags": "--ion-eager --ion-offthread-compile=off --ion-check-range-analysis --ion-extra-checks --no-sse3 --no-threads", "pid": 5668}, "jitflags": "--ion-eager --ion-offthread-compile=off --ion-check-range-analysis --ion-extra-checks --no-sse3 --no-threads", "message": "Unknown", "pid": 5668, "source": "jittests", "status": "FAIL", "test": "TypedObject/bug1265690.js", "thread": "main", "time": 1537854794.028497}
[task 2018-09-25T05:53:14.029Z] INFO exit-status     : -11
[task 2018-09-25T05:53:14.029Z] INFO timed-out       : False

Push with failures:
https://treeherder.mozilla.org/#/jobs?repo=autoland&group_state=expanded&revision=eae95de0eabec99b772fd01ac873880cc96425d9

Backout:
https://hg.mozilla.org/integration/autoland/rev/345c57d30d2d4df3bef3e90a7c5b190540e08251

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/9d5e7b73af8f
Provide an API for the gecko profiler,  introduce a string hash table to remove duplicate data, and add necessary locks and changes to support the profiler start/stop routines r=sfink

Comment 9

[Cristian Brindusan [:cbrindusan]]

https://hg.mozilla.org/mozilla-central/rev/9d5e7b73af8f