8298992: runtime/NMT/SummarySanityCheck.java failed with "Total committed (MMMMMM) did not match the summarized committed (NNNNNN)" #15306

afshin-zafari · 2023-08-16T12:18:35Z

During exhaustive tests, it is observed that during taking snapshot of NMT metrics it is possible that new allocations happen concurrently, although a ThreadCritical is used during copying current metrics to the snapshot.
A loop is surrounding the copying and checks whether the copied and original are the same.

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-8298992: runtime/NMT/SummarySanityCheck.java failed with "Total committed (MMMMMM) did not match the summarized committed (NNNNNN)" (Bug - P4)

Reviewers

Gerard Ziemski (@gerard-ziemski - Committer) ⚠️ Review applies to 09cf7076
Thomas Stuefe (@tstuefe - Reviewer)

Reviewing

Using git

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

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

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 15306

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

Using diff file

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

Webrev

Link to Webrev Comment

…tted (MMMMMM) did not match the summarized committed (NNNNNN)"

bridgekeeper · 2023-08-16T12:20:08Z

👋 Welcome back azafari! 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-08-16T12:21:57Z

@afshin-zafari The following label will be automatically applied to this pull request:

hotspot-runtime

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.

gerard-ziemski · 2023-08-21T17:25:09Z

src/hotspot/share/services/mallocTracker.hpp

-    for (int index = 0; index < mt_number_of_types; index ++) {
-      s->_malloc[index] = _malloc[index];
-    }
+    size_t total_mallocs;


Can we rename from total_mallocs to total_size? When I looked at the code at first I thought we were counting here the number of malloc operations.

gerard-ziemski · 2023-08-21T17:33:24Z

The loop in copy_to seems to only exit if no-one allocated memory while the loop was busy. Should we consider adding some max loop counter to bail out if some threshold was reached?

I am a bit uncomfortable with a loop here that in theory might never terminate even if in practice your testing reveals no issue. Just wanted to raise this issue, not 100% sure it needs to be addressed.

afshin-zafari · 2023-08-22T08:59:46Z

The loop in copy_to seems to only exit if no-one allocated memory while the loop was busy. Should we consider adding some max loop counter to bail out if some threshold was reached?

I am a bit uncomfortable with a loop here that in theory might never terminate even if in practice your testing reveals no issue. Just wanted to raise this issue, not 100% sure it needs to be addressed.

I agree with you. The loop is limited now. Thanks.

mlbridge · 2023-08-22T09:04:51Z

Webrevs

01: Full - Incremental (a55e417a)
00: Full (09cf7076)

tstuefe · 2023-08-22T12:52:13Z

src/hotspot/share/services/mallocTracker.hpp

+        total_size += _malloc[index].malloc_size();
+      }
+    } while(s->_all_mallocs.size() != total_size && ++loop_counter < loop_limit);
+    assert(s->_all_mallocs.size() == total_size, "Total != sum of parts");


Preexisting, but could you please move this to the cpp file? It should not live in the header.

Also I'm not sure the assert is really useful. Won't that be just a source for very rare intermittent errors? What would be the action we take if that assert fires, increase the loop count?

We copy MemoryCounter by value, not reference:

s->_all_mallocs = _all_mallocs;

where _all_mallocs is MemoryCounter, not *MemoryCounter, so that assert can never trigger, right?

I mean, even if more memory gets allocated between when we exit the loop and assert, _all_mallocs.size() might change, but s->_all_mallocs.size() is frozen in time, isn't it?

So I agree that the assert is not helpful here, but it's because it will never trigger.

I thought the point was to compare the accumulated sum with the running total kept in _all_mallocs?

My understanding is that we make a snapshot of 2 moving parts: _all_mallocs and _malloc[nmt_type]

The problem is that after we snapshot _all_mallocs, _malloc[nmt_type] can change, so that:

s._all_mallocs.size() != s._malloc[nmt_type1] + s._malloc[nmt_type2] + ...

