8255011: [TESTBUG] compiler/codecache/stress/UnexpectedDeoptimizationAllTest.java timed out #1030

neliasso · 2020-11-03T08:14:29Z

Hi,

This patch updates the code cache stress tests. I haven't been able to reproduce or retrieve a core file.

What I can see is that the tests provokes compile storms, and that the single C1 thread (on a 4CPU system) sometimes has trouble keeping up. A factor may also be that the tests run time scale with the timeout time - so that the time allotted as margin before the timeout is only 20% of the total runtime. Combining this with Xcomp, and that the test may run concurrently with other stress tests, it is reasonable that a timeout may occur.

I suggest to cap the tests to 60 seconds of testing. I've experimented with meassuring how much work is done and use that as a metric - but the different tests that use the CodeCacheStressRunner has completely different profiles.

In UnexpectedDeoptimizationAllTest.java I have adjusted the sleep time to 100 millis between the invalidations of the entire code cache.

In UnexpectedDeoptimizationTest.java I have added a sleep of 10 miilis between deoptimizing parts of the stack. The idea is to give the stack time to growth a bit before the next deoptimization. Otherwise the test might end up running mostly in the interpreter.

Please review,
Nils Eliasson

Progress

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

Testing

	Linux x64	Linux x86	Windows x64	macOS x64
Build	✔️ (5/5 passed)	✔️ (2/2 passed)	✔️ (2/2 passed)	✔️ (2/2 passed)
Test (tier1)	✔️ (9/9 passed)	❌ (1/9 failed)	✔️ (9/9 passed)	✔️ (9/9 passed)

Failed test task

Linux x86 (hs/tier1 compiler)

Issue

JDK-8255011: [TESTBUG] compiler/codecache/stress/UnexpectedDeoptimizationAllTest.java timed out

Reviewers

Igor Ignatyev (@iignatev - Reviewer)

Download

$ git fetch https://git.openjdk.java.net/jdk pull/1030/head:pull/1030
$ git checkout pull/1030

bridgekeeper · 2020-11-03T08:15:00Z

👋 Welcome back neliasso! 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 · 2020-11-03T08:16:52Z

@neliasso 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 · 2020-11-03T08:22:06Z

Webrevs

neliasso · 2020-11-03T13:33:00Z

/summary compiler/codecache/stress/UnexpectedDeoptimizationAllTest.java timed out

openjdk · 2020-11-03T13:42:39Z

@neliasso Setting summary to compiler/codecache/stress/UnexpectedDeoptimizationAllTest.java timed out

test/hotspot/jtreg/compiler/codecache/stress/CodeCacheStressRunner.java

iignatev · 2020-11-03T22:22:31Z

@lepestock, IIRC, you are/were working on fixing timeouts in some other code cache tests which use compiler/codecache/stress/CodeCacheStressRunner, so I believe this might be of interest to you.

iignatev · 2020-11-03T22:49:50Z

@neliasso ,

could you please explain why in UnexpectedDeoptimizationAllTest you "have adjusted the sleep time to 100 millis between the invalidations of the entire code cache"?

neliasso · 2020-11-04T15:49:22Z

/summary [TESTBUG] UnexpectedDeoptimizationAllTest.java timed out

@neliasso ,

could you please explain why in UnexpectedDeoptimizationAllTest you "have adjusted the sleep time to 100 millis between the invalidations of the entire code cache"?

I was experimenting with different levels of contention. 10 millis + Xcomp gets 30% fewer methods compiled, but in all other cases 10 millis results in more compilations. It's a toss for me.

I reverted since it doesn't really matter.

openjdk · 2020-11-04T15:50:28Z

@neliasso Updating existing summary to:

[TESTBUG] UnexpectedDeoptimizationAllTest.java timed out

> @neliasso ,
>
> could you please explain why in `UnexpectedDeoptimizationAllTest` you "have adjusted the sleep time to 100 millis between the invalidations of the entire code cache"?

I was experimenting with different levels of contention. 10 millis + Xcomp gets 30% fewer methods compiled, but in all other cases 10 millis results in more compilations. It's a toss for me.

I reverted since it doesn't really matter.

lepestock · 2020-11-04T20:00:12Z

@neliasso, could you please explain how those compile storms cause timeouts? As far as I could find, the JVM doesn't wait for the threads to finish, it gives them approx. 10 seconds, and then just exits.

So we only have to make sure that our 20% is larger than 10s + some reasonable margin, right?

neliasso · 2020-11-04T20:53:25Z

@neliasso, could you please explain how those compile storms cause timeouts? As far as I could find, the JVM doesn't wait for the threads to finish, it gives them approx. 10 seconds, and then just exits.

I don't know exactly since 1) I can't reproduce it 2) I didn't get any core or thread dump from the failure.

