author | goetz |
Fri, 20 Jul 2018 09:46:57 +0200 | |
changeset 51214 | 67736b4846a0 |
parent 50694 | 17d6de3b25fc |
child 59021 | cfc7bb9a5a92 |
permissions | -rw-r--r-- |
50113 | 1 |
/* |
2 |
* Copyright (c) 2017, 2018, Oracle and/or its affiliates. All rights reserved. |
|
3 |
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. |
|
4 |
* |
|
5 |
* This code is free software; you can redistribute it and/or modify it |
|
6 |
* under the terms of the GNU General Public License version 2 only, as |
|
7 |
* published by the Free Software Foundation. Oracle designates this |
|
8 |
* particular file as subject to the "Classpath" exception as provided |
|
9 |
* by Oracle in the LICENSE file that accompanied this code. |
|
10 |
* |
|
11 |
* This code is distributed in the hope that it will be useful, but WITHOUT |
|
12 |
* ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or |
|
13 |
* FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License |
|
14 |
* version 2 for more details (a copy is included in the LICENSE file that |
|
15 |
* accompanied this code). |
|
16 |
* |
|
17 |
* You should have received a copy of the GNU General Public License version |
|
18 |
* 2 along with this work; if not, write to the Free Software Foundation, |
|
19 |
* Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. |
|
20 |
* |
|
21 |
* Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA |
|
22 |
* or visit www.oracle.com if you need additional information or have any |
|
23 |
* questions. |
|
24 |
*/ |
|
25 |
||
26 |
package jdk.jfr.event.runtime; |
|
27 |
||
28 |
import com.sun.management.ThreadMXBean; |
|
29 |
import jdk.jfr.Recording; |
|
30 |
import jdk.jfr.consumer.RecordedEvent; |
|
31 |
import jdk.jfr.consumer.RecordedThread; |
|
32 |
import jdk.test.lib.Asserts; |
|
33 |
import jdk.test.lib.jfr.EventNames; |
|
34 |
import jdk.test.lib.jfr.Events; |
|
35 |
||
36 |
import java.lang.management.ManagementFactory; |
|
37 |
import java.time.Duration; |
|
38 |
import java.time.Instant; |
|
39 |
import java.util.Comparator; |
|
40 |
import java.util.Iterator; |
|
41 |
import java.util.List; |
|
42 |
import java.util.concurrent.BrokenBarrierException; |
|
43 |
import java.util.concurrent.CyclicBarrier; |
|
44 |
import java.util.stream.Collectors; |
|
45 |
||
51214 | 46 |
/** |
50113 | 47 |
* @test |
48 |
* @key jfr |
|
51214 | 49 |
* @requires vm.hasJFR |
50113 | 50 |
* @library /test/lib |
51 |
* @modules jdk.jfr |
|
52 |
* jdk.management |
|
53 |
* |
|
54 |
* @run main/othervm jdk.jfr.event.runtime.TestThreadCpuTimeEvent |
|
55 |
*/ |
|
56 |
||
57 |
/** |
|
58 |
*/ |
|
59 |
public class TestThreadCpuTimeEvent { |
|
60 |
||
61 |
public static void main(String[] args) throws Throwable { |
|
62 |
testSimple(); |
|
63 |
testCompareWithMXBean(); |
|
64 |
testEventAtThreadExit(); |
|
65 |
} |
|
66 |
||
67 |
private static final long eventPeriodMillis = 50; |
|
68 |
private static final String cpuConsumerThreadName = "cpuConsumer"; |
|
69 |
||
70 |
// The cpu consumer will run for eventPeriodMillis times this factor to ensure that we see some |
|
71 |
// events even if the scheduler isn't cooperating. |
|
72 |
private static final long cpuConsumerRunFactor = 10; |
|
73 |
||
74 |
// The cpu consumer will run at least this number of loops, even if it takes longer than |
|
75 |
// the requested period of time (in case the thread didn't get scheduled within the allotted time). |
|
76 |
private static final long cpuConsumerMinCount = 1000000; |
|
77 |
||
78 |
static class CpuConsumingThread extends Thread { |
|
79 |
||
80 |
Duration runTime; |
|
81 |
CyclicBarrier barrier; |
|
82 |
volatile long counter; |
|
83 |
||
84 |
CpuConsumingThread(Duration runTime, CyclicBarrier barrier, String threadName) { |
|
85 |
super(threadName); |
|
86 |
this.runTime = runTime; |
|
87 |
this.barrier = barrier; |
|
88 |
} |
|
89 |
||
90 |
CpuConsumingThread(Duration runTime, CyclicBarrier barrier) { |
|
91 |
this(runTime, barrier, cpuConsumerThreadName); |
|
92 |
} |
|
93 |
||
94 |
@Override |
|
95 |
public void run() { |
|
96 |
try { |
|
97 |
while (true) { |
|
98 |
barrier.await(); |
|
99 |
Instant start = Instant.now(); |
|
100 |
counter = 0; |
|
101 |
while ((Duration.between(start, Instant.now()).compareTo(runTime) < 0) || |
|
102 |
(counter < cpuConsumerMinCount)) { |
|
103 |
counter++; |
|
104 |
} |
|
105 |
barrier.await(); |
|
106 |
} |
|
107 |
} catch (BrokenBarrierException e) { |
|
108 |
// Another thread has been interrupted - wait for us to be interrupted as well |
|
109 |
while (!interrupted()) { |
|
110 |
yield(); |
|
111 |
} |
|
112 |
} catch (InterruptedException e) { |
|
113 |
// Normal way of stopping the thread |
|
114 |
} |
|
115 |
} |
|
116 |
} |
|
117 |
||
118 |
// For a given thread, check that accumulated processTime >= cpuTime >= userTime. |
|
119 |
// This may not hold for a single event instance due to differences in counter resolution |
|
120 |
static void verifyPerThreadInvariant(List<RecordedEvent> events, String threadName) { |
|
121 |
List<RecordedEvent> filteredEvents = events.stream() |
|
122 |
.filter(e -> e.getThread().getJavaName().equals(threadName)) |
|
123 |
.sorted(Comparator.comparing(RecordedEvent::getStartTime)) |
|
124 |
.collect(Collectors.toList()); |
|
125 |
||
126 |
int numCpus = Runtime.getRuntime().availableProcessors(); |
|
127 |
Iterator<RecordedEvent> i = filteredEvents.iterator(); |
|
128 |
while (i.hasNext()) { |
|
129 |
RecordedEvent event = i.next(); |
|
130 |
||
131 |
Float systemLoad = (Float)event.getValue("system"); |
|
132 |
Float userLoad = (Float)event.getValue("user"); |
|
133 |
||
134 |
Asserts.assertLessThan(systemLoad + userLoad, 1.01f / numCpus); // 100% + rounding errors |
|
135 |
} |
|
136 |
} |
|
137 |
||
138 |
static Duration getAccumulatedTime(List<RecordedEvent> events, String threadName, String fieldName) { |
|
139 |
List<RecordedEvent> filteredEvents = events.stream() |
|
140 |
.filter(e -> e.getThread().getJavaName().equals(threadName)) |
|
141 |
.sorted(Comparator.comparing(RecordedEvent::getStartTime)) |
|
142 |
.collect(Collectors.toList()); |
|
143 |
||
144 |
int numCpus = Runtime.getRuntime().availableProcessors(); |
|
145 |
Iterator<RecordedEvent> i = filteredEvents.iterator(); |
|
146 |
RecordedEvent cur = i.next(); |
|
147 |
Duration totalTime = Duration.ZERO; |
|
148 |
while (i.hasNext()) { |
|
149 |
RecordedEvent prev = cur; |
|
150 |
cur = i.next(); |
|
151 |
||
152 |
Duration sampleTime = Duration.between(prev.getStartTime(), cur.getStartTime()); |
|
153 |
Float load = (Float)cur.getValue(fieldName); |
|
154 |
||
155 |
// Adjust load to be thread-relative (fully loaded thread would give 100%) |
|
156 |
Float totalLoadForThread = load * numCpus; |
|
157 |
Duration threadTime = Duration.ofMillis((long) (sampleTime.toMillis() * totalLoadForThread)); |
|
158 |
totalTime = totalTime.plus(threadTime); |
|
159 |
} |
|
160 |
||
161 |
return totalTime; |
|
162 |
} |
|
163 |
||
50694
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
164 |
static List<RecordedEvent> generateEvents(int minimumEventCount, CyclicBarrier barrier) throws Throwable { |
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
165 |
int retryCount = 0; |
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
166 |
|
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
167 |
while (true) { |
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
168 |
Recording recording = new Recording(); |
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
169 |
|
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
170 |
// Default period is once per chunk |
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
171 |
recording.enable(EventNames.ThreadCPULoad).withPeriod(Duration.ofMillis(eventPeriodMillis)); |
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
172 |
recording.start(); |
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
173 |
|
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
174 |
// Run a single pass |
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
175 |
barrier.await(); |
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
176 |
barrier.await(); |
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
177 |
|
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
178 |
recording.stop(); |
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
179 |
List<RecordedEvent> events = Events.fromRecording(recording); |
50113 | 180 |
|
50694
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
181 |
long numEvents = events.stream() |
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
182 |
.filter(e -> e.getThread().getJavaName().equals(cpuConsumerThreadName)) |
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
183 |
.count(); |
50113 | 184 |
|
50694
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
185 |
// If the JFR periodicals thread is really starved, we may not get enough events. |
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
186 |
// In that case, we simply retry the operation. |
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
187 |
if (numEvents < minimumEventCount) { |
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
188 |
System.out.println("Not enough events recorded, trying again..."); |
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
189 |
if (retryCount++ > 10) { |
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
190 |
Asserts.fail("Retry count exceeded"); |
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
191 |
throw new RuntimeException(); |
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
192 |
} |
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
193 |
} else { |
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
194 |
return events; |
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
195 |
} |
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
196 |
} |
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
197 |
} |
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
198 |
|
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
199 |
static void testSimple() throws Throwable { |
50113 | 200 |
Duration testRunTime = Duration.ofMillis(eventPeriodMillis * cpuConsumerRunFactor); |
201 |
CyclicBarrier barrier = new CyclicBarrier(2); |
|
202 |
CpuConsumingThread thread = new CpuConsumingThread(testRunTime, barrier); |
|
50694
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
203 |
thread.start(); |
50113 | 204 |
|
50694
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
205 |
List<RecordedEvent> events = generateEvents(1, barrier); |
50113 | 206 |
verifyPerThreadInvariant(events, cpuConsumerThreadName); |
207 |
||
208 |
thread.interrupt(); |
|
209 |
thread.join(); |
|
210 |
} |
|
211 |
||
212 |
static void testCompareWithMXBean() throws Throwable { |
|
213 |
Duration testRunTime = Duration.ofMillis(eventPeriodMillis * cpuConsumerRunFactor); |
|
214 |
CyclicBarrier barrier = new CyclicBarrier(2); |
|
215 |
CpuConsumingThread thread = new CpuConsumingThread(testRunTime, barrier); |
|
50694
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
216 |
thread.start(); |
50113 | 217 |
|
50694
17d6de3b25fc
8205103: [TESTBUG] Instability in JFR test TestThreadCpuTimeEvent
rwestberg
parents:
50113
diff
changeset
|
218 |
List<RecordedEvent> beforeEvents = generateEvents(2, barrier); |
50113 | 219 |
verifyPerThreadInvariant(beforeEvents, cpuConsumerThreadName); |
220 |
||
221 |
// Run a second single pass |
|
222 |
barrier.await(); |
|
223 |
barrier.await(); |
|
224 |
||
225 |
ThreadMXBean bean = (ThreadMXBean) ManagementFactory.getThreadMXBean(); |
|
226 |
Duration cpuTime = Duration.ofNanos(bean.getThreadCpuTime(thread.getId())); |
|
227 |
Duration userTime = Duration.ofNanos(bean.getThreadUserTime(thread.getId())); |
|
228 |
||
229 |
// Check something that should hold even in the presence of unfortunate scheduling |
|
230 |
Asserts.assertGreaterThanOrEqual(cpuTime.toMillis(), eventPeriodMillis); |
|
231 |
Asserts.assertGreaterThanOrEqual(userTime.toMillis(), eventPeriodMillis); |
|
232 |
||
233 |
Duration systemTimeBefore = getAccumulatedTime(beforeEvents, cpuConsumerThreadName, "system"); |
|
234 |
Duration userTimeBefore = getAccumulatedTime(beforeEvents, cpuConsumerThreadName, "user"); |
|
235 |
Duration cpuTimeBefore = userTimeBefore.plus(systemTimeBefore); |
|
236 |
||
237 |
Asserts.assertLessThan(cpuTimeBefore, cpuTime); |
|
238 |
Asserts.assertLessThan(userTimeBefore, userTime); |
|
239 |
Asserts.assertGreaterThan(cpuTimeBefore, Duration.ZERO); |
|
240 |
||
241 |
thread.interrupt(); |
|
242 |
thread.join(); |
|
243 |
} |
|
244 |
||
245 |
static void testEventAtThreadExit() throws Throwable { |
|
246 |
Recording recording = new Recording(); |
|
247 |
||
248 |
recording.enable(EventNames.ThreadCPULoad).withPeriod(Duration.ofHours(10)); |
|
249 |
recording.start(); |
|
250 |
||
251 |
Duration testRunTime = Duration.ofMillis(eventPeriodMillis * cpuConsumerRunFactor); |
|
252 |
CyclicBarrier barrier = new CyclicBarrier(2); |
|
253 |
CpuConsumingThread thread = new CpuConsumingThread(testRunTime, barrier); |
|
254 |
||
255 |
// Run a single pass |
|
256 |
thread.start(); |
|
257 |
barrier.await(); |
|
258 |
barrier.await(); |
|
259 |
||
260 |
thread.interrupt(); |
|
261 |
thread.join(); |
|
262 |
||
263 |
recording.stop(); |
|
264 |
||
265 |
List<RecordedEvent> events = Events.fromRecording(recording); |
|
266 |
verifyPerThreadInvariant(events, cpuConsumerThreadName); |
|
267 |
||
268 |
int exitingCount = 0; |
|
269 |
for (RecordedEvent event : events) { |
|
270 |
RecordedThread eventThread = event.getThread(); |
|
271 |
if (eventThread.getJavaName().equals(cpuConsumerThreadName)) { |
|
272 |
exitingCount++; |
|
273 |
} |
|
274 |
} |
|
275 |
Asserts.assertEquals(exitingCount, 1); |
|
276 |
} |
|
277 |
} |