so we keep trying in a loop until we catch the system in a quiet enough period where:

s._all_mallocs.size() == s._malloc[nmt_type1] + s._malloc[nmt_type2] + ...

so when we come out of the loop then the assert is guaranteed never to trigger, because we made copies that are not going to change.

so we keep trying in a loop until we catch the system in a quiet enough period where:

s._all_mallocs.size() == s._malloc[nmt_type1] + s._malloc[nmt_type2] + ...

Either that or until the loop count is exhausted. That's what I meant - the assert could only fire if 100 tries were not enough to get a consistent picture.

I see now what you meant. On one hand it would be nice to know if the loop was unable to get consistent copy, on the other hand if we do get an assert, the only thing we can do is increase the count.

gerard-ziemski · 2023-08-22T19:36:50Z

src/hotspot/share/services/mallocTracker.hpp

+        total_size += _malloc[index].malloc_size();
+      }
+    } while(s->_all_mallocs.size() != total_size && ++loop_counter < loop_limit);
+    assert(s->_all_mallocs.size() == total_size, "Total != sum of parts");


Do we agree then that the assert on line 205 is not needed?

The issue here was that during copying malloc measures in the loop, some new allocations happen that change the copied items. This results in a mismatch of Total and the sum of items.
The ThreadCritical in the code was supposed to block other threads' allocations while copying. But it did not work as expected, since the ThreadCritical is used in a few deallocations in the code.
Therefore the while loop is written here to make sure that the malloc items that copied are consistent, i.e. $Total = \sum_i item_i$.

After Gerard's comment, the while-loop is upper limited to some iterations (loop_limit = 100) rather than be an infinite loop.

So if after loop_limit no of loops, the items are still not consistent then it is better to raise it here rather than to let this mismatch propagates up to the reports.

It is expected that replacing ThreadCritical with mutex for NMT, will resolve the issue and no while-loop is needed anymore.

Yes, I see the reaching loop counter issue now.

Are we going to replace ThreadCritical with NMT mutex here or is that going to be a different follow up issue?

jdksjolen · 2023-08-23T08:57:48Z

The ThreadCritical in the code was supposed to block other threads' allocations while copying. But it did not work as expected, since the ThreadCritical is used in a few deallocations in the code.

I don't understand what kind of concurrency problem we're reaching here. If the ThreadCritical lock is held during the summation and it attempts to be taken by the deallocations, then surely this would prevent any concurrent tampering of the data?

It is expected that replacing ThreadCritical with mutex for NMT, will resolve the issue and no while-loop is needed anymore.

I don't expect that to be true, ThreadCritical is a mutex.

afshin-zafari · 2023-08-23T10:04:45Z

I don't understand what kind of concurrency problem we're reaching here. If the ThreadCritical lock is held during the summation and it attempts to be taken by the deallocations, then surely this would prevent any concurrent tampering of the data?

If we remove the while loop and keep the assert, then in some rare tests in tiers 4 and 7 ( 3-4 cases in 700+ tests) that the assertion raised. I had used other asserts/logs in the code to find the roots of mismatching Total and Sum.
So, theoretically the ThreadCritical should keep other threads from alloc/dealloc. But in real, it does not.

afshin-zafari · 2023-08-23T10:25:33Z

ThreadCritical is a mutex.

I am referring to this issue.

tstuefe

I'm fine with the change (with or without assert). Thanks for fixing.

gerard-ziemski · 2023-08-23T15:26:20Z

The comment in void copy_to(MallocMemorySnapshot* s) says:

    // Need to make sure that mtChunks don't get deallocated while the
    // copy is going on, because their size is adjusted using this
    // buffer in make_adjustment().

but I don't see ThreadCritical used anywhere else, except copy_to() itself, so what does that lock synchronizes with exactly? Does it do anything at all right now?

I see atomic operations used to protect the individual memory counters, but I don't see anywhere where we protect the _all_mallocs + _malloc chunks. If anyone of them changes, then copying:

