Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
wants to merge 11 commits into from

Conversation

tobiasholenstein
Copy link
Contributor

@tobiasholenstein tobiasholenstein commented Dec 7, 2021

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.


Progress

  • Change must not contain extraneous whitespace
  • Commit message must refer to an issue
  • Change must be properly reviewed

Issue

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

Reviewers

Reviewing

Using git

Checkout this PR locally:
$ git fetch https://git.openjdk.java.net/jdk pull/6746/head:pull/6746
$ git checkout pull/6746

Update a local copy of the PR:
$ git checkout pull/6746
$ git pull https://git.openjdk.java.net/jdk pull/6746/head

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 6746

View PR using the GUI difftool:
$ git pr show -t 6746

Using diff file

Download this PR as a diff file:
https://git.openjdk.java.net/jdk/pull/6746.diff

@bridgekeeper
Copy link

bridgekeeper bot commented Dec 7, 2021

👋 Welcome back tobiasholenstein! A progress list of the required criteria for merging this PR into master will be added to the body of your pull request. There are additional pull request commands available for use with this pull request.

@openjdk
Copy link

openjdk bot commented Dec 7, 2021

@tobiasholenstein The following label will be automatically applied to this pull request:

  • hotspot

When this pull request is ready to be reviewed, an "RFR" email will be sent to the corresponding mailing list. If you would like to change these labels, use the /label pull request command.

@openjdk openjdk bot added the hotspot hotspot-dev@openjdk.org label Dec 7, 2021
@tobiasholenstein tobiasholenstein marked this pull request as ready for review December 15, 2021 12:16
@openjdk openjdk bot added the rfr Pull request is ready for review label Dec 15, 2021
@mlbridge
Copy link

mlbridge bot commented Dec 15, 2021

Webrevs

