Closed Bug 1480104 Opened 2 years ago Closed 2 years ago

Tracelogger: provide an API for the gecko profiler

Categories

(Core :: JavaScript Engine, enhancement)

enhancement
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla64
Tracking Status
firefox63 --- wontfix
firefox64 --- fixed

People

(Reporter: denispal, Assigned: denispal)

References

(Blocks 1 open bug)

Details

Attachments

(1 file, 1 obsolete file)

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.
Assignee: nobody → dpalmeiro
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)
Summary: Tracelogger: emit the dictionary, event list, and event graph in JSON → Tracelogger: provide an API for the gecko profiler
Depends on: 1482560
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.
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.
Attachment #9002161 - Attachment is obsolete: true
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 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.
Attachment #9007098 - Flags: review+
Depends on: 1491909
Keywords: checkin-needed
No longer depends on: 1491909
Pushed by dluca@mozilla.com:
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
Keywords: checkin-needed
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
Flags: needinfo?(dpalmeiro)
Flags: needinfo?(dpalmeiro)
Keywords: checkin-needed
Pushed by rvandermeulen@mozilla.com:
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
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/9d5e7b73af8f
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla64
QA Contact: sdetar
Depends on: 1496362
Blocks: 1501377
You need to log in before you can comment on or make changes to this bug.