s->_all_mallocs = _all_mallocs;
loop (index) { s->_malloc[index] = _malloc[index]; }

might at the end not to agree on:

s._all_mallocs.size() == s._malloc[nmt_type1] + s._malloc[nmt_type2] + ...

Afshin proposed a simple fix, which even though not ideal, will get job done.

An ideal fix would make sure that any operation involving changing _all_mallocs and _malloc[nmt_type] are both synchronized, so that we can use that same lock (whatever it is) in copy_to()

Did I get this right?

afshin-zafari · 2023-08-25T08:28:15Z

Some facts about these NMT metrics are:

The total and sum of parts of the NMT reports are never checked to be consistent, except the JTREG test mentioned in the title of the issue. In that test, a difference of up to 8K/8M is tolerated due to round off values to scale of 1K/1M.
The concurrency of updating the metrics is handled by atomic operations. During taking snapshots, no control is made for concurrency, neither for malloc nor for virtual memory allocations.
In malloc case, there is a Total that held in the snapshot as well. This metric is used to detect inconsistency of Total and sum of the copied parts.
Using of ThreadCritical for keeping the metrics consistent, is not cheap. (Based on the current implementation of NMT and the comments of the ThreadCritical class definition)

The proposed small change here in this PR tries to be somewhere between fully-consistent metrics and never-consistent ones.
There is another issue(8304824) for replacing ThreadCritical with mutex. When that issue fixed, the while-loop added here would be removed.

gerard-ziemski · 2023-08-25T15:28:13Z

OK, this fix looks good to me then as is.

Thank you for fixing this.

tstuefe

still good.

afshin-zafari · 2023-08-28T08:42:59Z

Thank you @tstuefe and @gerard-ziemski, for comments and review.
/integrate

openjdk · 2023-08-28T08:43:14Z

@afshin-zafari This pull request has not yet been marked as ready for integration.

afshin-zafari · 2023-08-30T09:12:34Z

/integrate

openjdk · 2023-08-30T09:14:06Z

@afshin-zafari This pull request has not yet been marked as ready for integration.

afshin-zafari · 2023-08-30T09:38:13Z

/integrate

openjdk · 2023-08-30T09:38:34Z

@afshin-zafari Your integration request cannot be fulfilled at this time, as the status check jcheck-openjdk/jdk-15306 did not complete successfully

openjdk · 2023-08-30T11:06:45Z

@afshin-zafari 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:

8298992: runtime/NMT/SummarySanityCheck.java failed with "Total committed (MMMMMM) did not match the summarized committed (NNNNNN)"

Reviewed-by: gziemski, stuefe

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

cb3f968: 8314651: G1: Fix -Wconversion warnings in static fields of HeapRegion
876a725: 8315206: RISC-V: hwprobe query is_set return wrong value
ed1ea5f: 8314024: SIGSEGV in PhaseIdealLoop::build_loop_late_post_work due to bad immediate dominator info
f3aeb02: 8315213: java/lang/ProcessHandle/TreeTest.java test enhance output of children
1e7e2bc: 8315214: Do not run sun/tools/jhsdb tests concurrently
ce2a7ea: 8314056: Remove runtime platform check from frem/drem
1c598c2: 8312428: PKCS11 tests fail with NSS 3.91
b2728cb: 8189685: need PerfMemory class update and a volatile_static_field support in VMStructs
e22762c: 8314932: G1: Fix -Wconversion warnings for simple cases inside g1 folder
762b652: 8314573: G1: Heap resizing at Remark does not take existing eden regions into account
... and 262 more: https://git.openjdk.org/jdk/compare/c1f4595e64b0ea0439c6e7f61a6a92b56b526d97...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.

afshin-zafari · 2023-08-30T11:10:35Z

/integrate

openjdk · 2023-08-30T11:11:46Z

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