@@ -245,6 +243,7 @@ static bool rematerialize_objects(JavaThread* thread, int exec_mode, CompiledMet
assert(Universe::heap()->is_in_or_null(result), "must be heap pointer");
if (TraceDeoptimization) {
tty->print_cr("SAVED OOP RESULT " INTPTR_FORMAT " in thread " INTPTR_FORMAT, p2i(result), p2i(thread));
tty->cr();
Copy link
Member

@dougxc dougxc Dec 15, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is this tty->cr() necessary given the print_cr call above?

if (TraceDeoptimization) {
tty->print_cr("DEOPT UNPACKING thread " INTPTR_FORMAT " vframeArray " INTPTR_FORMAT " mode %d",
p2i(thread), p2i(array), exec_mode);
tty->cr();
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same question as above about the necessity of cr().

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

DEOPT PACKING thread 0x00007f9b9b008a20 Compiled frame (sp=0x0000700002121f00 unextended sp=0x0000700002121f00, fp=0x0000000000000000, real_fp=0x0000700002121f30, pc=0x000000011bad5944)
     nmethod   1714  154       4       java.lang.String::indexOf (29 bytes)
     Virtual frames (innermost first):
        0 - (0x00007f9b9ff91038) - ifge @ bci 13 
        1 - (0x00007f9b9ff923a0) - invokestatic @ bci 13 
     Created vframeArray 0x00007f9ba280a820

DEOPT UNPACKING thread 0x00007f9b9b008a20 vframeArray 0x00007f9ba280a820 mode 2

{method} {0x000000012d00b8c8} 'indexOf' '(II)I' in 'java/lang/String' - invokestatic @ bci 13 sp = 0x0000700002121eb8
Expressions size: 0
Locals size: 3
[1. Interpreted Frame]
[...]

I have put it for separating the DEOPT PACKING, DEOPT UNPACKING and SAVED OOP RESULT blocks for readability reasons. But I don't mind removing it, if a compact log is preferred.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't feel strongly about it but I think -XX:+TraceDeoptimization -XX:-PrintDeoptimizationDetails has never printed blank lines. However, this is primarily for human consumption so it's fine to leave as you have it.

Copy link
Contributor

@vnkozlov vnkozlov left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good.

@openjdk
Copy link

openjdk bot commented Dec 16, 2021

@tobiasholenstein This change now passes all automated pre-integration checks.

ℹ️ This project also has non-automated pre-integration requirements. Please see the file CONTRIBUTING.md for details.

After integration, the commit message for the final commit will be:

8278329: some TraceDeoptimization code not included in PRODUCT build

Reviewed-by: dnsimon, kvn, never, thartmann

You can use pull request commands such as /summary, /contributor and /issue to adjust it as needed.

At the time when this comment was updated there had been 203 new commits pushed to the master branch:

  • 79b614c: 8279523: Parallel: Remove unnecessary PSScavenge::_to_space_top_before_gc
  • 5fa13bb: 8279522: Serial: Remove unused Generation::clear_remembered_set
  • 4aefd8b: 8279528: Unused TypeEnter.diag after JDK-8205187
  • 2f8a2fd: 8279568: IGV: Add bci and line number property for OSR compilations
  • 8d1a1e8: 8278228: C2: Improve identical back-to-back if elimination
  • e14fb4f: 8279437: [JVMCI] exception in HotSpotJVMCIRuntime.translate can exit the VM
  • 77757ba: 8225122: Test AncestorResized.java fails when Windows desktop is scaled.
  • f203723: 8279337: The MToolkit is still referenced in a few places
  • d47af74: 8279500: Remove FileMapHeader::_heap_obj_roots
  • 4243f4c: 8279540: Shenandoah: Should only clear CLD::_claim_strong mark for strong CLD iterations
  • ... and 193 more: https://git.openjdk.java.net/jdk/compare/23fd9f15da40cef00231380766158bc0fa537c38...master

As there are no conflicts, your changes will automatically be rebased on top of these commits when integrating. If you prefer to avoid this automatic rebasing, please check the documentation for the /integrate command for further details.

As you do not have Committer status in this project an existing Committer must agree to sponsor your change. Possible candidates are the reviewers of this PR (@dougxc, @vnkozlov, @tkrodriguez, @TobiHartmann) but any other Committer may sponsor as well.

➡️ To flag this PR as ready for integration with the above commit message, type /integrate in a new comment. (Afterwards, your sponsor types /sponsor in a new comment to perform the integration).

@openjdk openjdk bot added the ready Pull request is ready to be integrated label Dec 16, 2021
@tkrodriguez
Copy link
Contributor

Thanks for cleaning this up. I think a one or two things should be moved under PrintDeoptimizationDetails for consistency but I wanted to look more closely at the output before adding my comments. I'll have some comments up soon.

@tobiasholenstein
Copy link
Contributor Author

Thanks for cleaning this up. I think a one or two things should be moved under PrintDeoptimizationDetails for consistency but I wanted to look more closely at the output before adding my comments. I'll have some comments up soon.

Sure I will wait for your comment. (It could make sense to move some parts to PrintDeoptimizationDetails)

Note: PrintDeoptimizationDetails is not a diagnostic flag at the moment. I didn't change that in this PR because JDK-8278329 is typed as a Bug. I think if that is desired, it's best to change it in a separate enhancement issue. Also PrintDeoptimizationDetails can be combined with Verbose and WizardMode which are also not diagnostic flags.

@tkrodriguez
Copy link
Contributor

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 theDEOPT UNPACKINGprinting intovframeArray::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.

@tobiasholenstein
Copy link
Contributor Author

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-debugbuild:

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?

@tkrodriguez
Copy link
Contributor

Yes that output looks great to me. Thank you for taking the time to do this.

Copy link
Member

@TobiHartmann TobiHartmann left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Great work, looks good to me. Just found some minor style issues.

if (TraceDeoptimization) {
ResourceMark rm;
stringStream st;
//st.print_cr("DEOPT PACKING thread " INTPTR_FORMAT " ", p2i(thread));
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should be removed.

st.print(" bci=%d pc=" INTPTR_FORMAT ", relative_pc=" INTPTR_FORMAT JVMCI_ONLY(", debug_id=%d"), trap_scope->bci(), p2i(fr.pc()), fr.pc() - nm->code_begin()
#if INCLUDE_JVMCI
, debug_id
#endif
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You can use JVMCI_ONLY here as well. Same in line 1840.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Unfortunately, because of the comma and the way JVMCI_ONLY is defined, this does not work. I will leave it as it is

ResourceMark rm;
stringStream st;
st.print_cr("DEOPT UNPACKING thread=" INTPTR_FORMAT " vframeArray=" INTPTR_FORMAT " mode=%d",
p2i(current), p2i(this), exec_mode);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Indentation of line 586 is off-by-one.

@tobiasholenstein
Copy link
Contributor Author

@tkrodriguez , @dougxc , @vnkozlov and @TobiHartmann Thanks for the inputs and the reviews!

Copy link
Member

@TobiHartmann TobiHartmann left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for changing. Looks good!

@mlbridge
Copy link

mlbridge bot commented Jan 8, 2022

Mailing list message from David Holmes on hotspot-dev:

Hi Tobias,

On 7/01/2022 8:56 pm, Tobias Holenstein wrote:

On Fri, 7 Jan 2022 07:28:23 GMT, Tobias Hartmann <thartmann at openjdk.org> wrote:

Tobias Holenstein has updated the pull request incrementally with one additional commit since the last revision:

Cleanup output of TraceDeoptimization

src/hotspot/share/runtime/deoptimization.cpp line 1954:

1952: #if INCLUDE_JVMCI
1953: , debug_id
1954: #endif

You can use `JVMCI_ONLY` here as well. Same in line 1840.

Unfortunately, because of the comma and the way JVMCI_ONLY is defined, this does not work. I will leave it as it is

We have the COMMA macro to solve that problem e.g.

./share/runtime/threadSMR.inline.hpp: DEBUG_ONLY(COMMA _list(list))

Cheers,
David

@tobiasholenstein
Copy link
Contributor Author

Mailing list message from David Holmes on hotspot-dev:

Hi Tobias,

On 7/01/2022 8:56 pm, Tobias Holenstein wrote:

On Fri, 7 Jan 2022 07:28:23 GMT, Tobias Hartmann wrote:

Tobias Holenstein has updated the pull request incrementally with one additional commit since the last revision:
Cleanup output of TraceDeoptimization

src/hotspot/share/runtime/deoptimization.cpp line 1954:

1952: #if INCLUDE_JVMCI
1953: , debug_id
1954: #endif

You can use JVMCI_ONLY here as well. Same in line 1840.

Unfortunately, because of the comma and the way JVMCI_ONLY is defined, this does not work. I will leave it as it is

We have the COMMA macro to solve that problem e.g.

./share/runtime/threadSMR.inline.hpp: DEBUG_ONLY(COMMA _list(list))

Cheers, David

Ok, I didn't know that. I changed it now to DEBUG_ONLY(COMMA ...)

Thanks David!

  • Tobias

@tobiasholenstein
Copy link
Contributor Author

/integrate

@openjdk openjdk bot added the sponsor Pull request is ready to be sponsored label Jan 10, 2022
@openjdk
Copy link

openjdk bot commented Jan 10, 2022

@tobiasholenstein
Your change (at version fe555ff) is now ready to be sponsored by a Committer.

@TobiHartmann
Copy link
Member

/sponsor

@openjdk
Copy link

openjdk bot commented Jan 10, 2022

Going to push as commit 1f101b0.
Since your change was applied there have been 203 commits pushed to the master branch:

  • 79b614c: 8279523: Parallel: Remove unnecessary PSScavenge::_to_space_top_before_gc
  • 5fa13bb: 8279522: Serial: Remove unused Generation::clear_remembered_set
  • 4aefd8b: 8279528: Unused TypeEnter.diag after JDK-8205187
  • 2f8a2fd: 8279568: IGV: Add bci and line number property for OSR compilations
  • 8d1a1e8: 8278228: C2: Improve identical back-to-back if elimination
  • e14fb4f: 8279437: [JVMCI] exception in HotSpotJVMCIRuntime.translate can exit the VM
  • 77757ba: 8225122: Test AncestorResized.java fails when Windows desktop is scaled.
  • f203723: 8279337: The MToolkit is still referenced in a few places
  • d47af74: 8279500: Remove FileMapHeader::_heap_obj_roots
  • 4243f4c: 8279540: Shenandoah: Should only clear CLD::_claim_strong mark for strong CLD iterations
  • ... and 193 more: https://git.openjdk.java.net/jdk/compare/23fd9f15da40cef00231380766158bc0fa537c38...master

Your commit was automatically rebased without conflicts.

@openjdk openjdk bot added the integrated Pull request has been integrated label Jan 10, 2022
@openjdk openjdk bot closed this Jan 10, 2022
@openjdk openjdk bot removed ready Pull request is ready to be integrated rfr Pull request is ready for review sponsor Pull request is ready to be sponsored labels Jan 10, 2022
@openjdk
Copy link

openjdk bot commented Jan 10, 2022

@TobiHartmann @tobiasholenstein Pushed as commit 1f101b0.

💡 You may see a message that your pull request was closed with unmerged commits. This can be safely ignored.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
hotspot hotspot-dev@openjdk.org integrated Pull request has been integrated
5 participants