MozillaWiki

Javascript Profiling: Difference between revisions

Page Discussion

Javascript Profiling (view source)

Revision as of 19:58, 19 September 2012

5,233 bytes added ,  19 September 2012
Note that this API plan has been set aside.
No edit summary
(Note that this API plan has been set aside.)
 
(11 intermediate revisions by one other user not shown)
Line 1: Line 1:
Note: the API described here has been set aside; it will not become part of the Mozilla platform. We're going to use the [https://developer.mozilla.org/en-US/docs/Performance/Profiling_with_the_Built-in_Profiler SPS profiler] as our profiling back end.
= Profiling API =
= Profiling API =


Line 4: Line 6:


As an idea of what should be possible to build on top of this API, see [http://unity3d.com/support/documentation/Manual/Profiler.html Unity's profiler],
As an idea of what should be possible to build on top of this API, see [http://unity3d.com/support/documentation/Manual/Profiler.html Unity's profiler],
The profiling API is centered around profiling particular "contexts" of information. These "contexts" represent a set of scripts which are to be profiled, and will be referred to as from the root object, or "the global." This concept is similar to the [[Debugger]] API. When profiling a script, the scripts being profiled are contained to the specified global.


== The Profiler object ==
== The Profiler object ==


There will be a global <tt>Profiler</tt> object available to instantiate to begin profiling other objects. The <tt>Profiler</tt> object has the following methods:
There will be a global <tt>Profiler</tt> object available to instantiate to begin profiling the runtime in which the profiler was created in. The <tt>Profiler</tt> object has the following methods:


<dl>
<dl>
Line 15: Line 15:
<dd>The constructor takes no arguments
<dd>The constructor takes no arguments


<dt>startProfiling(object)
<dt>start([sample_rate, [max_samples]])
<dd>Starts profiling the specified object's global's scripts. If the object's global is currently being profiled this instance, then an error is thrown.
<dd>Begins profiling. All arguments are optional. The sample rate is the time between samples of the call stack specified in microseconds (defaults to 1000 = 1ms). The sample rate is mostly a guideline as the platform being run might not guarantee the granularity of timing. Samples will not happen more frequently than the specified rate, but may occur more infrequently.
<dt>isProfiling(object)
 
<dd>Returns whether the specified object's global is being profiled or not by this instance.
A maximum number of samples can be specified as well, but the default is unlimited (0). If the maximum number of samples is reached, then the sample storage is treated as a ring buffer, discarding the oldest samples.
 
If some other Profiler object is profiling the runtime, then the other profiler is forcibly stopped. Eventually a call to stop() must be paired with this call to cease data collection.
<dt>isProfiling()
<dd>Returns whether profiling is active for this Profiler instance
<dt>frame()
<dt>frame()
<dd>Fetch the current object instance representing the current stack trace of invocation for the invoking context's global. Properties can be added to this object and will be persisted across invocations of this method so long as each invocation has the same backtrace. If the invoking context's global is not being profiled by the <tt>Profiler</tt> instance, then an error is thrown
<dd>Fetches an object to represent the current stack trace to be later returned via results(). This object can have any properties attached to it and will persist across different invocations of frame() so long as the same backtrace is present each time. All information specified here will later be available via results() with the full backtrace listed. By default this returns an empty object with no properties. If the profiler is not active or has been forcibly stopped, then an error is thrown.
<dt>info(object)
<dt>results()
<dd>Returns all information profiled for the object's global given. The format of the information is described below
<dd>Returns all profile information gathered. The data returned is all that is collected between the last invocation of reset() and all the sample data.
<dt>clearInfo(object)
<dt>samples()
<dd>Removes all known frame instances for the given object's global. Throws an error if the global is not being profiled
<dd>Returns all profiling samples gathered. The data returned is all that is collected between the last invocation of reset() and now. If profiling is turned on, it is disabled for the duration of this function.
<dt>stopProfiling(object)
<dt>reset()
<dd>Ceases profiling the specified object's global. Throws an error if the global is not being profiled.
<dd>Resets all information that is stored. This includes samples and also frame() information.
<dt>stop()
<dd>Ceases profiling on the runtime. If this profiler is not active or has been forcibly stopped, an error is thrown.


</dl>
</dl>


=== The return of <tt>.info()</tt> ===
=== The return of <tt>.results()</tt> ===


The return value is an object which is a hash containing all the information. The hash can loosely be viewed as a trie. Here's some example code:
The return value is an object which is a hash containing all the information. The hash can loosely be viewed as a trie. Here's some example code:
   
   
  profiler = new Profiler();
  // input.js
  profiler.startProfiling(this);
var p = new Profiler();              
function b() { profiler.frame().b = true; }
  function foo(n) {                     
  function a() { b(); profiler.frame().a = 4; }
    var sum = 0;                      
  a();
    for (var i = 0; i < n; i++) {    
  profiler.info() // => { 'input.js:3 (a)': {a: 4, 'input.js:2 (b)': {b: true}}}
        sum += i;                     
    }                                 
    var fac = 1;                     
    for (var i = 1; i < 2 * n; i++) { 
        fac *= i;                    
    }                                
    return sum + fac;                 
}                                     
                                       
  function bar(n) {                    
    p.frame().one = 1;                
    var info = p.frame();             
    info.two = 2;                     
    info.n  = n;                    
}                                    
                                       
  p.start();                 
foo(4000000);                         
bar(200);                             
p.stop();
                                       
  print(JSON.stringify(p.results()))     
 
And the following hash would be printed:
 
{                                                                 
  samples: 624,                                                     
  gcSamples: 1,                                                     
  micros: 12421,                                                     
  children: [                                                     
    {                                                             
      function: { file: 'input.js', line: 1, name: '<top level>' },                     
      site: { file: 'input.js', line: 25 },                       
      samples: 624,                                                 
      children: [                                                 
        {                                                         
          function: { file: 'input.js', line: 1, name: 'foo' },   
          site: { file: 'input.js', line: 7 },                     
          samples: 195,                                             
          selfCount: 195                                               
        }, {                                                       
          function: { file: 'input.js', line: 1, name: 'foo' },   
          site: { file: 'input.js', line: 11 },                   
          samples: 429,                                             
          selfCount: 429                                               
        }                                                         
      ]                                                           
    }, {                                                           
      function: { file: 'input.js', line: 1 },                     
      site: { file: 'input.js', line: 26 },                         
      children: [                                                 
        {                                                         
          function: { file: 'input.js', line: 18, name: 'bar' },   
          site: { file: 'input.js', line: 18 },                   
          data: { one: 1 }                                         
        }, {                                                       
          function: { file: 'input.js', line: 18, name: 'bar' },   
          site: { file: 'input.js', line: 19 },                   
          data: { two: 2, n: 200 }                                 
        }                                                          
      ]                                                           
    }                                                              
  ]                                                               
}                                                                  


With this structure, each "stack trace" has its own object which is persisted across invocations. Each object also has information about whatever children were invoked from it.
With this structure, each "stack trace" has its own object which is persisted across invocations. Each object also has information about whatever children were invoked from it.
Line 45: Line 114:
=== Profiled Statistics ===
=== Profiled Statistics ===


Some internal events are profiled when profiling is turned on, and they are kept track of in the following fields of the corresponding <tt>Profiler.Frame</tt> instance.
At the root level of the results is the following information:
 
<dl>
<dt>samples
<dd>The total number of samples that were taken while the profiler was running.
<dt>gcSamples
<dd>This is the total number of samples which were taken where GC activity was happening, but no other JS code was running.
<dt>micros
<dd>This is the number of microseconds for which the profiler was running. If the results were generated when the profiler was stopped, then this is the amount of time between the start/stop. If the profiler is still running, then this is the amount of time from the start of the profiler to when the results() method was called.
</dl>
 
Each child then has the following profile statistics:


<dl>
<dl>
<dt>runtime
<dt>function
<dd>This is an integer value of the amount of milliseconds that the corresponding stack trace was seen running for
<dd>This is the function in which the sample was taken. It contains information about the function's name/file/line definition
<dt>allocs
<dt>site
<dd>This is a two-element hash. The <tt>total</tt> key represents the total amount of allocations that occurred at this trace, and the <tt>amt</tt> key is the number of times that allocation was triggered at this location
<dd>This is the actual site of execution at which the sample was taken. For example if function a calls function b and a sample were then taken, the site of b would be the line at which the sample was taken inside b, and the site of a would be the line of the function call to b.
<dt>data
<dd>If the frame() method was invoked, then this represents the corresponding data which was attached to the frame information.
<dt>samples
<dd>This is an integer value of the number of ticks while this function's frame was on the stack. This is useful when counting total time spent in a function. It should be true that: <tt>samples = selfCount + children.sum('samples')</tt>
<dt>selfCount
<dd>This is an integer value like "samples," but instead only counts the time spent in the function itself. When a sample is taken and a function is currently running (it's the top of the stack), it's selfCount is increased.
</dl>
</dl>


Other statistics can be easily added from either JS or C++.
 
=== The return of <tt>.samples()</tt> ===
 
The samples() method of a Profiler returns a list of sample objects which describe a sample taken at a particular time. Each object has the following structure:
{                                                   
    micros: 100,                                     
    weight: 2,                                       
    stack: [                                         
        {                                           
            function: { line: 20, file: '...' },     
            site: { line: 30, file: '...' }         
        },                                           
        ...                                         
    ]                                               
}                                                   
 
Each sample's field are as follows:
<dl>
<dt>micros
<dd>This is the time at which the sample was taken (in microseconds).
<dt>weight
<dd>Due to the way sampling is currently implemented, time spent in native C++ functions prevent samples from being taken. For this reason, the time is attributed to the next sample. Hence this weight indicates how many samples were deferred to this stack trace.
<dt>stack
<dd>This will be a non-empty array with the stack trace at the time of the sample. The first function is the top of the stack and each subsequent function called the previous function. The 'function' field describes where the function was defined, and the 'site' field describes where the function is currently executing.
</dl>


== Use Cases ==
== Use Cases ==
Line 62: Line 172:
=== Test Cases ===
=== Test Cases ===


The test suite would initially create a <tt>Profiler</tt> object and then start/stop profiling the current page on each call to <tt>startProfiling</tt>/<tt>stopProfiling</tt> and the information returned from <tt>info</tt> would be what is displayed. Between each test, the <tt>clearInfo</tt> method would be used to prevent pollution between runs.
The test suite would initially create a <tt>Profiler</tt> object and then start/stop profiling the current page on each call to <tt>start</tt>/<tt>stop</tt> and the information returned from <tt>results</tt> would be what is displayed. Between each test, the <tt>reset</tt> method would be used to prevent pollution between runs.


=== Extension ===
=== Extension ===


Opened on a page and creates its own <tt>Profiler</tt> object. It then profiles the current page via <tt>startProfiling</tt> (probably a button to be hit). Some time later <tt>info</tt> is used to get information about the run of profiling (again probably a button being hit) and then all of the information is sorted through and displayed in some fancy fashion.
Opened on a page and creates its own <tt>Profiler</tt> object. It then profiles the current page via <tt>start</tt> (probably a button to be hit). Some time later <tt>results</tt> is used to get information about the run of profiling (again probably a button being hit) and then all of the information is sorted through and displayed in some fancy fashion.


The page being profiled is unaware that it's being profiled, and there's nothing that it needs to do to help it along.
The page being profiled is unaware that it's being profiled, and there's nothing that it needs to do to help it along.
Line 119: Line 229:
* Biased, operational callbacks are only invoked at particular points in the code, so true line-by-line sampling is impossible. It is possible with signal-based sampling, but that has a large number of other issues with it.
* Biased, operational callbacks are only invoked at particular points in the code, so true line-by-line sampling is impossible. It is possible with signal-based sampling, but that has a large number of other issues with it.
* Might still require some wonky code maybe? Not quite sure about this...
* Might still require some wonky code maybe? Not quite sure about this...
==== Pseudocode ====
def Profiler.startProfiling(object)             
  compartment = object.root.compartment         
  compartment.setOperationCallback(sample, FREQ)
  compartment.root_node = {}                   
                                                 
def Profiler.isProfiling(object) ...           
                                                 
def Profiler.stopProfling(object)               
  compartment = object.root.compartment         
  compartment.removeOperationCallback(sample)   
                                                 
def Profiler.frame(object)                     
  compartment = object.root.compartment         
  node = compartment.root_node                 
  for (frame in compartment.js_stack)           
    if (node[frame] == NULL)                   
      node[frame] = new node(parent=node)       
    node = node[frame.script]                   
  return node                                   
                                                 
def Profiler.info(object)                       
  return object.root.compartment.root_node     
                                                 
def Profiler.clearInfo(object)                 
  object.root.compartment.root_node.clear()     
                                                 
def Profiler.sample():                         
  compartment = this.upvalues.compartment       
  node = compartment.root_node                 
  for (frame in compartment.js_stack)           
    node2 = node[frame.str]                     
    if (node == NULL)                           
      node2 = new node(parent=node)             
      node[frame.str] = node2                   
    node = node2                               
    node.ticks++                               
    if (frame == compartment.js_stack.top)     
      node.self_ticks++                         


=== Choice ===
=== Choice ===
Jimb
Confirmed users
497

edits

Retrieved from "https://wiki.mozilla.org/Special:MobileDiff/439216...472070"