Closed Bug 766752 Opened 12 years ago Closed 11 years ago

Ionmonkey: Graph to differentiate between running/compiling times of baseline/Ion

Categories

(Core :: JavaScript Engine, defect)

defect
Not set
normal

Tracking

()

RESOLVED FIXED

People

(Reporter: h4writer, Assigned: h4writer)

Details

(Whiteboard: [ion:t])

Attachments

(5 files, 14 obsolete files)

765 bytes, application/javascript
Details
628 bytes, text/css
Details
4.80 KB, text/x-python
Details
23.39 KB, patch
jandem
: review+
h4writer
: checkin+
Details | Diff | Splinter Review
6.21 KB, patch
Details | Diff | Splinter Review
I was interested in the compilation/running times of the different javascript engines and quickly created a little script to extract that information. This was hacked together and not intended to land, but different people showed interest to add it permanently in the engine. This bug is to allow other people to create these graphs and to get that patch into land-able state.

The graphs look like:
http://alasal.be/ionmonkey/ss.html
http://alasal.be/ionmonkey/v8.html
(I'll try to keep them updated)

Howto create such graphs (linux, 32bit only atm):

1) Patch engine with the "hooks patch".

2) Run your favorite benchmark and save the output the engine generates.

3) Run the python script I've added with as first argument the file just created by running the benchmark.

4) Save the output of the python script. That's the html output.

5) Download the css and js file and put it in the same directory
Attached file Python script to generate HTML file (obsolete) —
Attached file Stylesheet (obsolete) —
Attached file Javascript file
What should happen before patch is proper:
- add support for all platforms (the getticks function only works on 32bit linux) 
- add configure flag to not always output this information
- ...

Currently I don't have the time to properly do this, as I'm still having exams. So feel free to improve this! I think djvj wanted to do this ...
This is the code I've used for measuring ticks and contains also the information to do this on other platforms:
http://www.mcs.anl.gov/~kazutomo/rdtsc.html
Attached file Python script to generate HTML file (obsolete) —
The logs already contain information about bailouts, forgot to add this information to the graph.
Attachment #635092 - Attachment is obsolete: true
Attached file Stylesheet
Minor adjustments to the colors + added color for bailouts
Attachment #635093 - Attachment is obsolete: true
1) Better organized
2) Works for x86, x64 and powerpc
3) Improved performance by only printing the information after end of benchmark
4) Higher accuracy by subtracting the time spend in the logging functions
Attachment #635090 - Attachment is obsolete: true
I was playing around with a slightly modified version of your patch today.  I wrote this python script to generate the raw span data for doing a finer grained visualization of the data.

It won't work with the output your patch has because of my changes to the text that the logging functions output, but I'm throwing a comment in for future reference.  I'm just gonna pastebin my code so it doesn't clutter up your attachments.

Python script to generate JSON: http://pastebin.mozilla.org/1681423

Note that it generates a JSON-ified data structure, and then outputs an escaped string encoding of that, because loading that large of a JSON structure directly via literals causes problems in Firefox.

Javascript code to render the above JSON into a Canvas: http://pastebin.mozilla.org/1681460

