1504005 - Structured Spewer for JS Engine

Status: RESOLVED FIXED

(Core :: JavaScript Engine, enhancement, P3)

Description

[Matthew Gaudet (he/him) [:mgaudet]]

Provide an easy to use mechanism for emitting structured spew from the JIT.

Comment 1

[Matthew Gaudet (he/him) [:mgaudet]]

Attachment: Structured Spewer Design Prototype

This spewer design has two goals:

  1. Provide a spew mechanism that has first-class support for slicing and
     dicing output. This means that filtering by script and channel should be
     the dominant output mechanism.
  2. Provide a simple powerful mechanism for getting information out of the
     compiler and into tools. I'm inspired by tools like CacheIR analyzer,
     IR Hydra, and the upcoming tracelogger integration into perf.html.

The prototype here has three main control knobs, all currently set as
environment variables:

    SPEW: Activates the spewer. The value provided is interpreted as a comma
          separated list that selects channels by name. Currently there's no
          mapping between internal and external names, so the channel names
          are exactly those described in STRUCTURED_CHANNEL_LIST below.

    SPEW_FILE: Selects the file to write to. An absolute path, or
               /tmp/spewfile (for now, non-portable!) if not specified.

    SPEW_FILTER: A string which is matched against 'signature' constructed
                 for a JSScript, currently connsisting of filename:line:col.

                 Matching in this prototype is merely finding the string in
                 in question in the 'signature'

An example usage:

SPEW=BaselineScripts SPEW_FILE=$PWD/deltablue SPEW_FILTER=deltablue.js:880  \
   ../build_DBG.OBJ/dist/bin/js run-deltablue.js

produces a single entry log file:

    [{
      "channel":"BaselineScripts",
      "location":{
        "filename":"/Users/mgaudet/mozilla-unified-clean/js/src/octane/deltablue.js",
        "line":880,
        "column":18
      },
      "baseline":{
        "success":1,
        "duration":316
      }
    }]

Prototype Usage:

- To feel out the API, the prototype has two channels implemented: One
  for dumping the IC entry counters added in Bug 1494473.
- A new spew for baseline compilation. This uses a ScopeExit to capture
  the compilation duration.

  This usage is neat, but does present a real challenge for keeping coherent
  logs, and would likely necessitate changing the architecture of the spewer.
  See design notes.


Design Notes worth considering:

- The current design largely just exposes JSONPrinter's interface. It makes
  no attempt to facade or provide any additional functionaity. This feels
  short sighted to me, as it means we couldn't easily adopt a new backend
  (for example, one that does a more compressed output like MessagePack,
  JSONB or BSON)

  We're also stuck with the requirement spew proceed entirely linearly,
  which may be desirable to remove (c.f. ScopeExit above).

- The current design has been put into the jit namespace and is described
  like it is only useful for the JIT: This is entirely an artifact of me not
  knowing what are the desirable aspects for spew in the GC and VM.

  Nevertheless, it feels like this could easily (and perhaps should be)
  hoisted out of the JIT.

- Using environment variables for control seems necessary for existing in an
  embedded context. However, it also seems there's room for providing more
  syntax. For example, imagine a syntax where you specify spew and channel on
  a regex basis like

       SPEW='{*frob*}(BaselineICStats),{*baz*}(*)'

  and getting IC stats for all scripts that match *frob* and all spew for
  scripts that match *baz*.

- The current design doesn't subsume the CacheIR spewer, but it comes from a
  similar place, and I wonder if it wouldn't be worth combining them
  eventually.

Comment 2

[Matthew Gaudet (he/him) [:mgaudet]]

As Ted notes on IRC: we do need to make sure this design stands up to e10s, and in general should have PID suffixed filenames.

Comment 3

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

