Tracing optimization and deoptimization events

We can tap into the V8 decision process regarding when to optimize a function using the --trace-opt and trace-deopt flags.

Imagine we had an application with an entry point of app.js, we could watch optimization events with the following:

$ node --trace-opt --trace-deopt app.js

This would yield output resembling the following:

[marking 0x21e29c142521 <JS Function varOf (SharedFunctionInfo 0x1031e5bfa4b9)> for recompilation, reason: hot and stable, ICs with typeinfo: 3/3 (100%), generic ICs: 0/3 (0%)]
 [compiling method 0x21e29c142521 <JS Function varOf (SharedFunctionInfo 0x1031e5bfa4b9)> using Crankshaft]
 [optimizing 0x21e29c142521 <JS Function varOf (SharedFunctionInfo 0x1031e5bfa4b9)> - took 0.019, 0.106, 0.033 ms]
 [completed optimizing 0x21e29c142521 <JS Function varOf (SharedFunctionInfo 0x1031e5bfa4b9)>]

Here we see that a function named varOf is marked for optimization and then optimized shortly after.

We may also observe the following output:

[marking 0x21e29d33b401 <JS Function (SharedFunctionInfo 0x363485de4f69)> for recompilation, reason: small function, ICs with typeinfo: 1/1 (100%), generic ICs: 0/1 (0%)]
 [compiling method 0x21e29d33b401 <JS Function (SharedFunctionInfo 0x363485de4f69)> using Crankshaft]
 [optimizing 0x21e29d33b401 <JS Function (SharedFunctionInfo 0x363485de4f69)> - took 0.012, 0.072, 0.021 ms]

In this case, an anonymous function is being marked for recompilation. It can be very difficult to know where this function is defined. Naming functions is highly important in profiling situations.

From time to time, we can also see a de-optimization happening:

[deoptimizing (DEOPT eager): begin 0x1f5a5b1fd601 <JS Function forOwn (SharedFunctionInfo 0x1f5a5b161259)> (opt #125) @55, FP to SP delta:
 376]
             ;;; deoptimize at 109463: not a Smi
   reading input frame forOwn => node=3, args=13, height=2; inputs:
       0: 0x1f5a5b1fd601 ; (frame function) 0x1f5a5b1fd601 <JS Function
 forOwn (SharedFunctionInfo 0x1f5a5b161259)>
       1: 0x1f5a5b1fa7d9 ; [fp + 32] 0x1f5a5b1fa7d9 <JS Function lodash
 (SharedFunctionInfo 0x1f5a5b153b19)>
       2: 0x2e17991e6409 ; [fp + 24] 0x2e17991e6409 <an Object with map
 0x366bf3f38b89>
       3: 0x2e17991ebb41 ; [fp + 16] 0x2e17991ebb41 <JS Function
 (SharedFunctionInfo 0x1f5a5b1ca9e1)>
       4: 0x1f5a5b1eaed1 ; [fp - 24] 0x1f5a5b1eaed1 <FixedArray[272]>
       5: 0x1f5a5b1ee239 ; [fp - 32] 0x1f5a5b1ee239 <JS Function
 baseForOwn (SharedFunctionInfo 0x1f5a5b155d39)>
 ...

The reason for the deoptimization is "not a SMI", which means that the function was expecting a 32-bit fixed integer and it got something else instead.