RFR: JDK-8278329: some TraceDeoptimization code not included in PRODUCT build

Tobias Holenstein duke at openjdk.java.net
Thu Jan 6 14:22:18 UTC 2022 

On Fri, 17 Dec 2021 20:51:44 GMT, Tom Rodriguez <never at openjdk.org> wrote:

>> After "JDK-8154011: Make `TraceDeoptimization` a diagnostic flag" some code was not included in the PRODUCT build. 
>> 
>> Removed all the #ifndef PRODUCT guards around `TraceDeoptimization` checks and made sure to be consistent. 
>> 
>> The DEOPT PACKING messages were controlled by `PrintDeoptimizationDetails` (develop flag), but DEOPT UNPACKING is controlled by `TraceDeoptimization` (product flag),. Therefore changed DEOPT PACKING messages to be controlled by `TraceDeoptimization` as well. 
>> 
>> Checked that tests are not affected. Checked on Aurora that performance is not affected.
>
> We can convert JDK-8278329 into a RFE if we need to.  Creating yet another bug just complicates things.  For debugging output the distinction between a bug and an RFE is pretty small anyway.
> 
> The first thing I notice that in a release build we get `[CodeBlob]` in this output which isn't very helpful.
> 
> DEOPT PACKING thread 0x00007fae8000dc00 Compiled frame (sp=0x000070000dd06ee0 unextended sp=0x000070000dd06ee0, fp=0x000000000000003a, real_fp=0x000070000dd06f10, pc=0x0000000116950388)
>      [CodeBlob]
>      Virtual frames (innermost first):
> 
> In fastdebug we get output like:
> 
>      nmethod   2351 1042       4       jdk.internal.misc.Unsafe::allocateUninitializedArray (55 bytes)
> 
> so I think the code is using a print function that doesn't exist in product.  That said I don't think that line of output is helpful since it reiterates the information in the trap or packing messages, so I'd be inclined to delete it.
> A full pack/unpack sequence looks like this:
> 
> Uncommon trap   bci=2 pc=0x00000001169ba620, relative_pc=0x00000000000005c0, method=scala.collection.mutable.HashTable$class.elemEquals(Lscala/collection/mutable/HashTable;Ljava/lang/Object;Ljava/lang/Object;)Z, debug_id=0
> Uncommon trap occurred in scala.collection.mutable.HashTable$class::findEntry compiler=c2 compile_id=1418 (@0x00000001169ba620) thread=7171 reason=unstable_if action=reinterpret unloaded_class_index=-1 debug_id=0
> DEOPT PACKING thread 0x00007fae8000dc00 Compiled frame (sp=0x000070000dd06230 unextended sp=0x000070000dd06230, fp=0x00000006016a06e0, real_fp=0x000070000dd06280, pc=0x00000001169ba620)
>      [CodeBlob]
>      Virtual frames (innermost first):
>         0 - (0x00007fae90293010) - if_acmpne @ bci 2 
>         1 - (0x00007fae90294328) - invokestatic @ bci 3 
>         2 - (0x00007fae90295640) - invokeinterface @ bci 35 
>      Created vframeArray 0x00007fadf1041800
> 
> DEOPT UNPACKING thread 0x00007fae8000dc00 vframeArray 0x00007fadf1041800 mode 2
> 
> {method} {0x0000000133ac41a8} 'findEntry' '(Lscala/collection/mutable/HashTable;Ljava/lang/Object;)Lscala/collection/mutable/HashEntry;' in 'scala/collection/mutable/HashTable$class' - invokeinterface @ bci 35 sp = 0x000070000dd061f0
> {method} {0x0000000133824bf8} 'elemEquals' '(Ljava/lang/Object;Ljava/lang/Object;)Z' in 'scala/collection/mutable/HashMap' - invokestatic @ bci 3 sp = 0x000070000dd06180
> {method} {0x0000000133ac4a60} 'elemEquals' '(Lscala/collection/mutable/HashTable;Ljava/lang/Object;Ljava/lang/Object;)Z' in 'scala/collection/mutable/HashTable$class' - if_acmpne @ bci 2 sp = 0x000070000dd06118
> 
> The `{method}` lines correspond to the vframes in the `PACKING` step so it would be nice if they were printed in a similar way, without the extra blank line in between.  We should also use a different printing function so they are printed in a more natural way, like class.name(parameters) without the '{method}` part.  So I'd recommended moving the `DEOPT UNPACKING` printing into `vframeArray::unpack_to_stack and try to make the output look similar between the two.  The unpacking step just add information about the sp used in the recreated interpreter frame.  Maybe something like this:
> 
> DEOPT UNPACKING thread 0x00007fae8000dc00 vframeArray 0x00007fadf1041800 mode 2
>      Virtual frames (innermost first):
>         0 - {0x0000000133ac41a8} scala/collection/mutable/HashTable$class.findEntry(Lscala/collection/mutable/HashTable;Ljava/lang/Object;)Lscala/collection/mutable/HashEntry; - invokeinterface @ bci 35 sp =
>         1 - {0x0000000133824bf8} scala/collection/mutable/HashMap.elemEquals(Ljava/lang/Object;Ljava/lang/Object;)Z - invokestatic @ bci 3 sp =
>         2 - {0x0000000133ac4a60} scala/collection/mutable/HashTable$class.elemEquals(Lscala/collection/mutable/HashTable;Ljava/lang/Object;Ljava/lang/Object;)Z - if_acmpne @ bci 2 sp =
> ``` and update the vframe printing to include similar information about the actual method?
> There's also the issue of 2 `Uncommon trap` messages for every trap that show slightly different information.  A single message would be clearer but maybe there's some good reason for the double printing that I'm missing.
> I can prepare a changeset with my suggestions if it's unclear what I'm asking for.
> I'm fine with the current state of PrintDeoptimizationDetails being non-product, but I'm surprised no one has finally deleted the `Verbose` and `WizardMode` flags.  Those are some ancient artifacts that should probably be purged.

