Tracelogger: provide an API for the gecko profiler

RESOLVED FIXED in Firefox 64

Status

()

enhancement
RESOLVED FIXED
11 months ago
8 months ago

People

(Reporter: denispal, Assigned: denispal)

Tracking

(Blocks 1 bug)

Trunk
mozilla64
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox63 wontfix, firefox64 fixed)

Details

Attachments

(1 attachment, 1 obsolete attachment)

Assignee

Description

11 months ago
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

Updated

11 months ago
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)
Assignee

Updated

10 months ago
Summary: Tracelogger: emit the dictionary, event list, and event graph in JSON → Tracelogger: provide an API for the gecko profiler
Assignee

Updated

10 months ago
Depends on: 1482560
Assignee

Comment 2

10 months ago
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.
Assignee

Comment 3

10 months ago
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.

Updated

10 months ago
Attachment #9002161 - Attachment is obsolete: true
Assignee

Comment 4

9 months ago
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+
Assignee

Updated

9 months ago
Depends on: 1491909
Assignee

Updated

9 months ago
Keywords: checkin-needed
Assignee

Updated

9 months ago
No longer depends on: 1491909

Comment 6

9 months ago
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)
Assignee

Updated

9 months ago
Flags: needinfo?(dpalmeiro)
Assignee

Updated

9 months ago
Keywords: checkin-needed

Comment 8

9 months ago
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

Comment 9

9 months ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/9d5e7b73af8f
Status: NEW → RESOLVED
Closed: 9 months ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla64
QA Contact: sdetar
QA Contact: sdetar
Depends on: 1496362
Assignee

Updated

8 months ago
Blocks: 1501377
You need to log in before you can comment on or make changes to this bug.