cb3f968: 8314651: G1: Fix -Wconversion warnings in static fields of HeapRegion
876a725: 8315206: RISC-V: hwprobe query is_set return wrong value
ed1ea5f: 8314024: SIGSEGV in PhaseIdealLoop::build_loop_late_post_work due to bad immediate dominator info
f3aeb02: 8315213: java/lang/ProcessHandle/TreeTest.java test enhance output of children
1e7e2bc: 8315214: Do not run sun/tools/jhsdb tests concurrently
ce2a7ea: 8314056: Remove runtime platform check from frem/drem
1c598c2: 8312428: PKCS11 tests fail with NSS 3.91
b2728cb: 8189685: need PerfMemory class update and a volatile_static_field support in VMStructs
e22762c: 8314932: G1: Fix -Wconversion warnings for simple cases inside g1 folder
762b652: 8314573: G1: Heap resizing at Remark does not take existing eden regions into account
... and 262 more: https://git.openjdk.org/jdk/compare/c1f4595e64b0ea0439c6e7f61a6a92b56b526d97...master

Your commit was automatically rebased without conflicts.

openjdk · 2023-08-30T11:11:52Z

@afshin-zafari Pushed as commit bf63945.

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

8298992: runtime/NMT/SummarySanityCheck.java failed with "Total commi…

3ebd649

…tted (MMMMMM) did not match the summarized committed (NNNNNN)"

openjdk bot added the hotspot-runtime hotspot-runtime-dev@openjdk.org label Aug 16, 2023

afshin-zafari added 2 commits August 21, 2023 19:04

Extra log_debug are removed.

2f38495

Rmoved a missed log.

a31da2b

gerard-ziemski suggested changes Aug 21, 2023

View reviewed changes

Set a limit for loop, renamed a local var.

09cf707

afshin-zafari marked this pull request as ready for review August 22, 2023 08:59

openjdk bot added the rfr Pull request is ready for review label Aug 22, 2023

tstuefe reviewed Aug 22, 2023

View reviewed changes

gerard-ziemski suggested changes Aug 22, 2023

View reviewed changes

tstuefe approved these changes Aug 23, 2023

View reviewed changes

gerard-ziemski approved these changes Aug 25, 2023

View reviewed changes

move the copy_to function from header to cpp file.

a55e417

tstuefe approved these changes Aug 28, 2023

View reviewed changes

openjdk bot removed the rfr Pull request is ready for review label Aug 30, 2023

openjdk bot added ready Pull request is ready to be integrated rfr Pull request is ready for review labels Aug 30, 2023

openjdk bot added the integrated Pull request has been integrated label Aug 30, 2023

openjdk bot closed this Aug 30, 2023

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

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

8298992: runtime/NMT/SummarySanityCheck.java failed with "Total committed (MMMMMM) did not match the summarized committed (NNNNNN)" #15306

8298992: runtime/NMT/SummarySanityCheck.java failed with "Total committed (MMMMMM) did not match the summarized committed (NNNNNN)" #15306

afshin-zafari commented Aug 16, 2023 •

edited by openjdk bot

Loading

bridgekeeper bot commented Aug 16, 2023

openjdk bot commented Aug 16, 2023

gerard-ziemski Aug 21, 2023 •

edited

Loading

afshin-zafari Aug 22, 2023

gerard-ziemski commented Aug 21, 2023

afshin-zafari commented Aug 22, 2023 •

edited

Loading

mlbridge bot commented Aug 22, 2023 •

edited

Loading

tstuefe Aug 22, 2023

gerard-ziemski Aug 22, 2023 •

edited

Loading

tstuefe Aug 22, 2023

gerard-ziemski Aug 22, 2023

tstuefe Aug 23, 2023

gerard-ziemski Aug 23, 2023

gerard-ziemski Aug 22, 2023

afshin-zafari Aug 23, 2023 •

edited

Loading

gerard-ziemski Aug 23, 2023 •

edited

Loading

jdksjolen commented Aug 23, 2023

afshin-zafari commented Aug 23, 2023

afshin-zafari commented Aug 23, 2023 •

