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