nashorn/docs/DEVELOPER_README
changeset 16147 e63b63819133
child 16152 ea430b83d74d
equal deleted inserted replaced
16146:7b62478ee76c 16147:e63b63819133
       
     1 This document describes system properties that are used for internal
       
     2 debugging and instrumentation purposes, along with the system loggers,
       
     3 which are used for the same thing.
       
     4 
       
     5 This document is intended as a developer resource, and it is not
       
     6 needed as Nashorn documentation for normal usage. Flags and system
       
     7 properties described herein are subject to change without notice.
       
     8 
       
     9 =====================================
       
    10 1. System properties used internally
       
    11 =====================================
       
    12 
       
    13 This documentation of the system property flags assume that the
       
    14 default value of the flag is false, unless otherwise specified.
       
    15 
       
    16 
       
    17 SYSTEM PROPERTY: -Dnashorn.callsiteaccess.debug
       
    18 
       
    19 See the description of the access logger below. This flag is
       
    20 equivalent to enabling the access logger with "info" level.
       
    21 
       
    22 
       
    23 SYSTEM PROPERTY: -Dnashorn.compiler.ints.disable
       
    24 
       
    25 This flag prevents ints and longs (non double values) from being used
       
    26 for any primitive representation in the lowered IR. This is default
       
    27 false, i.e Lower will attempt to use integer variables as long as it
       
    28 can. For example, var x = 17 would try to use x as an integer, unless
       
    29 other operations occur later that require coercion to wider type, for
       
    30 example x *= 17.1;
       
    31 
       
    32 
       
    33 SYSTEM PROPERTY: -Dnashorn.compiler.intarithmetic 
       
    34 
       
    35 Arithmetic operations in Nashorn (except bitwise ones) typically
       
    36 coerce the operands to doubles (as per the JavaScript spec). To switch
       
    37 this off and remain in integer mode, for example for "var x = a&b; var
       
    38 y = c&d; var z = x*y;", use this flag. This will force the
       
    39 multiplication of variables that are ints to be done with the IMUL
       
    40 bytecode and the result "z" to become an int.
       
    41 
       
    42 WARNING: Note that is is experimental only to ensure that type support
       
    43 exists for all primitive types. The generated code is unsound. This
       
    44 will be the case until we do optimizations based on it. There is a CR
       
    45 in Nashorn to do better range analysis, and ensure that this is only
       
    46 done where the operation can't overflow into a wider type. Currently
       
    47 no overflow checking is done, so at the moment, until range analysis
       
    48 has been completed, this option is turned off.
       
    49 
       
    50 We've experimented by using int arithmetic for everything and putting
       
    51 overflow checks afterwards, which would recompute the operation with
       
    52 the correct precision, but have yet to find a configuration where this
       
    53 is faster than just using doubles directly, even if the int operation
       
    54 does not overflow. Getting access to a JVM intrinsic that does branch
       
    55 on overflow would probably alleviate this.
       
    56 
       
    57 There is also a problem with this optimistic approach if the symbol
       
    58 happens to reside in a local variable slot in the bytecode, as those
       
    59 are strongly typed. Then we would need to split large sections of
       
    60 control flow, so this is probably not the right way to go, while range
       
    61 analysis is. There is a large difference between integer bytecode
       
    62 without overflow checks and double bytecode. The former is
       
    63 significantly faster.
       
    64 
       
    65 
       
    66 SYSTEM PROPERTY: -Dnashorn.codegen.debug, -Dnashorn.codegen.debug.trace=<x>
       
    67 
       
    68 See the description of the codegen logger below.
       
    69 
       
    70 
       
    71 SYSTEM_PROPERTY: -Dnashorn.fields.debug
       
    72 
       
    73 See the description on the fields logger below.
       
    74 
       
    75 
       
    76 SYSTEM PROPERTY: -Dnashorn.fields.dual
       
    77 
       
    78 When this property is true, Nashorn will attempt to use primitive
       
    79 fields for AccessorProperties (currently just AccessorProperties, not
       
    80 spill properties). Memory footprint for script objects will increase,
       
    81 as we need to maintain both a primitive field (a long) as well as an
       
    82 Object field for the property value. Ints are represented as the 32
       
    83 low bits of the long fields. Doubles are represented as the
       
    84 doubleToLongBits of their value. This way a single field can be used
       
    85 for all primitive types. Packing and unpacking doubles to their bit
       
    86 representation is intrinsified by the JVM and extremely fast.
       
    87 
       
    88 While dual fields in theory runs significantly faster than Object
       
    89 fields due to reduction of boxing and memory allocation overhead,
       
    90 there is still work to be done to make this a general purpose
       
    91 solution. Research is ongoing.
       
    92 
       
    93 In the future, this might complement or be replaced by experimental
       
    94 feature sun.misc.TaggedArray, which has been discussed on the mlvm
       
    95 mailing list. TaggedArrays are basically a way to share data space
       
    96 between primitives and references, and have the GC understand this.
       
    97 
       
    98 As long as only primitive values are written to the fields and enough
       
    99 type information exists to make sure that any reads don't have to be
       
   100 uselessly boxed and unboxed, this is significantly faster than the
       
   101 standard "Objects only" approach that currently is the default. See
       
   102 test/examples/dual-fields-micro.js for an example that runs twice as
       
   103 fast with dual fields as without them. Here, the compiler, can
       
   104 determine that we are dealing with numbers only throughout the entire
       
   105 property life span of the properties involved.
       
   106 
       
   107 If a "real" object (not a boxed primitive) is written to a field that
       
   108 has a primitive representation, its callsite is relinked and an Object
       
   109 field is used forevermore for that particular field in that
       
   110 PropertyMap and its children, even if primitives are later assigned to
       
   111 it.
       
   112 
       
   113 As the amount of compile time type information is very small in a
       
   114 dynamic language like JavaScript, it is frequently the case that
       
   115 something has to be treated as an object, because we don't know any
       
   116 better. In reality though, it is often a boxed primitive is stored to
       
   117 an AccessorProperty. The fastest way to handle this soundly is to use
       
   118 a callsite typecheck and avoid blowing the field up to an Object. We
       
   119 never revert object fields to primitives. Ping-pong:ing back and forth
       
   120 between primitive representation and Object representation would cause
       
   121 fatal performance overhead, so this is not an option.
       
   122 
       
   123 For a general application the dual fields approach is still slower
       
   124 than objects only fields in some places, about the same in most cases,
       
   125 and significantly faster in very few. This is due the program using
       
   126 primitives, but we still can't prove it. For example "local_var a =
       
   127 call(); field = a;" may very well write a double to the field, but the
       
   128 compiler dare not guess a double type if field is a local variable,
       
   129 due to bytecode variables being strongly typed and later non
       
   130 interchangeable. To get around this, the entire method would have to
       
   131 be replaced and a continuation retained to restart from. We believe
       
   132 that the next steps we should go through are instead:
       
   133 
       
   134 1) Implement method specialization based on callsite, as it's quite
       
   135 frequently the case that numbers are passed around, but currently our
       
   136 function nodes just have object types visible to the compiler. For
       
   137 example "var b = 17; func(a,b,17)" is an example where two parameters
       
   138 can be specialized, but the main version of func might also be called
       
   139 from another callsite with func(x,y,"string").
       
   140 
       
   141 2) This requires lazy jitting as the functions have to be specialized
       
   142 per callsite.
       
   143 
       
   144 Even though "function square(x) { return x*x }" might look like a
       
   145 trivial function that can always only take doubles, this is not
       
   146 true. Someone might have overridden the valueOf for x so that the
       
   147 toNumber coercion has side effects. To fulfil JavaScript semantics,
       
   148 the coercion has to run twice for both terms of the multiplication
       
   149 even if they are the same object. This means that call site
       
   150 specialization is necessary, not parameter specialization on the form
       
   151 "function square(x) { var xd = (double)x; return xd*xd; }", as one
       
   152 might first think.
       
   153 
       
   154 Generating a method specialization for any variant of a function that
       
   155 we can determine by types at compile time is a combinatorial explosion
       
   156 of byte code (try it e.g. on all the variants of am3 in the Octane
       
   157 benchmark crypto.js). Thus, this needs to be lazy
       
   158 
       
   159 3) Possibly optimistic callsite writes, something on the form
       
   160 
       
   161 x = y; //x is a field known to be a primitive. y is only an object as
       
   162 far as we can tell
       
   163 
       
   164 turns into
       
   165 
       
   166 try {
       
   167   x = (int)y;
       
   168 } catch (X is not an integer field right now | ClassCastException e) {
       
   169   x = y;
       
   170 }
       
   171 
       
   172 Mini POC shows that this is the key to a lot of dual field performance
       
   173 in seemingly trivial micros where one unknown object, in reality
       
   174 actually a primitive, foils it for us. Very common pattern. Once we
       
   175 are "all primitives", dual fields runs a lot faster than Object fields
       
   176 only.
       
   177 
       
   178 We still have to deal with objects vs primitives for local bytecode
       
   179 slots, possibly through code copying and versioning.
       
   180 
       
   181 
       
   182 SYSTEM PROPERTY: -Dnashorn.compiler.symbol.trace=<x>
       
   183 
       
   184 When this property is set, creation and manipulation of any symbol
       
   185 named "x" will show information about when the compiler changes its
       
   186 type assumption, bytecode local variable slot assignment and other
       
   187 data. This is useful if, for example, a symbol shows up as an Object,
       
   188 when you believe it should be a primitive. Usually there is an
       
   189 explanation for this, for example that it exists in the global scope
       
   190 and type analysis has to be more conservative. In that case, the stack
       
   191 trace upon type change to object will usually tell us why.
       
   192 
       
   193 
       
   194 SYSTEM PROPERTY: nashorn.lexer.xmlliterals
       
   195 
       
   196 If this property it set, it means that the Lexer should attempt to
       
   197 parse XML literals, which would otherwise generate syntax
       
   198 errors. Warning: there are currently no unit tests for this
       
   199 functionality.
       
   200 
       
   201 XML literals, when this is enabled, end up as standard LiteralNodes in
       
   202 the IR.
       
   203 
       
   204 
       
   205 SYSTEM_PROPERTY: nashorn.debug
       
   206 
       
   207 If this property is set to true, Nashorn runs in Debug mode. Debug
       
   208 mode is slightly slower, as for example statistics counters are enabled
       
   209 during the run. Debug mode makes available a NativeDebug instance
       
   210 called "Debug" in the global space that can be used to print property
       
   211 maps and layout for script objects, as well as a "dumpCounters" method
       
   212 that will print the current values of the previously mentioned stats
       
   213 counters.
       
   214 
       
   215 These functions currently exists for Debug:
       
   216 
       
   217 "map" - print(Debug.map(x)) will dump the PropertyMap for object x to
       
   218 stdout (currently there also exist functions called "embedX", where X
       
   219 is a value from 0 to 3, that will dump the contents of the embed pool
       
   220 for the first spill properties in any script object and "spill", that
       
   221 will dump the contents of the growing spill pool of spill properties
       
   222 in any script object. This is of course subject to change without
       
   223 notice, should we change the script object layout.
       
   224 
       
   225 "methodHandle" - this method returns the method handle that is used
       
   226 for invoking a particular script function.
       
   227 
       
   228 "identical" - this method compares two script objects for reference
       
   229 equality. It is a == Java comparison
       
   230 
       
   231 "dumpCounters" - will dump the debug counters' current values to
       
   232 stdout.
       
   233 
       
   234 Currently we count number of ScriptObjects in the system, number of
       
   235 Scope objects in the system, number of ScriptObject listeners added,
       
   236 removed and dead (without references).
       
   237 
       
   238 We also count number of ScriptFunctions, ScriptFunction invocations
       
   239 and ScriptFunction allocations.
       
   240 
       
   241 Furthermore we count PropertyMap statistics: how many property maps
       
   242 exist, how many times were property maps cloned, how many times did
       
   243 the property map history cache hit, prevent new allocations, how many
       
   244 prototype invalidations were done, how many time the property map
       
   245 proto cache hit.
       
   246 
       
   247 Finally we count callsite misses on a per callsite bases, which occur
       
   248 when a callsite has to be relinked, due to a previous assumption of
       
   249 object layout being invalidated.
       
   250 
       
   251 
       
   252 SYSTEM PROPERTY: nashorn.methodhandles.debug,
       
   253 nashorn.methodhandles.debug=create
       
   254 
       
   255 If this property is enabled, each MethodHandle related call that uses
       
   256 the java.lang.invoke package gets its MethodHandle intercepted and an
       
   257 instrumentation printout of arguments and return value appended to
       
   258 it. This shows exactly which method handles are executed and from
       
   259 where. (Also MethodTypes and SwitchPoints). This can be augmented with
       
   260 more information, for example, instance count, by subclassing or
       
   261 further extending the TraceMethodHandleFactory implementation in
       
   262 MethodHandleFactory.java.
       
   263 
       
   264 If the property is specialized with "=create" as its option,
       
   265 instrumentation will be shown for method handles upon creation time
       
   266 rather than at runtime usage.
       
   267 
       
   268 
       
   269 SYSTEM PROPERTY: nashorn.methodhandles.debug.stacktrace
       
   270 
       
   271 This does the same as nashorn.methodhandles.debug, but when enabled
       
   272 also dumps the stack trace for every instrumented method handle
       
   273 operation. Warning: This is enormously verbose, but provides a pretty
       
   274 decent "grep:able" picture of where the calls are coming from.
       
   275 
       
   276 See the description of the codegen logger below for a more verbose
       
   277 description of this option
       
   278 
       
   279 
       
   280 SYSTEM PROPERTY: nashorn.scriptfunction.specialization.disable
       
   281 
       
   282 There are several "fast path" implementations of constructors and
       
   283 functions in the NativeObject classes that, in their original form,
       
   284 take a variable amount of arguments. Said functions are also declared
       
   285 to take Object parameters in their original form, as this is what the
       
   286 JavaScript specification mandates.
       
   287 
       
   288 However, we often know quite a lot more at a callsite of one of these
       
   289 functions. For example, Math.min is called with a fixed number (2) of
       
   290 integer arguments. The overhead of boxing these ints to Objects and
       
   291 folding them into an Object array for the generic varargs Math.min
       
   292 function is an order of magnitude slower than calling a specialized
       
   293 implementation of Math.min that takes two integers. Specialized
       
   294 functions and constructors are identified by the tag
       
   295 @SpecializedFunction and @SpecializedConstructor in the Nashorn
       
   296 code. The linker will link in the most appropriate (narrowest types,
       
   297 right number of types and least number of arguments) specialization if
       
   298 specializations are available.
       
   299 
       
   300 Every ScriptFunction may carry specializations that the linker can
       
   301 choose from. This framework will likely be extended for user defined
       
   302 functions. The compiler can often infer enough parameter type info
       
   303 from callsites for in order to generate simpler versions with less
       
   304 generic Object types. This feature depends on future lazy jitting, as
       
   305 there tend to be many calls to user defined functions, some where the
       
   306 callsite can be specialized, some where we mostly see object
       
   307 parameters even at the callsite.
       
   308 
       
   309 If this system property is set to true, the linker will not attempt to
       
   310 use any specialized function or constructor for native objects, but
       
   311 just call the generic one.
       
   312 
       
   313 
       
   314 SYSTEM PROPERTY: nashorn.tcs.miss.samplePercent=<x>
       
   315 
       
   316 When running with the trace callsite option (-tcs), Nashorn will count
       
   317 and instrument any callsite misses that require relinking. As the
       
   318 number of relinks is large and usually produces a lot of output, this
       
   319 system property can be used to constrain the percentage of misses that
       
   320 should be logged. Typically this is set to 1 or 5 (percent). 1% is the
       
   321 default value.
       
   322 
       
   323 
       
   324 SYSTEM_PROPERTY: nashorn.profilefile=<filename>
       
   325 
       
   326 When running with the profile callsite options (-pcs), Nashorn will
       
   327 dump profiling data for all callsites to stderr as a shutdown hook. To
       
   328 instead redirect this to a file, specify the path to the file using
       
   329 this system property.
       
   330 
       
   331 
       
   332 ===============
       
   333 2. The loggers.
       
   334 ===============
       
   335 
       
   336 The Nashorn loggers can be used to print per-module or per-subsystem
       
   337 debug information with different levels of verbosity. The loggers for
       
   338 a given subsystem are available are enabled by using
       
   339 
       
   340 --log=<systemname>[:<level>]
       
   341 
       
   342 on the command line.
       
   343 
       
   344 Here <systemname> identifies the name of the subsystem to be logged
       
   345 and the optional colon and level argument is a standard
       
   346 java.util.logging.Level name (severe, warning, info, config, fine,
       
   347 finer, finest). If the level is left out for a particular subsystem,
       
   348 it defaults to "info". Any log message logged as the level or a level
       
   349 that is more important will be output to stderr by the logger.
       
   350 
       
   351 Several loggers can be enabled by a single command line option, by
       
   352 putting a comma after each subsystem/level tuple (or each subsystem if
       
   353 level is unspecified). The --log option can also be given multiple
       
   354 times on the same command line, with the same effect.
       
   355 
       
   356 For example: --log=codegen,fields:finest is equivalent to
       
   357 --log=codegen:info --log=fields:finest
       
   358 
       
   359 The subsystems that currently support logging are:
       
   360 
       
   361 
       
   362 * compiler
       
   363 
       
   364 The compiler is in charge of turning source code and function nodes
       
   365 into byte code, and installs the classes into a class loader
       
   366 controlled from the Context. Log messages are, for example, about
       
   367 things like new compile units being allocated. The compiler has global
       
   368 settings that all the tiers of codegen (e.g. Lower and CodeGenerator)
       
   369 use.
       
   370 
       
   371 
       
   372 * codegen
       
   373 
       
   374 The code generator is the emitter stage of the code pipeline, and
       
   375 turns the lowest tier of a FunctionNode into bytecode. Codegen logging
       
   376 shows byte codes as they are being emitted, line number information
       
   377 and jumps. It also shows the contents of the bytecode stack prior to
       
   378 each instruction being emitted. This is a good debugging aid. For
       
   379 example:
       
   380 
       
   381 [codegen] #41                       line:2 (f)_afc824e 
       
   382 [codegen] #42                           load symbol x slot=2 
       
   383 [codegen] #43  {1:O}                    load int 0 
       
   384 [codegen] #44  {2:I O}                  dynamic_runtime_call GT:ZOI_I args=2 returnType=boolean 
       
   385 [codegen] #45                              signature (Ljava/lang/Object;I)Z 
       
   386 [codegen] #46  {1:Z}                    ifeq  ternary_false_5402fe28 
       
   387 [codegen] #47                           load symbol x slot=2 
       
   388 [codegen] #48  {1:O}                    goto ternary_exit_107c1f2f 
       
   389 [codegen] #49                       ternary_false_5402fe28 
       
   390 [codegen] #50                           load symbol x slot=2 
       
   391 [codegen] #51  {1:O}                    convert object -> double 
       
   392 [codegen] #52  {1:D}                    neg 
       
   393 [codegen] #53  {1:D}                    convert double -> object 
       
   394 [codegen] #54  {1:O}                ternary_exit_107c1f2f 
       
   395 [codegen] #55  {1:O}                    return object 
       
   396 
       
   397 shows a ternary node being generated for the sequence "return x > 0 ?
       
   398 x : -x"
       
   399 
       
   400 The first number on the log line is a unique monotonically increasing
       
   401 emission id per bytecode. There is no guarantee this is the same id
       
   402 between runs.  depending on non deterministic code
       
   403 execution/compilation, but for small applications it usually is. If
       
   404 the system variable -Dnashorn.codegen.debug.trace=<x> is set, where x
       
   405 is a bytecode emission id, a stack trace will be shown as the
       
   406 particular bytecode is about to be emitted. This can be a quick way to
       
   407 determine where it comes from without attaching the debugger. "Who
       
   408 generated that neg?"
       
   409 
       
   410 The --log=codegen option is equivalent to setting the system variable
       
   411 "nashorn.codegen.debug" to true.
       
   412 
       
   413 
       
   414 * lower
       
   415 
       
   416 The lowering annotates a FunctionNode with symbols for each identifier
       
   417 and transforms high level constructs into lower level ones, that the
       
   418 CodeGenerator consumes.
       
   419 
       
   420 Lower logging typically outputs things like post pass actions,
       
   421 insertions of casts because symbol types have been changed and type
       
   422 specialization information. Currently very little info is generated by
       
   423 this logger. This will probably change.
       
   424 
       
   425 
       
   426 * access
       
   427 
       
   428 The --log=access option is equivalent to setting the system variable
       
   429 "nashorn.callsiteaccess.debug" to true. There are several levels of
       
   430 the access logger, usually the default level "info" is enough
       
   431 
       
   432 It is very simple to create your own logger. Use the DebugLogger class
       
   433 and give the subsystem name as a constructor argument.
       
   434 
       
   435 
       
   436 * fields
       
   437 
       
   438 The --log=fields option (at info level) is equivalent to setting the
       
   439 system variable "nashorn.fields.debug" to true. At the info level it
       
   440 will only show info about type assumptions that were invalidated. If
       
   441 the level is set to finest, it will also trace every AccessorProperty
       
   442 getter and setter in the program, show arguments, return values
       
   443 etc. It will also show the internal representation of respective field
       
   444 (Object in the normal case, unless running with the dual field
       
   445 representation)