edited

Loading

tstuefe left a comment

gerard-ziemski commented Aug 23, 2023 •

edited

Loading

afshin-zafari commented Aug 25, 2023

gerard-ziemski commented Aug 25, 2023

tstuefe left a comment

afshin-zafari commented Aug 28, 2023

openjdk bot commented Aug 28, 2023

afshin-zafari commented Aug 30, 2023

openjdk bot commented Aug 30, 2023

afshin-zafari commented Aug 30, 2023

openjdk bot commented Aug 30, 2023

openjdk bot commented Aug 30, 2023

afshin-zafari commented Aug 30, 2023

openjdk bot commented Aug 30, 2023

openjdk bot commented Aug 30, 2023

8298992: runtime/NMT/SummarySanityCheck.java failed with "Total committed (MMMMMM) did not match the summarized committed (NNNNNN)" #15306

8298992: runtime/NMT/SummarySanityCheck.java failed with "Total committed (MMMMMM) did not match the summarized committed (NNNNNN)" #15306

Conversation

afshin-zafari commented Aug 16, 2023 • edited by openjdk bot Loading

Progress

Issue

Reviewers

Reviewing

Webrev

bridgekeeper bot commented Aug 16, 2023

openjdk bot commented Aug 16, 2023

gerard-ziemski Aug 21, 2023 • edited Loading

Choose a reason for hiding this comment

afshin-zafari Aug 22, 2023

Choose a reason for hiding this comment

gerard-ziemski commented Aug 21, 2023

afshin-zafari commented Aug 22, 2023 • edited Loading

mlbridge bot commented Aug 22, 2023 • edited Loading

Webrevs

tstuefe Aug 22, 2023

Choose a reason for hiding this comment

gerard-ziemski Aug 22, 2023 • edited Loading

Choose a reason for hiding this comment

tstuefe Aug 22, 2023

Choose a reason for hiding this comment

gerard-ziemski Aug 22, 2023

Choose a reason for hiding this comment

tstuefe Aug 23, 2023

Choose a reason for hiding this comment

gerard-ziemski Aug 23, 2023

Choose a reason for hiding this comment

gerard-ziemski Aug 22, 2023

Choose a reason for hiding this comment

afshin-zafari Aug 23, 2023 • edited Loading

Choose a reason for hiding this comment

gerard-ziemski Aug 23, 2023 • edited Loading

Choose a reason for hiding this comment

jdksjolen commented Aug 23, 2023

afshin-zafari commented Aug 23, 2023

afshin-zafari commented Aug 23, 2023 • edited Loading

tstuefe left a comment

Choose a reason for hiding this comment

gerard-ziemski commented Aug 23, 2023 • edited Loading

afshin-zafari commented Aug 25, 2023

gerard-ziemski commented Aug 25, 2023

tstuefe left a comment

Choose a reason for hiding this comment

afshin-zafari commented Aug 28, 2023

openjdk bot commented Aug 28, 2023

afshin-zafari commented Aug 30, 2023

openjdk bot commented Aug 30, 2023

afshin-zafari commented Aug 30, 2023

openjdk bot commented Aug 30, 2023

openjdk bot commented Aug 30, 2023

afshin-zafari commented Aug 30, 2023

openjdk bot commented Aug 30, 2023

openjdk bot commented Aug 30, 2023

afshin-zafari commented Aug 16, 2023 •

edited by openjdk bot

Loading

gerard-ziemski Aug 21, 2023 •

edited

Loading

afshin-zafari commented Aug 22, 2023 •

edited

Loading

mlbridge bot commented Aug 22, 2023 •

edited

Loading

gerard-ziemski Aug 22, 2023 •

edited

Loading

afshin-zafari Aug 23, 2023 •

edited

Loading

gerard-ziemski Aug 23, 2023 •

edited

Loading

afshin-zafari commented Aug 23, 2023 •

edited

Loading

gerard-ziemski commented Aug 23, 2023 •

edited

Loading