I have cleaned up the output of `TraceDeoptimization` as suggested by @tkrodriguez 

  - The printing of `Uncommon trap` are now merged into one line
  - `DEOPT UNPACKING` and `DEOPT PACKING` are now printed in a similar and more structured way.

A `UNCOMMON TRAP` followed by the corresponding `DEOPT PACKING` and `DEOPT UNPACKING` now looks like this in `release` build:

UNCOMMON TRAP method=java.util.HashMap.putVal(ILjava/lang/Object;Ljava/lang/Object;ZZ)Ljava/lang/Object;  bci=56 pc=0x000000011d4482a8, relative_pc=0x0000000000000be8, debug_id=0 compiler=c2 compile_id=388 (@0x000000011d4482a8) thread=53259 reason=bimorphic_or_optimized_type_check action=maybe_recompile unloaded_class_index=-1 debug_id=0
DEOPT PACKING thread=0x00007fe4ad009200 vframeArray=0x00007fe4a901c600
   Compiled frame (sp=0x000070000ba30c20 unextended sp=0x000070000ba30c20, fp=0x000000070f6f9d70, real_fp=0x000070000ba30cb0, pc=0x000000011d4482a8)
   Virtual frames (innermost/newest first):
      VFrame 0 (0x00007fe4a88f2e10) - java.util.HashMap.putVal(ILjava/lang/Object;Ljava/lang/Object;ZZ)Ljava/lang/Object; - invokevirtual @ bci=56 
      VFrame 1 (0x00007fe4a88f4128) - java.util.HashMap.put(Ljava/lang/Object;Ljava/lang/Object;)Ljava/lang/Object; - invokevirtual @ bci=9 

DEOPT UNPACKING thread=0x00007fe4ad009200 vframeArray=0x00007fe4a901c600 mode=2
   Virtual frames (outermost/oldest first):
      VFrame 1 (0x00007fe4a901db58) - java.util.HashMap.put(Ljava/lang/Object;Ljava/lang/Object;)Ljava/lang/Object; - invokevirtual @ bci=9 sp=0x000070000ba30bf0
      VFrame 0 (0x00007fe4a901db00) - java.util.HashMap.putVal(ILjava/lang/Object;Ljava/lang/Object;ZZ)Ljava/lang/Object; - invokevirtual @ bci=56 sp=0x000070000ba30b60


and like this in `slow-debug`build:

UNCOMMON TRAP method=java.lang.StringLatin1.indexOf([BII)I  bci=13 pc=0x0000000118ad50c4, relative_pc=0x00000000000001e4, debug_id=0 compiler=c2 compile_id=155 (@0x0000000118ad50c4) thread=5635 reason=range_check action=reinterpret unloaded_class_index=-1 debug_id=0
DEOPT PACKING thread=0x00007ff88a008a20 vframeArray=0x00007ff88888f420
   Compiled frame (sp=0x000070000117a310 unextended sp=0x000070000117a310, fp=0x0000000000000000, real_fp=0x000070000117a340, pc=0x0000000118ad50c4)
     nmethod   1257  155       4       java.lang.String::indexOf (29 bytes)
   Virtual frames (innermost/newest first):
      VFrame 0 (0x00007ff88bfb3038) - java.lang.StringLatin1.indexOf([BII)I - ifge @ bci=13 
      VFrame 1 (0x00007ff88bfb43a0) - java.lang.String.indexOf(II)I - invokestatic @ bci=13 

DEOPT UNPACKING thread=0x00007ff88a008a20 vframeArray=0x00007ff88888f420 mode=2
   Virtual frames (outermost/oldest first):
      VFrame 1 (0x00007ff888890988) - java.lang.String.indexOf(II)I - invokestatic @ bci=13 sp=0x000070000117a2c8
      VFrame 0 (0x00007ff888890928) - java.lang.StringLatin1.indexOf([BII)I - ifge @ bci=13 sp=0x000070000117a268


@tkrodriguez does that look like what you had in mind?

-------------

PR: https://git.openjdk.java.net/jdk/pull/6746

More information about the hotspot-dev mailing list