What I do know is 1) The failure was on a slow platform 2) It was probably running concurrently with other tests 3) It was running with -Xcomp

Using JFR and jcmd I have seen - 1) very long compile queues (> 500 for C1)

I did some measurements on workload too. In normal mode 6500 iterations of CodeCacheStressRunner was performed in 30 sec, with -Xcomp only 250. But in total compiles -Xcomp had 30% less compilations.

What I also do know is that the CodeCache lock will be contended by the compile threads and the test thread that is invalidating everything in the cache. With long compile queues the MethodCompileQueue lock can also become contented because the time held is proportional to the number of compile tasks in the queue. In register_method both locks are held.

So we only have to make sure that our 20% is larger than 10s + some reasonable margin, right?

Yes. I suggest 60 seconds test time and minimum of 60 seconds margin.
I also suggest to not scale the test time with the timeout fraction since the run times becomes excessive. I experimented with keeping the CodeCaceStressRunner iterations constant but the different tests have completely different profiles and the variants are too many. 60 seconds is still a huge amount of compiles and invalidations. (times 2 since all tests are run with and without segmented code cache).

iignatev · 2020-11-04T21:03:35Z

@neliasso ,
could you please explain why in UnexpectedDeoptimizationAllTest you "have adjusted the sleep time to 100 millis between the invalidations of the entire code cache"?

I was experimenting with different levels of contention. 10 millis + Xcomp gets 30% fewer methods compiled, but in all other cases 10 millis results in more compilations. It's a toss for me.

I reverted since it doesn't really matter.

👍 , but could you please add comments to both sleep so the future readers would know why they are there?

iignatev · 2020-11-04T21:08:30Z

... In normal mode 6500 iterations of CodeCacheStressRunner was performed in 30 sec, with -Xcomp only 250. But in total compiles -Xcomp had 30% less compilations...

would it make sense to update CodeCacheStressRunner and/or individual tests to count iterations and have a reasonable (test-specific?) threshold below which a test isn't considered passed, but instead considered skipped (ie throws jtreg.SkippedException). this way we would know if tests run enough iterations in the allocated amount of time, and if they don't in some configuration, we will have data to make proper decision on either increasing time budget, decreasing threshold, or excluding configurations.

-- Igor

neliasso · 2020-11-04T21:56:27Z

... In normal mode 6500 iterations of CodeCacheStressRunner was performed in 30 sec, with -Xcomp only 250. But in total compiles -Xcomp had 30% less compilations...

would it make sense to update CodeCacheStressRunner and/or individual tests to count iterations and have a reasonable (test-specific?) threshold below which a test isn't considered passed, but instead considered skipped (ie throws jtreg.SkippedException). this way we would know if tests run enough iterations in the allocated amount of time, and if they don't in some configuration, we will have data to make proper decision on either increasing time budget, decreasing threshold, or excluding configurations.

-- Igor

I experimented with couting the CodeCaceStressRunner iterations but the different tests have completely different profiles and the variants are many - 4 tests, 2 modes (Xcomp) that all need separate values.

I would like to see that we added thread dumps and core files on timeouts. Then we can experiment with lower timeouts since it will be possible to diagnose them quickly.

iignatev · 2020-11-04T22:48:06Z

would like to see that we added thread dumps and core files on timeouts.

we actually do that since JDK 9, JEP 279 added the failure handler which runs many things including jstack, gdb -ex thread apply all backtrace (or its equivalent) to get java and native thread dumps and kill -ABRT to generate core files on timeouts. however b/c it's run concurrently to a timed out process, you don't always get the data. so I'm wondering what you meant.

-- Igor

neliasso · 2020-11-05T09:39:20Z

we actually do that since JDK 9, JEP 279 added the failure handler which runs many things including jstack, gdb -ex thread apply all backtrace (or its equivalent) to get java and native thread dumps and kill -ABRT to generate core files on timeouts. however b/c it's run concurrently to a timed out process, you don't always get the data. so I'm wondering what you meant.

That has completely passed me by. I must look into it.

Regarding the test:
I think 60 secs is plenty of time for this test, especially since it runs multiple times. If there is a deadlock - the test will timeout regardless of timeout time. Adding some workload measurement would be nice - but not worth the time in my opinion.

iignatev · 2020-11-05T17:41:00Z

Adding some workload measurement would be nice - but not worth the time in my opinion.

sure-sure, I didn't mean to do it as part of this PR, just a thought for future improvements in these tests.

iignatev

LGTM. however I'd like to you to wait for explcit 'ok' from Evgeny (@lepestock) as well.

BTW, you need to either update the title of this PR to [TESTBUG] compiler/codecache/stress/UnexpectedDeoptimizationAllTest.java timed out or change 8255011's title to [TESTBUG] UnexpectedDeoptimizationAllTest.java timed out

-- Igor