I just implemented (on a temporary basis, to track down a bug) something similar but different for my work on incremental weakmap marking. My goals were a bit different: (1) I didn't intend to land it, so I didn't spend any effort making it nice; (2) I was logging a trace of many events, so used a simple yet annoyingly stupid and inflexible binary format; and (3) I needed it to run on the try server and upload the result (I couldn't reproduce the bug locally.) But I have some experience using it in anger, figuratively and literally, so I'll mention some learnings from that:

 - A useful default, or at least easy-to-trigger behavior, is to write the output file(s) into $MOZ_UPLOAD_DIR/<filename>. No need to use a single output file or make the names predictable; anything in that dir will show up on treeherder under 'Job Details'.

 - I ended up writing the decoder (a straightforward Python script) concurrently with the emitter code, because I kept adding new types of info and needed to keep them in sync. It would have been nice to have a schema-like thing to remove the need to update the decoder constantly, and get some checking that I wasn't messing up. (This is much more of an issue with a binary format.)

 - Even with my minimal use, I ended up adding a version number to the output so I could run the decoder on the output of multiple try runs, where I changed the meaning of a few things for each push. (If version is 1 then this field means this.) Again, not as much of an issue with JSON output, but it's still nice to be able to look at a file and know what it contains.

 - It would be nice to have something lightweight and unobtrusive enough that I could easily compile it out. Perhaps not an issue with the stuff you're spewing? I was logging a lot of trace data, like every weakmap key ever traced. (I buffered the log in memory and only wrote it out if I hit a particular assertion failure, so the cost was a 25-byte Vector append.)

Comment 4

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

For the GC use case, we're already using JSONPrinter as the interface. But we ended up having a separate textual backend as well, which only shares the input data but none of the rendering code. The JSON code has a corresponding Flow JSON schema in the gecko profiler. Or whatever that's called.

Comment 5

[Matthew Gaudet (he/him) [:mgaudet]]

(In reply to Steve Fink [:sfink] [:s:] (PTO Nov 5-16) from comment #4)
> For the GC use case, we're already using JSONPrinter as the interface. But
> we ended up having a separate textual backend as well, which only shares the
> input data but none of the rendering code. The JSON code has a corresponding
> Flow JSON schema in the gecko profiler. Or whatever that's called.

I'd be curious to see how this works, as it sounds interesting: I think there's definitely room for having a textual rendering backend for this too.

Comment 6

[Matthew Gaudet (he/him) [:mgaudet]]

(In reply to Matthew Gaudet (he/him) [:mgaudet] from comment #1)
> Design Notes worth considering:
> 
> - The current design largely just exposes JSONPrinter's interface. It makes
>   no attempt to facade or provide any additional functionality. This feels
>   short sighted to me, as it means we couldn't easily adopt a new backend
>   (for example, one that does a more compressed output like MessagePack,
>   JSONB or BSON)
> 
>   We're also stuck with the requirement spew proceed entirely linearly,
>   which may be desirable to remove (c.f. ScopeExit above).

The more I think about this, the more this constraint concerns me. The particular thing that concerns me is that the guard class encourages using patterns that will only ever produce garbage logs unless we can remove the linear output requirement; 

i.e. In the attached patch, we create a StructuredSpewer::AutoClosingPrinter at the beginning of BaselineCompiler::compile, and keep it open until the exit of that function (in order that we might produce a 'succeeded' property on it) 

As a result of this, along with the linear spew requirement, we cannot now spew anything during the process of executing baseline compile; creating a second AutoClosingPrinter would produce JSON that looked like this: 

    [{
      "channel":"BaselineScripts",
      "location":{
        "filename":"/Users/mgaudet/mozilla-unified-clean/js/src/octane/deltablue.js",
        "line":880,
        "column":18
      },
      "baseline":{
          {
          "channel":"OtherChannel",
          "location":{
            "filename":"/Users/mgaudet/mozilla-unified-clean/js/src/octane/deltablue.js",
            "line":880,
            "column":18
          },

Which is asking for trouble. 

It seems, increasingly, like this spewer only makes sense if I can provide atomic access to the JSONPrinter or other backend; However, then we could be in a position where each spewer allocates, which means having to deal with memory management, and a level of increased complexity from having to manage an interface between the compiler and the JSON printer. 

Note: the current spewer doesn't really try to solve this problem, but it does feel like this design sort of cries out for it.

If I were a crazier person, the answer would lie in having the spewer manage a JSObject, upon which we'd call toString and append to the output log, atomically. That seems crazy though. Right?

Comment 7

[Matthew Gaudet (he/him) [:mgaudet]]

(In reply to Matthew Gaudet (he/him) [:mgaudet] from comment #6)
 
> It seems, increasingly, like this spewer only makes sense if I can provide
> atomic access to the JSONPrinter or other backend; However, then we could be
> in a position where each spewer allocates, which means having to deal with
> memory management, and a level of increased complexity from having to manage
> an interface between the compiler and the JSON printer. 

(To make it explicit, this would also solve the background thread problem by providing an excellent mutual exclusion point)

Comment 8

[Matthew Gaudet (he/him) [:mgaudet]]

Attachment: Bug 1504005 - Initial Structured Spewer r?jandem

This spewer design has two goals:

  1. Provide a spew mechanism that has first-class support for slicing and
     dicing output. This means that filtering by script and channel should be
     the dominant output mechanism.
  2. Provide a simple powerful mechanism for getting information out of the
     compiler and into tools. I'm inspired by tools like CacheIR analyzer,
     IR Hydra, and the upcoming tracelogger integration into perf.html.

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/f7f8b232d111
Initial Structured Spewer r=jandem

Comment 10

[Cristian Brindusan [:cbrindusan]]

Backed out changeset f7f8b232d111 (Bug 1504005) for devtools failures on browser_dbg_rr_breakpoints-01.js.

Backout: https://hg.mozilla.org/integration/autoland/rev/937ed33f8229ec736cc467e2d323087edb9b7c6f

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=f7f8b232d111ba86b0ac3d9c7aa65a7be21f82ea&selectedJob=214383861

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=214383861&repo=autoland&lineNumber=8976

Comment 11

[Matthew Gaudet (he/him) [:mgaudet]]

I'm definitely baffled by this one.

Brian: I'm seeing this failure with this patch applied: 

 0:13.12 TEST_START: devtools/client/debugger/new/test/mochitest/browser_dbg_rr_breakpoints-01.js
 0:13.71 GECKO(49186) MIDDLEMAN 49192 /var/folders/b7/yvcc5cld3wg97tl62wbcl9zw0000gn/T/TempRecording.49186.1
 0:13.78 INFO Waiting for event: 'RecordingFinished' on [object ParentProcessMessageManager].
 0:14.07 GECKO(49186) RECORDING 49193 /var/folders/b7/yvcc5cld3wg97tl62wbcl9zw0000gn/T/TempRecording.49186.1
 0:14.26 GECKO(49186) Spew[49193]: WARNING: Repeated accesses to the same dirty address 0x0
 0:14.26 GECKO(49186) ***** Fatal Record/Replay Error *****
 0:14.26 GECKO(49186) HandleDirtyMemoryFault failed 0x0

Would you be able to help shed some light on what HandleDirtyMemoryFault is trying to suggest to me?

Comment 12

[Matthew Gaudet (he/him) [:mgaudet]]

(oh, there is one mozilla::Atomic in here; however, I tried changing it to mozilla::recordreplay::Behavior::DontPreserve, and it didn't fix anything, but I think is the right choice here?)

Comment 13

[Brian Hackett [Laid off!]]

(In reply to Matthew Gaudet (he/him) [:mgaudet] from comment #11)
> I'm definitely baffled by this one.
> 
> Brian: I'm seeing this failure with this patch applied: 
> 
>  0:13.12 TEST_START:
> devtools/client/debugger/new/test/mochitest/browser_dbg_rr_breakpoints-01.js
>  0:13.71 GECKO(49186) MIDDLEMAN 49192
> /var/folders/b7/yvcc5cld3wg97tl62wbcl9zw0000gn/T/TempRecording.49186.1
>  0:13.78 INFO Waiting for event: 'RecordingFinished' on [object
> ParentProcessMessageManager].
>  0:14.07 GECKO(49186) RECORDING 49193
> /var/folders/b7/yvcc5cld3wg97tl62wbcl9zw0000gn/T/TempRecording.49186.1
>  0:14.26 GECKO(49186) Spew[49193]: WARNING: Repeated accesses to the same
> dirty address 0x0
>  0:14.26 GECKO(49186) ***** Fatal Record/Replay Error *****
>  0:14.26 GECKO(49186) HandleDirtyMemoryFault failed 0x0
> 
> Would you be able to help shed some light on what HandleDirtyMemoryFault is
> trying to suggest to me?

Hi, the HandleDirtyMemoryFault message is shown when a replaying process crashed.  Normally this will generate a crash report, but the crash reporter is disabled when running mochitests.  The clearest way to see the problem is in the treeherder log, which shows a crash at MOZ_RELEASE_ASSERT(mThread->CanAccessRecording()) in toolkit/recordreplay/Thread.h, inside Preamble_getenv on a JS helper thread.

The assertion which failed is checking that the current thread is allowed to access the recording, so that it can save information about events that are happening, in this case that a getenv call was made and the value that was returned.  We don't allow events like these to ever be recorded on JS helper threads, because their behavior can vary between recording and replaying according to the JS compilation, GC, etc. activity that is happening.

The best way to fix this is I think to avoid calling getenv on the helper thread if mozilla::recordreplay::IsRecordingOrReplaying().  We have to do this in a few other places in the JS engine, such as js::InferSpewActive.  FWIW I'm hoping to improve this situation soon and allow getenv calls to happen at any time.  Sorry about the trouble.

Comment 14

[Matthew Gaudet (he/him) [:mgaudet]]

Thanks! I really appreciate the pointer. It would have taken me quite a long time to get to that point without you!

Guarding all the getenv accesses seems to have done it locally, and running try now.

Comment 15

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/88ca4ffc6f68
Initial Structured Spewer r=jandem

Comment 16

[Razvan Maries]

https://hg.mozilla.org/mozilla-central/rev/88ca4ffc6f68