DEVELOPER_README revision 2:da1e581c933b
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 16 17SYSTEM PROPERTY: -Dnashorn.callsiteaccess.debug 18 19See the description of the access logger below. This flag is 20equivalent to enabling the access logger with "info" level. 21 22 23SYSTEM PROPERTY: -Dnashorn.compiler.ints.disable 24 25This flag prevents ints and longs (non double values) from being used 26for any primitive representation in the lowered IR. This is default 27false, i.e Lower will attempt to use integer variables as long as it 28can. For example, var x = 17 would try to use x as an integer, unless 29other operations occur later that require coercion to wider type, for 30example x *= 17.1; 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 184When this property is set, creation and manipulation of any symbol 185named "x" will show information about when the compiler changes its 186type assumption, bytecode local variable slot assignment and other 187data. This is useful if, for example, a symbol shows up as an Object, 188when you believe it should be a primitive. Usually there is an 189explanation for this, for example that it exists in the global scope 190and type analysis has to be more conservative. In that case, the stack 191trace upon type change to object will usually tell us why. 192 193 194SYSTEM PROPERTY: nashorn.lexer.xmlliterals 195 196If this property it set, it means that the Lexer should attempt to 197parse XML literals, which would otherwise generate syntax 198errors. Warning: there are currently no unit tests for this 199functionality. 200 201XML literals, when this is enabled, end up as standard LiteralNodes in 202the IR. 203 204 205SYSTEM_PROPERTY: nashorn.debug 206 207If this property is set to true, Nashorn runs in Debug mode. Debug 208mode is slightly slower, as for example statistics counters are enabled 209during the run. Debug mode makes available a NativeDebug instance 210called "Debug" in the global space that can be used to print property 211maps and layout for script objects, as well as a "dumpCounters" method 212that will print the current values of the previously mentioned stats 213counters. 214 215These functions currently exists for Debug: 216 217"map" - print(Debug.map(x)) will dump the PropertyMap for object x to 218stdout (currently there also exist functions called "embedX", where X 219is a value from 0 to 3, that will dump the contents of the embed pool 220for the first spill properties in any script object and "spill", that 221will dump the contents of the growing spill pool of spill properties 222in any script object. This is of course subject to change without 223notice, should we change the script object layout. 224 225"methodHandle" - this method returns the method handle that is used 226for invoking a particular script function. 227 228"identical" - this method compares two script objects for reference 229equality. It is a == Java comparison 230 231"dumpCounters" - will dump the debug counters' current values to 232stdout. 233 234Currently we count number of ScriptObjects in the system, number of 235Scope objects in the system, number of ScriptObject listeners added, 236removed and dead (without references). 237 238We also count number of ScriptFunctions, ScriptFunction invocations 239and ScriptFunction allocations. 240 241Furthermore we count PropertyMap statistics: how many property maps 242exist, how many times were property maps cloned, how many times did 243the property map history cache hit, prevent new allocations, how many 244prototype invalidations were done, how many time the property map 245proto cache hit. 246 247Finally we count callsite misses on a per callsite bases, which occur 248when a callsite has to be relinked, due to a previous assumption of 249object layout being invalidated. 250 251 252SYSTEM PROPERTY: nashorn.methodhandles.debug, 253nashorn.methodhandles.debug=create 254 255If this property is enabled, each MethodHandle related call that uses 256the java.lang.invoke package gets its MethodHandle intercepted and an 257instrumentation printout of arguments and return value appended to 258it. This shows exactly which method handles are executed and from 259where. (Also MethodTypes and SwitchPoints). This can be augmented with 260more information, for example, instance count, by subclassing or 261further extending the TraceMethodHandleFactory implementation in 262MethodHandleFactory.java. 263 264If the property is specialized with "=create" as its option, 265instrumentation will be shown for method handles upon creation time 266rather than at runtime usage. 267 268 269SYSTEM PROPERTY: nashorn.methodhandles.debug.stacktrace 270 271This does the same as nashorn.methodhandles.debug, but when enabled 272also dumps the stack trace for every instrumented method handle 273operation. Warning: This is enormously verbose, but provides a pretty 274decent "grep:able" picture of where the calls are coming from. 275 276See the description of the codegen logger below for a more verbose 277description of this option 278 279 280SYSTEM PROPERTY: nashorn.scriptfunction.specialization.disable 281 282There are several "fast path" implementations of constructors and 283functions in the NativeObject classes that, in their original form, 284take a variable amount of arguments. Said functions are also declared 285to take Object parameters in their original form, as this is what the 286JavaScript specification mandates. 287 288However, we often know quite a lot more at a callsite of one of these 289functions. For example, Math.min is called with a fixed number (2) of 290integer arguments. The overhead of boxing these ints to Objects and 291folding them into an Object array for the generic varargs Math.min 292function is an order of magnitude slower than calling a specialized 293implementation of Math.min that takes two integers. Specialized 294functions and constructors are identified by the tag 295@SpecializedFunction and @SpecializedConstructor in the Nashorn 296code. The linker will link in the most appropriate (narrowest types, 297right number of types and least number of arguments) specialization if 298specializations are available. 299 300Every ScriptFunction may carry specializations that the linker can 301choose from. This framework will likely be extended for user defined 302functions. The compiler can often infer enough parameter type info 303from callsites for in order to generate simpler versions with less 304generic Object types. This feature depends on future lazy jitting, as 305there tend to be many calls to user defined functions, some where the 306callsite can be specialized, some where we mostly see object 307parameters even at the callsite. 308 309If this system property is set to true, the linker will not attempt to 310use any specialized function or constructor for native objects, but 311just call the generic one. 312 313 314SYSTEM PROPERTY: nashorn.tcs.miss.samplePercent=<x> 315 316When running with the trace callsite option (-tcs), Nashorn will count 317and instrument any callsite misses that require relinking. As the 318number of relinks is large and usually produces a lot of output, this 319system property can be used to constrain the percentage of misses that 320should be logged. Typically this is set to 1 or 5 (percent). 1% is the 321default value. 322 323 324SYSTEM_PROPERTY: nashorn.profilefile=<filename> 325 326When running with the profile callsite options (-pcs), Nashorn will 327dump profiling data for all callsites to stderr as a shutdown hook. To 328instead redirect this to a file, specify the path to the file using 329this system property. 330 331 332=============== 3332. The loggers. 334=============== 335 336The Nashorn loggers can be used to print per-module or per-subsystem 337debug information with different levels of verbosity. The loggers for 338a given subsystem are available are enabled by using 339 340--log=<systemname>[:<level>] 341 342on the command line. 343 344Here <systemname> identifies the name of the subsystem to be logged 345and the optional colon and level argument is a standard 346java.util.logging.Level name (severe, warning, info, config, fine, 347finer, finest). If the level is left out for a particular subsystem, 348it defaults to "info". Any log message logged as the level or a level 349that is more important will be output to stderr by the logger. 350 351Several loggers can be enabled by a single command line option, by 352putting a comma after each subsystem/level tuple (or each subsystem if 353level is unspecified). The --log option can also be given multiple 354times on the same command line, with the same effect. 355 356For example: --log=codegen,fields:finest is equivalent to 357--log=codegen:info --log=fields:finest 358 359The subsystems that currently support logging are: 360 361 362* compiler 363 364The compiler is in charge of turning source code and function nodes 365into byte code, and installs the classes into a class loader 366controlled from the Context. Log messages are, for example, about 367things like new compile units being allocated. The compiler has global 368settings that all the tiers of codegen (e.g. Lower and CodeGenerator) 369use. 370 371 372* codegen 373 374The code generator is the emitter stage of the code pipeline, and 375turns the lowest tier of a FunctionNode into bytecode. Codegen logging 376shows byte codes as they are being emitted, line number information 377and jumps. It also shows the contents of the bytecode stack prior to 378each instruction being emitted. This is a good debugging aid. For 379example: 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 397shows a ternary node being generated for the sequence "return x > 0 ? 398x : -x" 399 400The first number on the log line is a unique monotonically increasing 401emission id per bytecode. There is no guarantee this is the same id 402between runs. depending on non deterministic code 403execution/compilation, but for small applications it usually is. If 404the system variable -Dnashorn.codegen.debug.trace=<x> is set, where x 405is a bytecode emission id, a stack trace will be shown as the 406particular bytecode is about to be emitted. This can be a quick way to 407determine where it comes from without attaching the debugger. "Who 408generated that neg?" 409 410The --log=codegen option is equivalent to setting the system variable 411"nashorn.codegen.debug" to true. 412 413 414* lower 415 416The lowering annotates a FunctionNode with symbols for each identifier 417and transforms high level constructs into lower level ones, that the 418CodeGenerator consumes. 419 420Lower logging typically outputs things like post pass actions, 421insertions of casts because symbol types have been changed and type 422specialization information. Currently very little info is generated by 423this logger. This will probably change. 424 425 426* access 427 428The --log=access option is equivalent to setting the system variable 429"nashorn.callsiteaccess.debug" to true. There are several levels of 430the access logger, usually the default level "info" is enough 431 432It is very simple to create your own logger. Use the DebugLogger class 433and give the subsystem name as a constructor argument. 434 435 436* fields 437 438The --log=fields option (at info level) is equivalent to setting the 439system variable "nashorn.fields.debug" to true. At the info level it 440will only show info about type assumptions that were invalidated. If 441the level is set to finest, it will also trace every AccessorProperty 442getter and setter in the program, show arguments, return values 443etc. It will also show the internal representation of respective field 444(Object in the normal case, unless running with the dual field 445representation)