jlaskey@3: This document describes system properties that are used for internal jlaskey@3: debugging and instrumentation purposes, along with the system loggers, jlaskey@3: which are used for the same thing. jlaskey@3: jlaskey@3: This document is intended as a developer resource, and it is not jlaskey@3: needed as Nashorn documentation for normal usage. Flags and system jlaskey@3: properties described herein are subject to change without notice. jlaskey@3: jlaskey@3: ===================================== jlaskey@3: 1. System properties used internally jlaskey@3: ===================================== jlaskey@3: jlaskey@3: This documentation of the system property flags assume that the jlaskey@3: default value of the flag is false, unless otherwise specified. jlaskey@3: lagergren@8: SYSTEM PROPERTY: -Dnashorn.unstable.relink.threshold=x lagergren@8: lagergren@8: This property controls how many call site misses are allowed before a lagergren@8: callsite is relinked with "apply" semantics to never change again. lagergren@8: In the case of megamorphic callsites, this is necessary, or the lagergren@8: program would spend all its time swapping out callsite targets. Dynalink lagergren@8: has a default value (currently 8 relinks) for this property if it lagergren@8: is not explicitly set. lagergren@8: jlaskey@3: jlaskey@3: SYSTEM PROPERTY: -Dnashorn.callsiteaccess.debug jlaskey@3: jlaskey@3: See the description of the access logger below. This flag is jlaskey@3: equivalent to enabling the access logger with "info" level. jlaskey@3: jlaskey@3: jlaskey@3: SYSTEM PROPERTY: -Dnashorn.compiler.ints.disable jlaskey@3: jlaskey@3: This flag prevents ints and longs (non double values) from being used jlaskey@3: for any primitive representation in the lowered IR. This is default jlaskey@3: false, i.e Lower will attempt to use integer variables as long as it jlaskey@3: can. For example, var x = 17 would try to use x as an integer, unless jlaskey@3: other operations occur later that require coercion to wider type, for jlaskey@3: example x *= 17.1; jlaskey@3: jlaskey@3: jlaskey@3: SYSTEM PROPERTY: -Dnashorn.compiler.intarithmetic jlaskey@3: jlaskey@3: Arithmetic operations in Nashorn (except bitwise ones) typically jlaskey@3: coerce the operands to doubles (as per the JavaScript spec). To switch jlaskey@3: this off and remain in integer mode, for example for "var x = a&b; var jlaskey@3: y = c&d; var z = x*y;", use this flag. This will force the jlaskey@3: multiplication of variables that are ints to be done with the IMUL jlaskey@3: bytecode and the result "z" to become an int. jlaskey@3: jlaskey@3: WARNING: Note that is is experimental only to ensure that type support jlaskey@3: exists for all primitive types. The generated code is unsound. This jlaskey@3: will be the case until we do optimizations based on it. There is a CR jlaskey@3: in Nashorn to do better range analysis, and ensure that this is only jlaskey@3: done where the operation can't overflow into a wider type. Currently jlaskey@3: no overflow checking is done, so at the moment, until range analysis jlaskey@3: has been completed, this option is turned off. jlaskey@3: jlaskey@3: We've experimented by using int arithmetic for everything and putting jlaskey@3: overflow checks afterwards, which would recompute the operation with jlaskey@3: the correct precision, but have yet to find a configuration where this jlaskey@3: is faster than just using doubles directly, even if the int operation jlaskey@3: does not overflow. Getting access to a JVM intrinsic that does branch jlaskey@3: on overflow would probably alleviate this. jlaskey@3: jlaskey@3: There is also a problem with this optimistic approach if the symbol jlaskey@3: happens to reside in a local variable slot in the bytecode, as those jlaskey@3: are strongly typed. Then we would need to split large sections of jlaskey@3: control flow, so this is probably not the right way to go, while range jlaskey@3: analysis is. There is a large difference between integer bytecode jlaskey@3: without overflow checks and double bytecode. The former is jlaskey@3: significantly faster. jlaskey@3: jlaskey@3: jlaskey@3: SYSTEM PROPERTY: -Dnashorn.codegen.debug, -Dnashorn.codegen.debug.trace= jlaskey@3: jlaskey@3: See the description of the codegen logger below. jlaskey@3: jlaskey@3: jlaskey@3: SYSTEM_PROPERTY: -Dnashorn.fields.debug jlaskey@3: jlaskey@3: See the description on the fields logger below. jlaskey@3: jlaskey@3: jlaskey@3: SYSTEM PROPERTY: -Dnashorn.fields.dual jlaskey@3: jlaskey@3: When this property is true, Nashorn will attempt to use primitive jlaskey@3: fields for AccessorProperties (currently just AccessorProperties, not jlaskey@3: spill properties). Memory footprint for script objects will increase, jlaskey@3: as we need to maintain both a primitive field (a long) as well as an jlaskey@3: Object field for the property value. Ints are represented as the 32 jlaskey@3: low bits of the long fields. Doubles are represented as the jlaskey@3: doubleToLongBits of their value. This way a single field can be used jlaskey@3: for all primitive types. Packing and unpacking doubles to their bit jlaskey@3: representation is intrinsified by the JVM and extremely fast. jlaskey@3: jlaskey@3: While dual fields in theory runs significantly faster than Object jlaskey@3: fields due to reduction of boxing and memory allocation overhead, jlaskey@3: there is still work to be done to make this a general purpose jlaskey@3: solution. Research is ongoing. jlaskey@3: jlaskey@3: In the future, this might complement or be replaced by experimental jlaskey@3: feature sun.misc.TaggedArray, which has been discussed on the mlvm jlaskey@3: mailing list. TaggedArrays are basically a way to share data space jlaskey@3: between primitives and references, and have the GC understand this. jlaskey@3: jlaskey@3: As long as only primitive values are written to the fields and enough jlaskey@3: type information exists to make sure that any reads don't have to be jlaskey@3: uselessly boxed and unboxed, this is significantly faster than the jlaskey@3: standard "Objects only" approach that currently is the default. See jlaskey@3: test/examples/dual-fields-micro.js for an example that runs twice as jlaskey@3: fast with dual fields as without them. Here, the compiler, can jlaskey@3: determine that we are dealing with numbers only throughout the entire jlaskey@3: property life span of the properties involved. jlaskey@3: jlaskey@3: If a "real" object (not a boxed primitive) is written to a field that jlaskey@3: has a primitive representation, its callsite is relinked and an Object jlaskey@3: field is used forevermore for that particular field in that jlaskey@3: PropertyMap and its children, even if primitives are later assigned to jlaskey@3: it. jlaskey@3: jlaskey@3: As the amount of compile time type information is very small in a jlaskey@3: dynamic language like JavaScript, it is frequently the case that jlaskey@3: something has to be treated as an object, because we don't know any jlaskey@3: better. In reality though, it is often a boxed primitive is stored to jlaskey@3: an AccessorProperty. The fastest way to handle this soundly is to use jlaskey@3: a callsite typecheck and avoid blowing the field up to an Object. We jlaskey@3: never revert object fields to primitives. Ping-pong:ing back and forth jlaskey@3: between primitive representation and Object representation would cause jlaskey@3: fatal performance overhead, so this is not an option. jlaskey@3: jlaskey@3: For a general application the dual fields approach is still slower jlaskey@3: than objects only fields in some places, about the same in most cases, jlaskey@3: and significantly faster in very few. This is due the program using jlaskey@3: primitives, but we still can't prove it. For example "local_var a = jlaskey@3: call(); field = a;" may very well write a double to the field, but the jlaskey@3: compiler dare not guess a double type if field is a local variable, jlaskey@3: due to bytecode variables being strongly typed and later non jlaskey@3: interchangeable. To get around this, the entire method would have to jlaskey@3: be replaced and a continuation retained to restart from. We believe jlaskey@3: that the next steps we should go through are instead: jlaskey@3: jlaskey@3: 1) Implement method specialization based on callsite, as it's quite jlaskey@3: frequently the case that numbers are passed around, but currently our jlaskey@3: function nodes just have object types visible to the compiler. For jlaskey@3: example "var b = 17; func(a,b,17)" is an example where two parameters jlaskey@3: can be specialized, but the main version of func might also be called jlaskey@3: from another callsite with func(x,y,"string"). jlaskey@3: jlaskey@3: 2) This requires lazy jitting as the functions have to be specialized jlaskey@3: per callsite. jlaskey@3: jlaskey@3: Even though "function square(x) { return x*x }" might look like a jlaskey@3: trivial function that can always only take doubles, this is not jlaskey@3: true. Someone might have overridden the valueOf for x so that the jlaskey@3: toNumber coercion has side effects. To fulfil JavaScript semantics, jlaskey@3: the coercion has to run twice for both terms of the multiplication jlaskey@3: even if they are the same object. This means that call site jlaskey@3: specialization is necessary, not parameter specialization on the form jlaskey@3: "function square(x) { var xd = (double)x; return xd*xd; }", as one jlaskey@3: might first think. jlaskey@3: jlaskey@3: Generating a method specialization for any variant of a function that jlaskey@3: we can determine by types at compile time is a combinatorial explosion jlaskey@3: of byte code (try it e.g. on all the variants of am3 in the Octane jlaskey@3: benchmark crypto.js). Thus, this needs to be lazy jlaskey@3: jlaskey@3: 3) Possibly optimistic callsite writes, something on the form jlaskey@3: jlaskey@3: x = y; //x is a field known to be a primitive. y is only an object as jlaskey@3: far as we can tell jlaskey@3: jlaskey@3: turns into jlaskey@3: jlaskey@3: try { jlaskey@3: x = (int)y; jlaskey@3: } catch (X is not an integer field right now | ClassCastException e) { jlaskey@3: x = y; jlaskey@3: } jlaskey@3: jlaskey@3: Mini POC shows that this is the key to a lot of dual field performance jlaskey@3: in seemingly trivial micros where one unknown object, in reality jlaskey@3: actually a primitive, foils it for us. Very common pattern. Once we jlaskey@3: are "all primitives", dual fields runs a lot faster than Object fields jlaskey@3: only. jlaskey@3: jlaskey@3: We still have to deal with objects vs primitives for local bytecode jlaskey@3: slots, possibly through code copying and versioning. jlaskey@3: jlaskey@3: jlaskey@3: SYSTEM PROPERTY: -Dnashorn.compiler.symbol.trace= jlaskey@3: jlaskey@3: When this property is set, creation and manipulation of any symbol jlaskey@3: named "x" will show information about when the compiler changes its jlaskey@3: type assumption, bytecode local variable slot assignment and other jlaskey@3: data. This is useful if, for example, a symbol shows up as an Object, jlaskey@3: when you believe it should be a primitive. Usually there is an jlaskey@3: explanation for this, for example that it exists in the global scope jlaskey@3: and type analysis has to be more conservative. In that case, the stack jlaskey@3: trace upon type change to object will usually tell us why. jlaskey@3: jlaskey@3: jlaskey@3: SYSTEM PROPERTY: nashorn.lexer.xmlliterals jlaskey@3: jlaskey@3: If this property it set, it means that the Lexer should attempt to jlaskey@3: parse XML literals, which would otherwise generate syntax jlaskey@3: errors. Warning: there are currently no unit tests for this jlaskey@3: functionality. jlaskey@3: jlaskey@3: XML literals, when this is enabled, end up as standard LiteralNodes in jlaskey@3: the IR. jlaskey@3: jlaskey@3: jlaskey@3: SYSTEM_PROPERTY: nashorn.debug jlaskey@3: jlaskey@3: If this property is set to true, Nashorn runs in Debug mode. Debug jlaskey@3: mode is slightly slower, as for example statistics counters are enabled jlaskey@3: during the run. Debug mode makes available a NativeDebug instance jlaskey@3: called "Debug" in the global space that can be used to print property jlaskey@3: maps and layout for script objects, as well as a "dumpCounters" method jlaskey@3: that will print the current values of the previously mentioned stats jlaskey@3: counters. jlaskey@3: jlaskey@3: These functions currently exists for Debug: jlaskey@3: jlaskey@3: "map" - print(Debug.map(x)) will dump the PropertyMap for object x to jlaskey@3: stdout (currently there also exist functions called "embedX", where X jlaskey@3: is a value from 0 to 3, that will dump the contents of the embed pool jlaskey@3: for the first spill properties in any script object and "spill", that jlaskey@3: will dump the contents of the growing spill pool of spill properties jlaskey@3: in any script object. This is of course subject to change without jlaskey@3: notice, should we change the script object layout. jlaskey@3: jlaskey@3: "methodHandle" - this method returns the method handle that is used jlaskey@3: for invoking a particular script function. jlaskey@3: jlaskey@3: "identical" - this method compares two script objects for reference jlaskey@3: equality. It is a == Java comparison jlaskey@3: jlaskey@3: "dumpCounters" - will dump the debug counters' current values to jlaskey@3: stdout. jlaskey@3: jlaskey@3: Currently we count number of ScriptObjects in the system, number of jlaskey@3: Scope objects in the system, number of ScriptObject listeners added, jlaskey@3: removed and dead (without references). jlaskey@3: jlaskey@3: We also count number of ScriptFunctions, ScriptFunction invocations jlaskey@3: and ScriptFunction allocations. jlaskey@3: jlaskey@3: Furthermore we count PropertyMap statistics: how many property maps jlaskey@3: exist, how many times were property maps cloned, how many times did jlaskey@3: the property map history cache hit, prevent new allocations, how many jlaskey@3: prototype invalidations were done, how many time the property map jlaskey@3: proto cache hit. jlaskey@3: jlaskey@3: Finally we count callsite misses on a per callsite bases, which occur jlaskey@3: when a callsite has to be relinked, due to a previous assumption of jlaskey@3: object layout being invalidated. jlaskey@3: jlaskey@3: jlaskey@3: SYSTEM PROPERTY: nashorn.methodhandles.debug, jlaskey@3: nashorn.methodhandles.debug=create jlaskey@3: jlaskey@3: If this property is enabled, each MethodHandle related call that uses jlaskey@3: the java.lang.invoke package gets its MethodHandle intercepted and an jlaskey@3: instrumentation printout of arguments and return value appended to jlaskey@3: it. This shows exactly which method handles are executed and from jlaskey@3: where. (Also MethodTypes and SwitchPoints). This can be augmented with jlaskey@3: more information, for example, instance count, by subclassing or jlaskey@3: further extending the TraceMethodHandleFactory implementation in jlaskey@3: MethodHandleFactory.java. jlaskey@3: jlaskey@3: If the property is specialized with "=create" as its option, jlaskey@3: instrumentation will be shown for method handles upon creation time jlaskey@3: rather than at runtime usage. jlaskey@3: jlaskey@3: jlaskey@3: SYSTEM PROPERTY: nashorn.methodhandles.debug.stacktrace jlaskey@3: jlaskey@3: This does the same as nashorn.methodhandles.debug, but when enabled jlaskey@3: also dumps the stack trace for every instrumented method handle jlaskey@3: operation. Warning: This is enormously verbose, but provides a pretty jlaskey@3: decent "grep:able" picture of where the calls are coming from. jlaskey@3: jlaskey@3: See the description of the codegen logger below for a more verbose jlaskey@3: description of this option jlaskey@3: jlaskey@3: jlaskey@3: SYSTEM PROPERTY: nashorn.scriptfunction.specialization.disable jlaskey@3: jlaskey@3: There are several "fast path" implementations of constructors and jlaskey@3: functions in the NativeObject classes that, in their original form, jlaskey@3: take a variable amount of arguments. Said functions are also declared jlaskey@3: to take Object parameters in their original form, as this is what the jlaskey@3: JavaScript specification mandates. jlaskey@3: jlaskey@3: However, we often know quite a lot more at a callsite of one of these jlaskey@3: functions. For example, Math.min is called with a fixed number (2) of jlaskey@3: integer arguments. The overhead of boxing these ints to Objects and jlaskey@3: folding them into an Object array for the generic varargs Math.min jlaskey@3: function is an order of magnitude slower than calling a specialized jlaskey@3: implementation of Math.min that takes two integers. Specialized jlaskey@3: functions and constructors are identified by the tag jlaskey@3: @SpecializedFunction and @SpecializedConstructor in the Nashorn jlaskey@3: code. The linker will link in the most appropriate (narrowest types, jlaskey@3: right number of types and least number of arguments) specialization if jlaskey@3: specializations are available. jlaskey@3: jlaskey@3: Every ScriptFunction may carry specializations that the linker can jlaskey@3: choose from. This framework will likely be extended for user defined jlaskey@3: functions. The compiler can often infer enough parameter type info jlaskey@3: from callsites for in order to generate simpler versions with less jlaskey@3: generic Object types. This feature depends on future lazy jitting, as jlaskey@3: there tend to be many calls to user defined functions, some where the jlaskey@3: callsite can be specialized, some where we mostly see object jlaskey@3: parameters even at the callsite. jlaskey@3: jlaskey@3: If this system property is set to true, the linker will not attempt to jlaskey@3: use any specialized function or constructor for native objects, but jlaskey@3: just call the generic one. jlaskey@3: jlaskey@3: jlaskey@3: SYSTEM PROPERTY: nashorn.tcs.miss.samplePercent= jlaskey@3: jlaskey@3: When running with the trace callsite option (-tcs), Nashorn will count jlaskey@3: and instrument any callsite misses that require relinking. As the jlaskey@3: number of relinks is large and usually produces a lot of output, this jlaskey@3: system property can be used to constrain the percentage of misses that jlaskey@3: should be logged. Typically this is set to 1 or 5 (percent). 1% is the jlaskey@3: default value. jlaskey@3: jlaskey@3: jlaskey@3: SYSTEM_PROPERTY: nashorn.profilefile= jlaskey@3: jlaskey@3: When running with the profile callsite options (-pcs), Nashorn will jlaskey@3: dump profiling data for all callsites to stderr as a shutdown hook. To jlaskey@3: instead redirect this to a file, specify the path to the file using jlaskey@3: this system property. jlaskey@3: jlaskey@3: jlaskey@3: =============== jlaskey@3: 2. The loggers. jlaskey@3: =============== jlaskey@3: jlaskey@3: The Nashorn loggers can be used to print per-module or per-subsystem jlaskey@3: debug information with different levels of verbosity. The loggers for jlaskey@3: a given subsystem are available are enabled by using jlaskey@3: jlaskey@3: --log=[:] jlaskey@3: jlaskey@3: on the command line. jlaskey@3: jlaskey@3: Here identifies the name of the subsystem to be logged jlaskey@3: and the optional colon and level argument is a standard jlaskey@3: java.util.logging.Level name (severe, warning, info, config, fine, jlaskey@3: finer, finest). If the level is left out for a particular subsystem, jlaskey@3: it defaults to "info". Any log message logged as the level or a level jlaskey@3: that is more important will be output to stderr by the logger. jlaskey@3: jlaskey@3: Several loggers can be enabled by a single command line option, by jlaskey@3: putting a comma after each subsystem/level tuple (or each subsystem if jlaskey@3: level is unspecified). The --log option can also be given multiple jlaskey@3: times on the same command line, with the same effect. jlaskey@3: jlaskey@3: For example: --log=codegen,fields:finest is equivalent to jlaskey@3: --log=codegen:info --log=fields:finest jlaskey@3: jlaskey@3: The subsystems that currently support logging are: jlaskey@3: jlaskey@3: jlaskey@3: * compiler jlaskey@3: jlaskey@3: The compiler is in charge of turning source code and function nodes jlaskey@3: into byte code, and installs the classes into a class loader jlaskey@3: controlled from the Context. Log messages are, for example, about jlaskey@3: things like new compile units being allocated. The compiler has global jlaskey@3: settings that all the tiers of codegen (e.g. Lower and CodeGenerator) jlaskey@3: use. jlaskey@3: jlaskey@3: jlaskey@3: * codegen jlaskey@3: jlaskey@3: The code generator is the emitter stage of the code pipeline, and jlaskey@3: turns the lowest tier of a FunctionNode into bytecode. Codegen logging jlaskey@3: shows byte codes as they are being emitted, line number information jlaskey@3: and jumps. It also shows the contents of the bytecode stack prior to jlaskey@3: each instruction being emitted. This is a good debugging aid. For jlaskey@3: example: jlaskey@3: jlaskey@3: [codegen] #41 line:2 (f)_afc824e jlaskey@3: [codegen] #42 load symbol x slot=2 jlaskey@3: [codegen] #43 {1:O} load int 0 jlaskey@3: [codegen] #44 {2:I O} dynamic_runtime_call GT:ZOI_I args=2 returnType=boolean jlaskey@3: [codegen] #45 signature (Ljava/lang/Object;I)Z jlaskey@3: [codegen] #46 {1:Z} ifeq ternary_false_5402fe28 jlaskey@3: [codegen] #47 load symbol x slot=2 jlaskey@3: [codegen] #48 {1:O} goto ternary_exit_107c1f2f jlaskey@3: [codegen] #49 ternary_false_5402fe28 jlaskey@3: [codegen] #50 load symbol x slot=2 jlaskey@3: [codegen] #51 {1:O} convert object -> double jlaskey@3: [codegen] #52 {1:D} neg jlaskey@3: [codegen] #53 {1:D} convert double -> object jlaskey@3: [codegen] #54 {1:O} ternary_exit_107c1f2f jlaskey@3: [codegen] #55 {1:O} return object jlaskey@3: jlaskey@3: shows a ternary node being generated for the sequence "return x > 0 ? jlaskey@3: x : -x" jlaskey@3: jlaskey@3: The first number on the log line is a unique monotonically increasing jlaskey@3: emission id per bytecode. There is no guarantee this is the same id jlaskey@3: between runs. depending on non deterministic code jlaskey@3: execution/compilation, but for small applications it usually is. If jlaskey@3: the system variable -Dnashorn.codegen.debug.trace= is set, where x jlaskey@3: is a bytecode emission id, a stack trace will be shown as the jlaskey@3: particular bytecode is about to be emitted. This can be a quick way to jlaskey@3: determine where it comes from without attaching the debugger. "Who jlaskey@3: generated that neg?" jlaskey@3: jlaskey@3: The --log=codegen option is equivalent to setting the system variable jlaskey@3: "nashorn.codegen.debug" to true. jlaskey@3: jlaskey@3: jlaskey@3: * lower jlaskey@3: jlaskey@3: The lowering annotates a FunctionNode with symbols for each identifier jlaskey@3: and transforms high level constructs into lower level ones, that the jlaskey@3: CodeGenerator consumes. jlaskey@3: jlaskey@3: Lower logging typically outputs things like post pass actions, jlaskey@3: insertions of casts because symbol types have been changed and type jlaskey@3: specialization information. Currently very little info is generated by jlaskey@3: this logger. This will probably change. jlaskey@3: jlaskey@3: jlaskey@3: * access jlaskey@3: jlaskey@3: The --log=access option is equivalent to setting the system variable jlaskey@3: "nashorn.callsiteaccess.debug" to true. There are several levels of jlaskey@3: the access logger, usually the default level "info" is enough jlaskey@3: jlaskey@3: It is very simple to create your own logger. Use the DebugLogger class jlaskey@3: and give the subsystem name as a constructor argument. jlaskey@3: jlaskey@3: jlaskey@3: * fields jlaskey@3: jlaskey@3: The --log=fields option (at info level) is equivalent to setting the jlaskey@3: system variable "nashorn.fields.debug" to true. At the info level it jlaskey@3: will only show info about type assumptions that were invalidated. If jlaskey@3: the level is set to finest, it will also trace every AccessorProperty jlaskey@3: getter and setter in the program, show arguments, return values jlaskey@3: etc. It will also show the internal representation of respective field jlaskey@3: (Object in the normal case, unless running with the dual field jlaskey@3: representation)