lepestock · 2020-11-06T10:14:24Z

LGTM. I was considering similar change as well, so I agree.

openjdk · 2020-11-06T20:36:50Z

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

8255011: [TESTBUG] compiler/codecache/stress/UnexpectedDeoptimizationAllTest.java timed out

Change CodeCacheStressRunner to have a 60 second test time

Reviewed-by: iignatyev

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

0b7fba7: 8254270: linux 32 bit build doesn't compile libjdwp/log_messages.c
f5d36e6: 8246741: NetworkInterface/UniqueMacAddressesTest: mac address uniqueness test failed
688b10b: 8255561: add tests to check binary compatibility rules for records
727a69f: 8255969: Improve java/io/BufferedInputStream/LargeCopyWithMark.java using jtreg tags
952abea: 8254920: Application launched with jpackage produced .exe crashes JVM
5dfb42f: 8255563: Missing NULL checks after JDK-8233624
e730e8b: 8241806: The sun/awt/shell/FileSystemViewMemoryLeak.java is unstable
57b98fa: 8255965: LogCompilation: add sort by nmethod code size
e42c134: 8255706: The JDWP debug agent unecessarily checks for JVMTI_ERROR_INTERRUPT after calling RawMonitorEnter
e66fd6f: 8255756: Disabling logging does unnecessary work
... and 122 more: https://git.openjdk.java.net/jdk/compare/9b1eebc73d74cc33abd6d0f4002a8b20ada9c484...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.

neliasso · 2020-11-06T20:38:36Z

/summary Change CodeCacheStressRunner to have a 60 second test time

openjdk · 2020-11-06T20:39:02Z

@neliasso Updating existing summary to Change CodeCacheStressRunner to have a 60 second test time

neliasso · 2020-11-06T20:40:11Z

Thank you Evgeny and Igor!

neliasso · 2020-11-10T11:25:04Z

/integrate

openjdk · 2020-11-10T11:26:22Z

@neliasso Since your change was applied there have been 157 commits pushed to the master branch:

c601849: 8256038: G1: Improve comment about mark word handling of displaced mark words
a38dd53: 8256040: Shenandoah: Allow NULL referent in ShenandoahReferenceProcessor::should_discover()
01567b5: 8256036: Shenandoah: MethodHandles adapters section overflows after JDK-8255762
4bc065c: 8255782: Turn UseTLAB and ResizeTLAB from product_pd to product, defaulting to "true"
b5d78af: 8254863: Delete code leftover from old fixes
8066b33: 8253905: Update sanity test suite to not place windows at (0,0)
f71f9dc: 8255949: AArch64: Add support for vectorized shift right and accumulate
1332ba3: 8256039: Shenandoah: runtime/stringtable/StringTableCleaningTest.java fails
11431b1: 4619330: All built-in java.awt.color.ColorSpace fields should be specified as such
17f04fc: 8254078: DataOutputStream is very slow post-disabling of Biased Locking
... and 147 more: https://git.openjdk.java.net/jdk/compare/9b1eebc73d74cc33abd6d0f4002a8b20ada9c484...master

Your commit was automatically rebased without conflicts.

Pushed as commit e281b13.

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

…AllTest.java timed out Change CodeCacheStressRunner to have a 60 second test time Reviewed-by: iignatyev

…g to pointer In the cases like: ``` UNSAFE.putLong(address + off1 + 1030, lseed); UNSAFE.putLong(address + 1023, lseed); UNSAFE.putLong(address + off2 + 1001, lseed); ``` Unsafe intrinsifies direct memory access using a long as the base address, generating a `CastX2P` node converting long to pointer in C2. Then we get optoassembly code like: ``` ldr R10, [R15, openjdk#120] # int ! Field: address ldr R11, [R16, openjdk#136] # int ! Field: off1 ldr R12, [R16, openjdk#144] # int ! Field: off2 add R11, R11, R10 mov R11, R11 # long -> ptr add R12, R12, R10 mov R10, R10 # long -> ptr add R11, R11, openjdk#1030 # ptr str R17, [R11] # int add R10, R10, openjdk#1023 # ptr str R17, [R10] # int mov R10, R12 # long -> ptr add R10, R10, openjdk#1001 # ptr str R17, [R10] # int ``` In aarch64, the conversion from long to pointer could be a nop but C2 doesn't know it. On the existing code, we do nothing for `mov dst src` only when `dst` == `src` [1], then we have assembly: ``` ldr x10, [x15,openjdk#120] ldp x11, x12, [x16,openjdk#136] add x11, x11, x10 add x12, x12, x10 add x11, x11, #0x406 str x17, [x11] add x10, x10, #0x3ff str x17, [x10] mov x10, x12 <--- extra register copy add x10, x10, #0x3e9 str x17, [x10] ``` There is still one extra register copy, which we're trying to remove in this patch. This patch folds `CastX2P` into memory operands by introducing `indirectX2P` and `indOffX2P`. We also create a new opclass `iRegPorL2P` to remove extra copies from `CastX2P` in pointer addition. Tier 1~3 passed on aarch64. No obvious change in size of libjvm.so [1] https://github.com/openjdk/jdk/blob/5c612c230b0a852aed5fd36e58b82ebf2e1838af/src/hotspot/cpu/aarch64/aarch64.ad#L7906