These are a bit ugly and works in progress.  There are hardcoded constants galore.  Sorry :(  I'll fix it up as time allows.

Ultimately, I think it's possible to write a JS frontend that provides the following info:

1. When hovering over any given point in the visualization, it can show a sidebar with info about the script running, being compiled, or being interpreted at that point.
2. It can highlight all other relevant areas that deal with the same script (i.e. the other places where the script is being compiled, invalidated, run, interpreted, etc.) so we can get a better idea of what happens to a given script as it runs over time.
I've added the improvement djvj listed over irc. Thanks!

(In reply to Kannan Vijayan [:djvj] from comment #9)
> Javascript code to render the above JSON into a Canvas:
> http://pastebin.mozilla.org/1681460

Cool! It was on my TODO list to create this.
I haven't had the time to dive into the code yet.
I'll try to do this as fast as possible.
Attachment #636605 - Attachment is obsolete: true
Nice work on this Hannes.  I have a few suggestions that I think might be of interest:

1. log() is an incredibly generic name to use up for something like this.  I'd suggest something like jsTraceLog() for the function call name.  Likewise the logging enum names (LOGGING_ION_COMPILE_START, etc.) might be better named (TRACELOG_ION_COMPILE_START, etc.).  Once again "LOGGING" is a pretty generic term to occupy for this purpose.

2. Change the dump from writing to stdout (via printf) to writing to stderr via (fprintf(stderr, ...)).  Currently it interleaves with the actual stdout of the script

3. The resulting dumps are more likely to be given to programs to parse than looked at directly.  Given that, I think having a more parseable dump format (comma separated, no spaces, short tokens) seems reasonable.  Also seems to be a good idea to prepend the output with a unique token (say TRACELOG) so we can pick out those lines easily from a parser:

Instead of "23894913, Start, Ion compile, foo.js:33",
"TRACELOG:23894913,start,ion_compile,foo.js:33"

Then we can just write our scripts to use "line.startswith('TRACELOG:') to pick out the lines we want.

4. Logging of Ion script invalidations would be useful for future reference.  These don't have a start/end duality like the rest of the logs, but we'd definitely benefit from being able to tell when scripts get invalidated:

The code to change is roughly:
diff --git a/js/src/ion/Ion.cpp b/js/src/ion/Ion.cpp
--- a/js/src/ion/Ion.cpp
+++ b/js/src/ion/Ion.cpp
@@ -1301,16 +1301,17 @@ ion::Invalidate(FreeOp *fop, const Vecto
     // Add an invalidation reference to all invalidated IonScripts to indicate
     // to the traversal which frames have been invalidated.
     for (size_t i = 0; i < invalid.length(); i++) {
         JSScript *script = invalid[i].script;
         if (script->hasIonScript()) {
             IonSpew(IonSpew_Invalidate, " Invalidate %s:%u, IonScript %p",
                     script->filename, script->lineno, script->ion);
             script->ion->incref();
+            log(LOGGING_ION_INVALIDATE, script->filename, script->lineno);
         }
     }
 
     for (IonActivationIterator iter(fop->runtime()); iter.more(); ++iter)
         InvalidateActivation(fop, iter.top(), false);
 
     // Drop the references added above. If a script was never active, its
     // IonScript will be immediately destroyed. Otherwise, it will be held live


In the meantime, I updated my JS code and visualizer a bit yesterday.  It now supports some rudimentary interactivity like zooming in, out, and scrolling up/down.  It also reports the filename/lineno of the relevant JSScripts as you mouse over the visualization.

Furthermore, if you click on a particular span, it'll highlight (actually, darken) all regions in the visualization for that same script.  So you can click on an IonCompile for a script, and see everywhere else that script shows up, including JM compiles, JM runs, other Ion compiles, and Ion runs.  The highlighting is preserved across zooms and scrolls, so you can zoom in, click on a span, and then zoom out to get a picture of that script across the entire runtime.

The UI is really crappy (for now), and there might be some small bugs in it, but it works for the most part.  There's no legend, so just FYI the current color mappings are:

Ion Compile - Magenta
Ion Run - Red
JM Compile - Blue
JM Run - Green
Intepreter - Gray
GC - blu-ish (need better color for this, maybe yellow?)

The "highlight" colors for each of these are just darkened versions of each.

You can check it out at http://people.mozilla.org/~kvijayan/visualize-trace/test.html

It just shows data collected from an Early-Boyer run.

WARNINGS:
1. It loads around 27 Megs of JSON data when you visit, so be prepared to use some memory and wait a few seconds.
2. The UI is really crappy (as I mentioned before), so you need to resize your browser window to something wider than about 1600 pixels or so for the UI to render appropriately.  If you don't see the interactive controls, keep widening the browser ;)
Should be ready for check-in. I had no idea who I should take for reviewer, so it became you jandem. If you think somebody else should review it, just forward it. Thanks
Assignee: general → hv1989
Attachment #637722 - Attachment is obsolete: true
Attachment #638015 - Flags: review?(jdemooij)
Comment on attachment 638015 [details] [diff] [review]
Patch to add hooks in javascript engine

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

Sorry for the delay, forgot to get to it on Monday.

This looks nice and the visualization is really useful; the comments below are mostly style nits. You should probably ask dmandelin's approval as well, to make sure he's okay with adding this to the engine.

::: js/src/Makefile.in
@@ +141,5 @@
>  		Statistics.cpp \
>  		StringBuffer.cpp \
>  		Unicode.cpp \
>  		Xdr.cpp \
> +		tracelogging.cpp \

Nit: rename the file to TraceLogging.cpp

::: js/src/methodjit/Compiler.cpp
@@ +981,2 @@
>          jit = MakeJITScript(cx, script);
> +        traceLog(TRACELOG_JM_COMPILE_STOP, script->filename, script->lineno);

The actual compilation is done below, by the "cc.compile()" call (a single JITScript can have multiple JITChunks).

How about a RAII helper, so that we can put something like this at the top of CanMethodJIT:

AutoTraceLog(TRACELOG_JM_COMPILE, script);

The constructor and destructor can then log the start/stop messages.

::: js/src/methodjit/MethodJIT.cpp
@@ +1084,5 @@
>      JITScript *jit = script->getJIT(fp->isConstructing(), cx->compartment->needsBarrier());
>  
>      JS_ASSERT(cx->regs().pc == script->code);
>  
> +    traceLog(TRACELOG_JM_START, script->filename, script->lineno);

Nit: since this pattern is common, you may want to add a TraceLog function that takes a JSScript *.

::: js/src/tracelogging.cpp
@@ +16,5 @@
> +#if JS_TRACE_LOGGING
> +
> +#if defined(__i386__)
> +
> +static __inline__ unsigned long long

methodjit/Logging.h has a Profiler class which uses PRMJ_Now to get the time in nanoseconds, it would be great if we could reuse that (if there are no noticeable differences).

@@ +60,5 @@
> +#endif
> +
> +struct LoggerEntry {
> +    uint32_t tick_;
> +    char* file_;

Nit: "const char *file_"

@@ +62,5 @@
> +struct LoggerEntry {
> +    uint32_t tick_;
> +    char* file_;
> +    uint32_t lineno_;
> +    uint8_t type_;

Nit: Can this be TraceLogType?

@@ +76,5 @@
> +
> +unsigned long long delay = 0;
> +unsigned int numEntries = 1000000;
> +unsigned int curEntry = 0;
> +LoggerEntry *entries = NULL;

It would be good to add these and the functions below to a new class? The TraceLog function you expose could call a class method.

@@ +134,5 @@
> +
> +void
> +flushTraceLog()
> +{
> +    fprintf(stderr, "TRACELOGGING_START\n");

Can we print to a file instead of stdout here? Like IonMonkey's ion.cfg file.

@@ +143,5 @@
> +            fprintf(stderr, "TRACELOG:%lld,", (unsigned long long)entries[i].tick());
> +
> +        switch(entries[i].type()) {
> +        case TRACELOG_ION_COMPILE_START: 
> +            fprintf(stderr, "start,ion_compile"); break;

Nit: give the break its own line or put the case, fprintf and break on the same line:

case X:   fprintf("x");   break;
case XYZ: fprintf("xyz"); break;

::: js/src/tracelogging.h
@@ +35,5 @@
> +
> +#if JS_TRACE_LOGGING
> +void traceLog (TraceLogType type,  const char* file, int lineno);
> +void traceLog (TraceLogType type);
> +void flushTraceLog ();

Nit: TraceLog, FlushTraceLog (capitalize first letter for non-member functions)
Attachment #638015 - Flags: review?(jdemooij)
Thanks for the great review. 
I'll try to update the patch as soon as possible to address the comments and talk with dmandelin about it.

I only can work in the weekends, therefore the delay.
In the few hours I got I decide to update the graph and build system behind http://www.alasal.be/ionmonkey first.
The generation of graphs is now almost fully automatic and enables me to create graphs more easily.
The new system will also make it possible to generate graphs for "--no-jm", expect them to show up this week.
(In reply to Hannes Verschore from comment #14)
> Thanks for the great review. 
> I'll try to update the patch as soon as possible to address the comments and
> talk with dmandelin about it.

I saw this before and it's very cool. One look told me a lot of things about the current state of IM that I never knew before. I definitely want this to be part of the engine.

It's hard to give more detailed feedback without really trying to use the visualizations to solve problems, but I do see a couple things I would add (not required for landing, though):

 - Somehow also be able to show total time spent in each activity, e.g,. to quickly read off fraction of time spent in GC.
 - The tooltips are hard to understand. I would change the time so that the run starts from 0, maybe reformat the time to give smaller and/or rounder numbers. I also don't understand what the notations on the bottom mean.
(In reply to David Mandelin [:dmandelin] from comment #15)
>  - Somehow also be able to show total time spent in each activity, e.g,. to
> quickly read off fraction of time spent in GC.
>  - The tooltips are hard to understand. I would change the time so that the
> run starts from 0, maybe reformat the time to give smaller and/or rounder
> numbers. I also don't understand what the notations on the bottom mean.

1) Added the total time spent in each activity per benchmark
2) Tooltips now have the block nummer instead of the unreadable ticks
3) The bottom is actually the callstack. (The function at the bottom is the currently running function)

The improvements should be visible shortly.
(In reply to Hannes Verschore from comment #16)
> (In reply to David Mandelin [:dmandelin] from comment #15)
> >  - Somehow also be able to show total time spent in each activity, e.g,. to
> > quickly read off fraction of time spent in GC.
> >  - The tooltips are hard to understand. I would change the time so that the
> > run starts from 0, maybe reformat the time to give smaller and/or rounder
> > numbers. I also don't understand what the notations on the bottom mean.
> 
> 1) Added the total time spent in each activity per benchmark
> 2) Tooltips now have the block nummer instead of the unreadable ticks
> 3) The bottom is actually the callstack. (The function at the bottom is the
> currently running function)
> 
> The improvements should be visible shortly.

Cool. Now I can see that GC is 13% of the time on splay and 0-2% elsewhere. (If only I knew exactly what that meant. :-) I know that means taking GC time down to 0 would only be a 2% score improvement. But I don't know if GGC would help allocation or cache behavior and have a greater effect.)
(In reply to Jan de Mooij (:jandem) from comment #13)
> Nit: rename the file to TraceLogging.cpp
done

> AutoTraceLog(TRACELOG_JM_COMPILE, script);
done

> Nit: since this pattern is common, you may want to add a TraceLog function
> that takes a JSScript *.
done

> methodjit/Logging.h has a Profiler class which uses PRMJ_Now to get the time
> in nanoseconds, it would be great if we could reuse that (if there are no
> noticeable differences).
The overhead of logging through PRMJ_Now is too high. Very noticeable drop in performance on v8-regexp.
Therefore I decided against it.

> Nit: "const char *file_"
I can't free it if it is defined as const

> Nit: Can this be TraceLogType?
You mean TraceLogEntry?

> It would be good to add these and the functions below to a new class? The
> TraceLog function you expose could call a class method.
Is it really necessary for a class? There is no reason to have multiple instances and I assume it adds overhead when calling the methods. 

> Can we print to a file instead of stdout here? Like IonMonkey's ion.cfg file.
sure.

> Nit: TraceLog, FlushTraceLog (capitalize first letter for non-member
> functions)
done
Attachment #638015 - Attachment is obsolete: true
Attachment #642029 - Flags: review?(jdemooij)
Attached file Python script to generate HTML file (obsolete) —
Attachment #635350 - Attachment is obsolete: true
Fixed various issues. I noticed the graphs report more jm compilation with the logging place adjusted, like requested.
Attachment #642029 - Attachment is obsolete: true
Attachment #642029 - Flags: review?(jdemooij)
Attachment #642417 - Flags: review?(jdemooij)
Updated python file to generate the graphs.
Attachment #642097 - Attachment is obsolete: true
Attachment #642417 - Attachment is patch: true
Comment on attachment 642417 [details] [diff] [review]
Patch to add hooks in javascript engine

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

This seems almost ready, but I'd still like to wrap all the globals in a class somehow. It seems a lot more readable.

::: js/src/Makefile.in
@@ +143,5 @@
>  		Statistics.cpp \
>  		StringBuffer.cpp \
>  		Unicode.cpp \
>  		Xdr.cpp \
> +		TraceLogging.cpp \

Nit: we should only compile this if logging is enabled, something like the ENABLE_METHODJIT define:

ifdef ..TRACE_LOGGING..
CPPSRCS += TraceLogging.cpp
endif

::: js/src/TraceLogging.cpp
@@ +86,5 @@
> +
> +unsigned long long delay = 0;
> +unsigned int numEntries = 1000000;
> +unsigned int curEntry = 0;
> +TraceLogEntry *entries = NULL;

I still think these should be in a class, with all the functions below ("private" if possible). It's not a lot of work and it seems cleaner to have one global and call methods on it. This will also make it much easier to store data per-runtime or per-compartment if we ever want that in the future. And it avoids name clashes (cleanup/init etc are pretty generic).

@@ +87,5 @@
> +unsigned long long delay = 0;
> +unsigned int numEntries = 1000000;
> +unsigned int curEntry = 0;
> +TraceLogEntry *entries = NULL;
> +FILE *out = fopen(TRACE_LOG_DIR "tracelogging.log", "w");

Nit: FlushTraceLog should do this if out == NULL.

@@ +117,5 @@
> +
> +void
> +log_line(TraceLogType type, const char* file, uint32_t lineno)
> +{
> +    unsigned long long now = rdtsc();

Nit: uint64_t here and everywhere else.

@@ +125,5 @@
> +
> +    char *copy = NULL;
> +    if (file != NULL) {
> +        copy = (char*) malloc(strlen(file) + 1);
> +        strcpy(copy, file);

Nit: copy = strdup(file)?

@@ +133,5 @@
> +
> +    if (curEntry >= numEntries)
> +        grow();
> +
> +    delay += rdtsc()-now;

Not sure I understand the use of the |delay| variable. Wouldn't it be easier to remove it and just log the result of rdtsc()? Or maybe "now - ticks-at-startup".

@@ +165,5 @@
> +        else
> +            fprintf(out, "TRACELOG:%lld,", (unsigned long long)entries[i].tick());
> +
> +        switch(entries[i].type()) {
> +        case TRACELOG_ION_COMPILE_START: 

Nit: indent case labels with two spaces.

::: js/src/TraceLogging.h
@@ +54,5 @@
> +  public:
> +    AutoTraceLog(TraceLogType start, TraceLogType stop, JSScript* script)
> +      : stop(stop)
> +    {
> +        TraceLog (start, script);

Nit: no space between TraceLog and (, and below.
Attachment #642417 - Flags: review?(jdemooij)
Attached patch Patch: JIT logging hooks WIP (obsolete) — Splinter Review
Adding jit hooks for Ion -> Ion calls.
TODO:
- test bailouts
- JM -> Ion calls
-> JM -> JM calls
Attached patch Patch: tracelogging hooks WIP (obsolete) — Splinter Review
Almost ready. I only need to check for style nits etc.
Attachment #642417 - Attachment is obsolete: true
Attachment #648176 - Attachment is obsolete: true
Attached patch Patch: tracelogging hooks (obsolete) — Splinter Review
Should address all issues you raised. I've added also some extra code for when not all entries can get hold in memory and also code for when encountering file limit of 2GB.

Note: I've added "--enable-trace-logging-same-engine-calls". This is for logging ion -> ion calls. This isn't done in this patch. Get's used in the next patch ;)
Attachment #649147 - Attachment is obsolete: true
Attachment #649442 - Flags: review?(jdemooij)
Attached patch Patch: tracelogging ASM hooks (obsolete) — Splinter Review
Adds hooks for JM -> Ion logging (#775818 created inline cache for these calls and therefore they didn't get logged anymore)

Adds hooks for ion -> ion logging. Default off, because this causes huge logging files (6BG - 8GB for v8) and also slowdowns the engine significantly (because of the huge amount of logging calls). But could be useful for specific cases. Not needed in the graphs I make, therefor defaulted off.

JM -> JM logging is follow-up bug. First I don't need it for the graphs I make. Secondly I don't understand that code good enough atm. For now I think it would be wasted time, but if somebody wants/needs it, let me know.
Attachment #649444 - Flags: review?(jdemooij)
And ignore the "PR_SetCurrentThreadName" changes. I forget to remove them from the patch.
Comment on attachment 649442 [details] [diff] [review]
Patch: tracelogging hooks

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

Looks good, thanks for not giving up ;) The comments below are mostly style nits.

::: js/src/TraceLogging.cpp
@@ +60,5 @@
> +    return(result);
> +}
> +#endif
> +
> +const char* TraceLogging::type_name[] = {

Nit: static const char *

@@ +119,5 @@
> +    if (nentries == NULL) {
> +        flush();
> +        return;
> +    }
> +    

Nit: there's some trailing whitespace here and below (tip: the hg color extension can show whitespace)

@@ +161,5 @@
> +    if (out == NULL)
> +        out = fopen(TRACE_LOG_DIR "tracelogging.log", "w");
> +
> +    // Print all log entries into the file
> +    for(unsigned int i = 0; i < curEntry; i++) {

Nit: space between "for" and "(".

@@ +207,5 @@
> +TraceLogging::defaultLogger()
> +{
> +    if (_defaultLogger == NULL) {
> +        _defaultLogger = new TraceLogging();
> +        atexit (releaseDefaultLogger);

This is not necessary, the process will exit immediately afterwards so the OS will free all its memory (and logging won't be enabled in (official) release builds anyway).

@@ +221,5 @@
> +        _defaultLogger = NULL;
> +    }
> +}
> +
> +/* Helpers functions for asm calls */

Nit: s/helpers/helper

::: js/src/configure.in
@@ +3514,5 @@
> +    ENABLE_TRACE_LOGGING=1,
> +    ENABLE_TRACE_LOGGING= )
> +
> +MOZ_ARG_ENABLE_BOOL(trace-logging,
> +[  --enable-trace-logging-same-engine-calls   Enable trace logging of function calls to the same javascript engine],

I think we can remove this one, so that there's just one option to enable to make everything work. If we don't want to enable it on certain platforms we can use an extra #ifdef in the compiler.

::: js/src/ion/Ion.cpp
@@ +1192,5 @@
>      void *jitcode = code->raw();
>  
> +#if JS_TRACE_LOGGING
> +    TraceLogging* logger = TraceLogging::defaultLogger();
> +    logger->log(TraceLogging::ION_CANNON_START, script);

A static log function to grab the default logger and log to it seems slightly less verbose:

TraceLogging::log(...);

Will this also allow us to remove the #if/#endif if we define the (inline) function to be empty if logging is disabled?

::: js/src/jsgc.cpp
@@ +4222,5 @@
>      JS_AbortIfWrongThread(rt);
>  
> +#if JS_TRACE_LOGGING
> +    AutoTraceLog logger(TraceLogging::defaultLogger(), 
> +                        TraceLogging::GC_START, 

Nit: some trailing whitespace here.

::: js/src/jsinterp.cpp
@@ +1246,5 @@
> +#if JS_TRACE_LOGGING
> +    AutoTraceLog logger(TraceLogging::defaultLogger(),
> +                        TraceLogging::INTERPRETER_START,
> +                        TraceLogging::INTERPRETER_STOP,
> +                        script);

JSOP_CALL can call a new script without calling Interpret (it pushes a new frame and starts interpreting the callee). Can you make sure that's handled correctly?

::: js/src/methodjit/MethodJIT.cpp
@@ +1125,5 @@
> +                        TraceLogging::JM_SAFEPOINT_START, 
> +                        TraceLogging::JM_SAFEPOINT_STOP,
> +                        cx->fp()->script());
> +#endif
> +    

Nit: whitespace
Attachment #649442 - Flags: review?(jdemooij) → review+
Comment on attachment 649444 [details] [diff] [review]
Patch: tracelogging ASM hooks

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

Looks reasonable, but if this creates gigabytes of data, isn't there a noticeable overhead for Ion -> Ion calls? I'm not sure if it's worth the complexity if we're not planning on enabling it by default for trace logs?

::: js/src/ion/CodeGenerator.cpp
@@ +695,5 @@
> +    masm.passABIArg(eax);
> +    masm.mov(Imm32(TraceLogging::ION_CANNON_START), ecx);
> +    masm.passABIArg(ecx);
> +    masm.movePtr(Address(calleereg, offsetof(JSFunction, u.i.script_)), edx);
> +    masm.passABIArg(edx);

This won't work on ARM. Furthermore, we have to save all volatile registers (the call could clobber objreg), so you need a saveVolatile() before and restoreVolatile() call after it. After calling saveVolatile() you can pick any volatile register for passABIArg though so that will also make it work on ARM.

@@ +715,5 @@
>  
> +#if JS_TRACE_LOGGING && JS_TRACE_LOGGING_SAME_ENGINE
> +    masm.push(eax);
> +    masm.push(ecx);
> +    masm.push(edx);

You can use saveVolatile()/restoreVolatile() instead.

::: js/src/methodjit/MonoIC.cpp
@@ +703,5 @@
>          masm.orPtr(Imm32(ion::IonFrame_Entry), stackPushed);
>          masm.push(stackPushed);
>  
> +#if JS_TRACE_LOGGING
> +        masm.setupABICall(Registers::NormalCall, 3);

We have to save the ionScript register (and maybe other registers) before making this call.
Attachment #649444 - Flags: review?(jdemooij)
To be sure, I requested another review. But the changes are mostly the ones requested. Thanks for the "hg color" tip. 

(In reply to Jan de Mooij (:jandem) from comment #29)
> Comment on attachment 649444 [details] [diff] [review]
> Looks reasonable, but if this creates gigabytes of data, isn't there a
> noticeable overhead for Ion -> Ion calls? I'm not sure if it's worth the
> complexity if we're not planning on enabling it by default for trace logs?
Yes, it has noticeable overhead. Removed from this patch therefore.

> A static log function to grab the default logger and log to it seems slightly less verbose:
> TraceLogging::log(...);
> Will this also allow us to remove the #if/#endif if we define the (inline) function to be empty if logging is disabled?
Because there is already a global function to do this (for asm logging). Therefore I just reused those now.
This would make it possible to define (inline) empty functions. But mostly the AutoTraceLogger is used.
There is no real gain and decided against it. Also now not using TraceLogger removes all code of tracelogging.cpp.
So no interference...

> JSOP_CALL can call a new script without calling Interpret (it pushes a new frame and starts interpreting the callee). Can you make sure that's handled correctly?
Is this interpreter -> interpreter calls? In that case I wouldn't do it. JM -> JM and IM -> IM calls aren't logged either.
(Because it will generate huge data)

> @@ +207,5 @@
>> +TraceLogging::defaultLogger()
>> +{
>> +    if (_defaultLogger == NULL) {
>> +        _defaultLogger = new TraceLogging();
>> +        atexit (releaseDefaultLogger);
> This is not necessary, the process will exit immediately afterwards so the OS will free all its memory (and logging won't be enabled in (official) release builds anyway).

By default the logger only starts writing the log file on deconstruction. Therefore this is needed.
Attachment #649442 - Attachment is obsolete: true
Attachment #649809 - Flags: review?(jdemooij)
Comment on attachment 649809 [details] [diff] [review]
Patch: tracelogging hooks

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

Thanks, looks good! r=me with the few nits below addressed.

::: js/src/TraceLogging.cpp
@@ +119,5 @@
> +    if (nentries == NULL) {
> +        flush();
> +        return;
> +    }
> +    

Nit: still some whitespace here and below.

::: js/src/ion/Ion.cpp
@@ +1202,5 @@
> +#if JS_TRACE_LOGGING
> +    if (status == IonExec_Bailout)
> +        TraceLog(TraceLogging::defaultLogger(),
> +                 TraceLogging::ION_CANNON_BAIL,
> +                 script);

Nit: all TraceLog calls in this file fit on a single line (otherwise the if/else would need {} )

::: js/src/yarr/YarrJIT.h
@@ +46,5 @@
> +#if JS_TRACE_LOGGING
> +#include "TraceLogging.h"
> +#endif
> +
> +using namespace js;

This file is probably included in many other (header-)files, so to avoid making "js" available everywhere just use js::AutoTraceLog etc below.
Attachment #649809 - Flags: review?(jdemooij) → review+
Attachment #649809 - Flags: checkin+
Updated patch to report Ion->Ion calls
Attachment #649444 - Attachment is obsolete: true
Hannes, I don't know if you still have any use for this bug. Close it, if not.
OS: Linux → All
Hardware: x86 → All
Summary: Ionmonkey: Graph to differentiate between running/compiling times of JM/Ion → Ionmonkey: Graph to differentiate between running/compiling times of baseline/Ion
Status: NEW → RESOLVED
Closed: 11 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.