Timer events in V8

[Talha]

Hello,

I am looking to understand the role of timer events in V8. Do the  timeline plots generated by profviz.html provide accurate information about how much time was spent while executing code performing a particular operation (e.g. looking at "compile unopt" row, can I say with confidence that "full code generator" worked only for the time shown by this plot)? Also, am I correct in understanding that the %ages shown next to each category represent % execution time spent in each category and should sum to a 100% ?

From what I understand, these charts are generated using timing information associated with "timer-event-start" and "timer-event-end" events which are inserted whenever a particular code portion starts/ends execution in V8. Looking at these events should accurately tell me which part of the code is responsible for which functionality. Am I correct? Please point out if I misunderstood something. 

Also, I think I understand most of what the plot represents except for "external". I learned it corresponds to external callbacks in V8. Can anyone clarify what these external callbacks are? 

I would appreciate some confirmation/clarification of my understanding!

Thanks all !

[Ben Noordhuis]

On Sun, Oct 30, 2016 at 2:03 AM, Talha <tghaf...@gmail.com> wrote:
> Hello,
>
> I am looking to understand the role of timer events in V8. Do the timeline
> plots generated by profviz.html provide accurate information about how much
> time was spent while executing code performing a particular operation (e.g.
> looking at "compile unopt" row, can I say with confidence that "full code
> generator" worked only for the time shown by this plot)? Also, am I correct
> in understanding that the %ages shown next to each category represent %
> execution time spent in each category and should sum to a 100% ?

I think at least some cooperation from the host application is
necessary to get accurate numbers. We had an issue in node.js some
years back where it never summed to 100% due to (lack of) idle time
accounting.

> From what I understand, these charts are generated using timing information
> associated with "timer-event-start" and "timer-event-end" events which are
> inserted whenever a particular code portion starts/ends execution in V8.
> Looking at these events should accurately tell me which part of the code is
> responsible for which functionality. Am I correct? Please point out if I
> misunderstood something.

That's right. It's calculated from more than just timer events - the
built-in sampling profiler is involved as well - but that's details.

> Also, I think I understand most of what the plot represents except for
> "external". I learned it corresponds to external callbacks in V8. Can anyone
> clarify what these external callbacks are?

External callbacks are callbacks from V8 to the host application. For
example, when JS code calls a C++ API function that you created with
v8::FunctionTemplate::New() or
v8::ObjectTemplate::SetNamedPropertyHandler(), that's counted as
external callback time.

[Talha]

Hi Ben,

Thanks a lot for the response. That validates my understanding.

In the log files, I am observing the following pattern with timer events at some places (with IcMiss, CompileFullCode, Execute and maybe for some others as well):

start - start-end- start-end start-end - end. 

Let's say we consider this pattern for CompileFullCode events. What does it indicate? 

Does it mean that "compile_full_code" activity started with the first 'start' event and ended at the last 'end'? Can we consider the entirety of above pattern to belong to the "Full Code generator" activity and ignore the start - end pairs in between?

 

There may also be timer events for other activities (let's say icmiss events) in between these events. Would they also be considered part of this "FullCodeGen" activity?

Thanks,

Talha.

[Ben Noordhuis]

Can you post an excerpt from the log file? It's not entirely clear to
me what you mean.

[Talha]

Hi Ben,

Here are a couple of excerpts from the log file. I executed a simple Fibonacci application using node with --log-timer-events option.

timer-event-start,"V8.External",324787996

timer-event-start,"V8.CompileScriptMicroSeconds",324819996

timer-event-start,"V8.ParseMicroSeconds",324835996

timer-event-end,"V8.ParseMicroSeconds",324947996

timer-event-start,"V8.CompileMicroSeconds",324963996

timer-event-start,"V8.CompileFullCode",324983996

timer-event-start,"V8.CompileFullCode",324999996

timer-event-end,"V8.CompileFullCode",325035996

code-creation,Function,0,0x7315324c240,460," /home/talha/node_modules/fibonacci/example.js:1:11",0x297e43466190,~

timer-event-end,"V8.CompileFullCode",325083996

code-creation,Script,0,0x7315324c420,252,"/home/talha/node_modules/fibonacci/example.js",0x297e434662d0,~

timer-event-end,"V8.CompileMicroSeconds",325107996

timer-event-end,"V8.CompileScriptMicroSeconds",325119996

timer-event-end,"V8.External",325127996

--------------------------------------------------------------------------------------------------------

timer-event-start,"V8.GCCompactor",7460000

timer-event-start,"V8.External",7508000

timer-event-end,"V8.External",7524000

timer-event-start,"V8.External",12532000

timer-event-end,"V8.External",12548000

timer-event-end,"V8.GCCompactor",12596000

---------------------------------------------------------------------------------------------------------

I have also attached a .doc file having the log. You can see such patterns highlighted in the file. 

Thanks, 
Talha.

[Ben Noordhuis]

Thanks, I see what you mean now.

> Does it mean that "compile_full_code" activity started with the first
> 'start' event and ended at the last 'end'? Can we consider the entirety of
> above pattern to belong to the "Full Code generator" activity and ignore the
> start - end pairs in between?

Correct, V8.CompileScriptMicroSeconds is the main event, the ones in
between (like V8.ParseMicroSeconds) are phases.

> There may also be timer events for other activities (let's say icmiss
> events) in between these events. Would they also be considered part of this
> "FullCodeGen" activity?

I don't think so. IC misses are normally generated from running JS code.