JDK-8267155 : runtime/os/TestTracePageSizes times out
  • Type: Bug
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 17
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2021-05-14
  • Updated: 2021-05-27
  • Resolved: 2021-05-20
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 17
17 b24Fixed
Related Reports
Relates :  
JDK-8267460 - runtime/os/TestTracePageSizes.java#with-Serial fails on linux-aarch64 since JDK-8267155
Relates :  
JDK-8262188 - Add test to verify trace page sizes logging on Linux
Relates :  
JDK-8263236 - runtime/os/TestTracePageSizes.java fails on old kernels
Description
on a number of our Linux test machines, this jtreg test times out after 720 secs. We see this on various architectures, including x64.

Stack:
```
"MainThread" #26 prio=5 os_prio=0 cpu=719540.42ms elapsed=720.16s tid=0x00007f5a032d7b70 nid=0x5994 runnable  [0x00007f59dc149000]
   java.lang.Thread.State: RUNNABLE
Thread: 0x00007f5a032d7b70  [0x5994] State: _at_safepoint _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.util.regex.Pattern$Curly.match1(java.base@17.0.0.1-internal/Pattern.java:4433)
	at java.util.regex.Pattern$Curly.match(java.base@17.0.0.1-internal/Pattern.java:4382)
	at java.util.regex.Pattern$GroupTail.match(java.base@17.0.0.1-internal/Pattern.java:4836)
	at java.util.regex.Pattern$BmpCharPropertyGreedy.match(java.base@17.0.0.1-internal/Pattern.java:4345)
	at java.util.regex.Pattern$GroupHead.match(java.base@17.0.0.1-internal/Pattern.java:4805)
	at java.util.regex.Pattern$BmpCharProperty.match(java.base@17.0.0.1-internal/Pattern.java:3971)
	at java.util.regex.Pattern$GroupTail.match(java.base@17.0.0.1-internal/Pattern.java:4836)
	at java.util.regex.Pattern$BmpCharPropertyGreedy.match(java.base@17.0.0.1-internal/Pattern.java:4345)
	at java.util.regex.Pattern$GroupHead.match(java.base@17.0.0.1-internal/Pattern.java:4805)
	at java.util.regex.Pattern$Start.match(java.base@17.0.0.1-internal/Pattern.java:3624)
	at java.util.regex.Matcher.search(java.base@17.0.0.1-internal/Matcher.java:1728)
	at java.util.regex.Matcher.find(java.base@17.0.0.1-internal/Matcher.java:745)
	at java.util.Scanner$FindSpliterator.nextInBuffer(java.base@17.0.0.1-internal/Scanner.java:2996)
	at java.util.Scanner$FindSpliterator.tryAdvance(java.base@17.0.0.1-internal/Scanner.java:2970)
	at java.util.Spliterator.forEachRemaining(java.base@17.0.0.1-internal/Spliterator.java:326)
	at java.util.stream.ReferencePipeline$Head.forEach(java.base@17.0.0.1-internal/ReferencePipeline.java:762)
	at TestTracePageSizes.parseSmaps(TestTracePageSizes.java:110)
	at TestTracePageSizes.main(TestTracePageSizes.java:165)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@17.0.0.1-internal/Native Method)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@17.0.0.1-internal/NativeMethodAccessorImpl.java:78)
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@17.0.0.1-internal/DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(java.base@17.0.0.1-internal/Method.java:568)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
	at java.lang.Thread.run(java.base@17.0.0.1-internal/Thread.java:831)
```
Comments
Changeset: 726785b8 Author: Thomas Stuefe <stuefe@openjdk.org> Date: 2021-05-20 08:16:36 +0000 URL: https://git.openjdk.java.net/jdk/commit/726785b8d7c18569bddae6a08fa7f61d8d7bd2c4
20-05-2021
ILW = MLM = P4
18-05-2021
That's odd, because on all our machines it seems to pass rather quickly. Can you dump the smaps file somewhere, so we can see if it is somehow special?
17-05-2021
The matching is just plain slow (beside the consistency issue), takes ~12min on our x64 test machines. And no JDK-8263236 does not seem to have anything to do with it.
17-05-2021
One thing I wonder about is the atomicity of /proc. AFAIK the only guarantee of consistency is reading with a single read call. It may make sense to copy the smaps file first, then scanning the copy. Would also make analysis simpler (just by using -retain). Otherwise, I'll look into the delay on our machines.
17-05-2021
What is weird is that on my 3970X each test case passes within tens of seconds, even in slowdebug builds: $ time CONF=linux-x86_64-server-slowdebug make run-test TEST=runtime/os/TestTracePageSizes.java ... real 1m8.662s user 5m50.678s sys 0m7.873s
17-05-2021
Are you saying this started to happen after JDK-8263236 added another character in the match? Or that the pattern matching is expensive either way?
17-05-2021
Right. It seems "VmFlags" were introduced in 3.8: https://github.com/torvalds/linux/commit/834f82e2aa9a8ede94b17b656329f850c1471514
17-05-2021
Okay, "VmFlags" is missing from smaps on older kernels (<3.8). That makes the matching explode. kernel is 3.0.
17-05-2021