8255011: UnexpectedDeoptimizationAllTest.java timed out

cf3ec2c

openjdk bot added the rfr Pull request is ready for review label Nov 3, 2020

openjdk bot added the hotspot-compiler hotspot-compiler-dev@openjdk.org label Nov 3, 2020

neliasso changed the title ~~8255011: UnexpectedDeoptimizationAllTest.java timed out~~ 8255011: [TESTBUG] UnexpectedDeoptimizationAllTest.java timed out Nov 3, 2020

iignatev suggested changes Nov 3, 2020

View reviewed changes

test/hotspot/jtreg/compiler/codecache/stress/CodeCacheStressRunner.java Outdated Show resolved Hide resolved

simplify_timeout

0528503

openjdk bot added the build build-dev@openjdk.org label Nov 4, 2020

removed file

2a4151c

openjdk bot removed the build build-dev@openjdk.org label Nov 4, 2020

changed wait time

5050a2e

add comment

5d72bf9

iignatev approved these changes Nov 5, 2020

View reviewed changes

neliasso changed the title ~~8255011: [TESTBUG] UnexpectedDeoptimizationAllTest.java timed out~~ 8255011: [TESTBUG] compiler/codecache/stress/UnexpectedDeoptimizationAllTest.java timed out Nov 6, 2020

openjdk bot added the ready Pull request is ready to be integrated label Nov 6, 2020

openjdk bot closed this Nov 10, 2020

openjdk bot added integrated Pull request has been integrated and removed ready Pull request is ready to be integrated rfr Pull request is ready for review labels Nov 10, 2020

openjdk-notifier bot referenced this pull request Nov 10, 2020

8255011: [TESTBUG] compiler/codecache/stress/UnexpectedDeoptimization…

e281b13

…AllTest.java timed out Change CodeCacheStressRunner to have a 60 second test time Reviewed-by: iignatyev

neliasso deleted the fix_timeouts branch November 10, 2020 15:37

8255011: [TESTBUG] compiler/codecache/stress/UnexpectedDeoptimizationAllTest.java timed out #1030

8255011: [TESTBUG] compiler/codecache/stress/UnexpectedDeoptimizationAllTest.java timed out #1030

Uh oh!

Conversation

neliasso commented Nov 3, 2020 • edited by openjdk bot Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Progress

Testing

Issue

Reviewers

Download

Uh oh!

bridgekeeper bot commented Nov 3, 2020

Uh oh!

openjdk bot commented Nov 3, 2020

Uh oh!

mlbridge bot commented Nov 3, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Webrevs

Uh oh!

neliasso commented Nov 3, 2020

Uh oh!

openjdk bot commented Nov 3, 2020

Uh oh!

Uh oh!

iignatev commented Nov 3, 2020

Uh oh!

iignatev commented Nov 3, 2020

Uh oh!

neliasso commented Nov 4, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

openjdk bot commented Nov 4, 2020

Uh oh!

lepestock commented Nov 4, 2020

Uh oh!

neliasso commented Nov 4, 2020

Uh oh!

iignatev commented Nov 4, 2020

Uh oh!

iignatev commented Nov 4, 2020

Uh oh!

neliasso commented Nov 4, 2020

Uh oh!

iignatev commented Nov 4, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

neliasso commented Nov 5, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

iignatev commented Nov 5, 2020

Uh oh!

iignatev left a comment

Choose a reason for hiding this comment

Uh oh!

lepestock commented Nov 6, 2020

Uh oh!

openjdk bot commented Nov 6, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

neliasso commented Nov 6, 2020

Uh oh!

openjdk bot commented Nov 6, 2020

Uh oh!

neliasso commented Nov 6, 2020

Uh oh!

neliasso commented Nov 10, 2020

Uh oh!

openjdk bot commented Nov 10, 2020

Uh oh!

Reviewers

Assignees

Labels

Milestone

Development

Uh oh!

3 participants

neliasso commented Nov 3, 2020 •

edited by openjdk bot

Loading

mlbridge bot commented Nov 3, 2020 •

edited

Loading

neliasso commented Nov 4, 2020 •

edited

Loading

iignatev commented Nov 4, 2020 •

edited

Loading

neliasso commented Nov 5, 2020 •

edited

Loading

openjdk bot commented Nov 6, 2020 •

edited

Loading