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