8201516: DebugNonSafepoints generates incorrect information #12806

TobiHartmann · 2023-03-01T14:12:34Z

C2 emits incorrect debug information when diagnostic -XX:+DebugNonSafepoints is enabled. The problem is that renumbering of live nodes (-XX:+RenumberLiveNodes) introduced by JDK-8129847 in JDK 8u92 / JDK 9 does not update the _node_note_array side table that links IR node indices to debug information. As a result, after node indices are updated, they point to unrelated debug information.

The reproducer shared by the original reporter @jodzga (@jbachorik also reported this issue separately) does not work anymore with recent JDK versions but with a slight adjustment to trigger node renumbering, I could reproduce the wrong JFR method profile:

It suggests that the hottest method of the Test is not the long running loop in Test::arraycopy but several other short running methods. The hot method is not even in the profile. This is obviously wrong.

With the fix, or when running with -XX:-RenumberLiveNodes as a workaround, the correct profile looks like this:

With the help of the IR framework, it's easy to create a simple regression test (see testRenumberLiveNodes).

The fix is to create a new node_note_array and copy the debug information to the right index after updating node indices. We do the same in the matcher:

jdk/src/hotspot/share/opto/matcher.cpp

Lines 337 to 342 in c1e77e0

    
           // Save debug and profile information for nodes in old space: 
        
           _old_node_note_array = C->node_note_array(); 
        
           if (_old_node_note_array != NULL) { 
        
             C->set_node_note_array(new(C->comp_arena()) GrowableArray<Node_Notes*> 
        
                                    (C->comp_arena(), _old_node_note_array->length(), 
        
                                     0, NULL));

Another problem is that Parse::Parse calls C->set_default_node_notes(caller_nn) before do_exits, which resets the JVMState to the caller state. We then set the bci to InvocationEntryBci in the caller JVMState. Any new node that is emitted in do_exits, for example a MemBarRelease, will have that JVMState attached and NonSafepointEmitter::observe_instruction -> DebugInformationRecorder::describe_scope will then use that information when emitting debug info. The resulting debug info is misleading because it suggests that we are at the beginning of the caller method. The tests testFinalFieldInit and testSynchronized reproduce that scenario.

The fix is to move set_default_node_notes down to after do_exits.

I find it also misleading that we often emit "synchronization entry" for InvocationEntryBci at method entry/exit in the debug info, although there is no synchronization happening. I filed JDK-8303451 to fix that.

Thanks,
Tobias

Progress

Change must be properly reviewed (1 review required, with at least 1 Reviewer)
Change must not contain extraneous whitespace
Commit message must refer to an issue

Issue

JDK-8201516: DebugNonSafepoints generates incorrect information

Reviewers

Vladimir Kozlov (@vnkozlov - Reviewer)
Roland Westrelin (@rwestrel - Reviewer)

Reviewing

Using git

Checkout this PR locally:
$ git fetch https://git.openjdk.org/jdk pull/12806/head:pull/12806
$ git checkout pull/12806

Update a local copy of the PR:
$ git checkout pull/12806
$ git pull https://git.openjdk.org/jdk pull/12806/head

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 12806

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

Using diff file

Download this PR as a diff file:
https://git.openjdk.org/jdk/pull/12806.diff

bridgekeeper · 2023-03-01T14:14:08Z

👋 Welcome back thartmann! 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 · 2023-03-01T14:15:54Z

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

hotspot-compiler

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.

mlbridge · 2023-03-01T14:19:55Z

Webrevs

vnkozlov

I have few comments.

vnkozlov · 2023-03-01T17:51:14Z

src/hotspot/share/opto/phaseX.cpp

+  if (old_node_note_array != NULL) {
+    C->set_node_note_array(new (C->comp_arena()) GrowableArray<Node_Notes*> (C->comp_arena(), 8, 0, NULL));


Use nullptr in these lines.
Can you use _useful.size() as initial array length?

Thanks for the review, Vladimir. I updated the NULL usages.

Can you use _useful.size() as initial array length?

The node_note_array uses buckets/blocks of size C->_node_notes_block_size == 256. So the actual required size would be ceil((double)useful.size() / (double)256) but we could simply use 1 + (useful.size() / 256).

Now even when initializing the GrowableArray to that size, setting notes will then still call Compile::grow_node_notes multiple times to create the Node_Notes buckets and since it always at least doubles the backing array size, we actually end up with an array that is larger than what is required:

jdk/src/hotspot/share/opto/compile.cpp

Lines 1233 to 1238 in 4619e8b

if (grow_by < num_blocks) grow_by = num_blocks;

int num_notes = grow_by * _node_notes_block_size;

Node_Notes* notes = NEW_ARENA_ARRAY(node_arena(), Node_Notes, num_notes);

Copy::zero_to_bytes(notes, num_notes * sizeof(Node_Notes));

while (num_notes > 0) {

arr->append(notes);

I updated the code to properly pre-size the structure by calling grow_node_notes. This also has the advantage that the Node_Notes arena is one big chunk instead of incrementally allocating small ones.

What do you think?

vnkozlov · 2023-03-01T17:53:21Z

src/hotspot/share/opto/phaseX.cpp

@@ -484,6 +489,11 @@ PhaseRenumberLive::PhaseRenumberLive(PhaseGVN* gvn,
    assert(_old2new_map.at(n->_idx) == -1, "already seen");
    _old2new_map.at_put(n->_idx, current_idx);

+    if (old_node_note_array != NULL) {


vnkozlov · 2023-03-02T17:47:17Z

src/hotspot/share/opto/phaseX.cpp

@@ -469,6 +469,13 @@ PhaseRenumberLive::PhaseRenumberLive(PhaseGVN* gvn,

  uint worklist_size = worklist->size();

+  GrowableArray<Node_Notes*>* old_node_note_array = C->node_note_array();
+  if (old_node_note_array != nullptr) {
+    int new_size = (_useful.size() >> 8) + 1; // The node note array uses blocks, see C->_log2_node_notes_block_size


You should call new_size = MAX2(8, new_size) to make sure that we have at least 8 elements for initial allocation.

Okay, I added that. The 8 seems arbitrary to me but since we already use that for initial allocation of the array, we can as well be consistent here. Just note that since we are calling C->grow_node_notes, we will also initialize with Node_Notes* right away.

Why don't we just use C->_log2_node_notes_block_size directly in (_useful.size() >> 8)?

I don't understand why we have to add MAX2(8, new_size) either. It looks like c2 doesn't want to have node-level accuracy. It drops the lowest 8bits of node_idx as block_id. I think the minimal number of "block" is 1, or arr is NULL.

Why don't we just use C->_log2_node_notes_block_size directly in (_useful.size() >> 8)?

Because it's private in Compile. We could make it public but I thought it's not worth it.

I don't understand why we have to add MAX2(8, new_size) either. It looks like c2 doesn't want to have node-level accuracy. It drops the lowest 8bits of node_idx as block_id. I think the minimal number of "block" is 1, or arr is NULL.

I think you are misinterpreting the code in Compile::locate_node_notes. It first determines the block_idx by idx >> _log2_node_notes_block_size and then the position in that block by idx & (_node_notes_block_size-1).

Thanks for the clarification. yes, I understanding was wrong.

A block is an array of 256 Node_Note. Is it a particular reason that Compile needs at least 8 blocks? It can grow automatically anyway.

Is it a particular reason that Compile needs at least 8 blocks?

It's the value that is used when creating the array:

jdk/src/hotspot/share/opto/compile.cpp

Lines 1060 to 1062 in 4619e8b

set_node_note_array(new(comp_arena()) GrowableArray<Node_Notes*>

(comp_arena(), 8, 0, NULL));

set_default_node_notes(Node_Notes::make(this));

I don't think there is a particular reason for 8 but it's just one of those more or less reasonable default values/sizes that we use all over the place when creating containers.

vnkozlov

Good

openjdk · 2023-03-03T15:46:53Z

@TobiHartmann 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:

8201516: DebugNonSafepoints generates incorrect information

Reviewed-by: kvn, roland

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 100 new commits pushed to the master branch:

8e20145: 8300654: Remove JVMFlag::flag_error_str as it is unused
bdffe46: 8301222: Generalize check_release_entry in OopStorage
ec4e8aa: 8303244: G1: call CardTable::clear_MemRegion directly
5753ab5: 8297454: javax/swing/JComponent/7154030/bug7154030.java failed with "Exception: Failed to show opaque button"
fa1cebe: 8303266: Prefer ArrayList to LinkedList in JImageTask
5f153e0: 8302780: Add support for vectorized arraycopy GC barriers
d00a767: 8295737: macOS: Print content cut off when width > height with portrait orientation
15c76e4: 8301254: UNIX sun/font coding does not detect SuSE in openSUSE Leap distribution
3eff1a0: 8303630: Move nsk/jvmti/AttachOnDemand/attach002a/TestDescription.java back to general problem list
10d6a8e: 8299518: HotSpotVirtualMachine shared code across different platforms
... and 90 more: https://git.openjdk.org/jdk/compare/a2c5a4ac9ee10281470f291f5a8f8393acea02cc...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.

➡️ To integrate this PR with the above commit message to the master branch, type /integrate in a new comment.

rwestrel

Looks good to me.

TobiHartmann · 2023-03-06T18:36:29Z

Thanks for the review, Vladimir and Roland!

TobiHartmann · 2023-03-07T06:58:04Z

/integrate

openjdk · 2023-03-07T06:59:39Z

Going to push as commit 94eda53.
Since your change was applied there have been 110 commits pushed to the master branch:

c51d40c: 8303607: SunMSCAPI provider leaks memory and keys
f64ed09: 8303540: Eliminate unnecessary reference to javac internal class
ccfe167: 8298939: Refactor open/test/jdk/javax/rmi/ssl/SSLSocketParametersTest.sh to jtreg java test
cfb0a25: 8303440: The "ZonedDateTime.parse" may not accept the "UTC+XX" zone id
a97271e: 8301793: AlgorithmId should not encode a missing parameters field as NULL unless hardcoded
cac81dd: 8303577: [JVMCI] OOME causes crash while translating exceptions
877ab65: 8303264: Refactor nsk/stress/strace to extract shared and remove redundant code
ae8730f: 8303486: [REDO] Update ProcessTools.startProcess(...) to exit early if process exit before linePredicate is printed.
5977f26: 8303604: Passing by-value structs whose size is not power of 2 doesn't work on all platforms (mainline)
dccfe8a: 8303582: Reduce duplication in jdk/java/foreign tests
... and 100 more: https://git.openjdk.org/jdk/compare/a2c5a4ac9ee10281470f291f5a8f8393acea02cc...master

Your commit was automatically rebased without conflicts.

openjdk · 2023-03-07T07:00:03Z

@TobiHartmann Pushed as commit 94eda53.

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

apangin · 2023-04-17T17:33:57Z

/backport jdk17u-dev

openjdk · 2023-04-17T17:36:02Z

@apangin the backport was successfully created on the branch apangin-backport-94eda53d in my personal fork of openjdk/jdk17u-dev. To create a pull request with this backport targeting openjdk/jdk17u-dev:master, just click the following link:

➡️ Create pull request

The title of the pull request is automatically filled in correctly and below you find a suggestion for the pull request body:

Hi all,

This pull request contains a backport of commit 94eda53d from the openjdk/jdk repository.

The commit being backported was authored by Tobias Hartmann on 7 Mar 2023 and was reviewed by Vladimir Kozlov and Roland Westrelin.

Thanks!

If you need to update the source branch of the pull then run the following commands in a local clone of your personal fork of openjdk/jdk17u-dev:

$ git fetch https://github.com/openjdk-bots/jdk17u-dev.git apangin-backport-94eda53d:apangin-backport-94eda53d
$ git checkout apangin-backport-94eda53d
# make changes
$ git add paths/to/changed/files
$ git commit --message 'Describe additional changes made'
$ git push https://github.com/openjdk-bots/jdk17u-dev.git apangin-backport-94eda53d

TobiHartmann added 4 commits February 27, 2023 16:00

8201516: DebugNonSafepoints generates incorrect information

f65cb78

More fixes

2f13ef4

Fixed test method names

643b941

Added missing @ForceInline

1328155

openjdk bot added the rfr Pull request is ready for review label Mar 1, 2023

openjdk bot added the hotspot-compiler hotspot-compiler-dev@openjdk.org label Mar 1, 2023

Removed default argument

ec3ee51

vnkozlov reviewed Mar 1, 2023

View reviewed changes

TobiHartmann added 2 commits March 2, 2023 07:12

Use nullptr

413729d

Presize new node note array

f1bc8db

vnkozlov reviewed Mar 2, 2023

View reviewed changes

Use MAX2

5e22c2c

vnkozlov approved these changes Mar 3, 2023

View reviewed changes

openjdk bot added the ready Pull request is ready to be integrated label Mar 3, 2023

rwestrel approved these changes Mar 6, 2023

View reviewed changes

openjdk bot added the integrated Pull request has been integrated label Mar 7, 2023

openjdk bot closed this Mar 7, 2023

openjdk bot removed ready Pull request is ready to be integrated rfr Pull request is ready for review labels Mar 7, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

8201516: DebugNonSafepoints generates incorrect information #12806

8201516: DebugNonSafepoints generates incorrect information #12806

TobiHartmann commented Mar 1, 2023 •

edited by openjdk bot

Loading

bridgekeeper bot commented Mar 1, 2023

openjdk bot commented Mar 1, 2023

mlbridge bot commented Mar 1, 2023 •

edited

Loading

vnkozlov left a comment

vnkozlov Mar 1, 2023

TobiHartmann Mar 2, 2023

vnkozlov Mar 1, 2023

vnkozlov Mar 2, 2023

TobiHartmann Mar 3, 2023

navyxliu Mar 8, 2023

TobiHartmann Mar 8, 2023

navyxliu Mar 8, 2023

TobiHartmann Mar 9, 2023

vnkozlov left a comment

openjdk bot commented Mar 3, 2023 •

edited

Loading

rwestrel left a comment

TobiHartmann commented Mar 6, 2023

TobiHartmann commented Mar 7, 2023

openjdk bot commented Mar 7, 2023

openjdk bot commented Mar 7, 2023

apangin commented Apr 17, 2023

openjdk bot commented Apr 17, 2023

	// Save debug and profile information for nodes in old space:
	_old_node_note_array = C->node_note_array();
	if (_old_node_note_array != NULL) {
	C->set_node_note_array(new(C->comp_arena()) GrowableArray<Node_Notes*>
	(C->comp_arena(), _old_node_note_array->length(),
	0, NULL));

		if (old_node_note_array != NULL) {
		C->set_node_note_array(new (C->comp_arena()) GrowableArray<Node_Notes*> (C->comp_arena(), 8, 0, NULL));

	if (grow_by < num_blocks) grow_by = num_blocks;
	int num_notes = grow_by * _node_notes_block_size;
	Node_Notes* notes = NEW_ARENA_ARRAY(node_arena(), Node_Notes, num_notes);
	Copy::zero_to_bytes(notes, num_notes * sizeof(Node_Notes));
	while (num_notes > 0) {
	arr->append(notes);

	set_node_note_array(new(comp_arena()) GrowableArray<Node_Notes*>
	(comp_arena(), 8, 0, NULL));
	set_default_node_notes(Node_Notes::make(this));

8201516: DebugNonSafepoints generates incorrect information #12806

8201516: DebugNonSafepoints generates incorrect information #12806

Conversation

TobiHartmann commented Mar 1, 2023 • edited by openjdk bot Loading

Progress

Issue

Reviewers

Reviewing

bridgekeeper bot commented Mar 1, 2023

openjdk bot commented Mar 1, 2023

mlbridge bot commented Mar 1, 2023 • edited Loading

Webrevs

vnkozlov left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

vnkozlov left a comment

Choose a reason for hiding this comment

openjdk bot commented Mar 3, 2023 • edited Loading

rwestrel left a comment

Choose a reason for hiding this comment

TobiHartmann commented Mar 6, 2023

TobiHartmann commented Mar 7, 2023

openjdk bot commented Mar 7, 2023

openjdk bot commented Mar 7, 2023

apangin commented Apr 17, 2023

openjdk bot commented Apr 17, 2023

TobiHartmann commented Mar 1, 2023 •

edited by openjdk bot

Loading

mlbridge bot commented Mar 1, 2023 •

edited

Loading

openjdk bot commented Mar 3, 2023 •

edited

Loading