2
|
1 |
/*
|
5506
|
2 |
* Copyright (c) 2003, 2005, Oracle and/or its affiliates. All rights reserved.
|
2
|
3 |
*
|
|
4 |
* Redistribution and use in source and binary forms, with or without
|
|
5 |
* modification, are permitted provided that the following conditions
|
|
6 |
* are met:
|
|
7 |
*
|
|
8 |
* - Redistributions of source code must retain the above copyright
|
|
9 |
* notice, this list of conditions and the following disclaimer.
|
|
10 |
*
|
|
11 |
* - Redistributions in binary form must reproduce the above copyright
|
|
12 |
* notice, this list of conditions and the following disclaimer in the
|
|
13 |
* documentation and/or other materials provided with the distribution.
|
|
14 |
*
|
5506
|
15 |
* - Neither the name of Oracle nor the names of its
|
2
|
16 |
* contributors may be used to endorse or promote products derived
|
|
17 |
* from this software without specific prior written permission.
|
|
18 |
*
|
|
19 |
* THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS
|
|
20 |
* IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO,
|
|
21 |
* THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR
|
|
22 |
* PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT OWNER OR
|
|
23 |
* CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL,
|
|
24 |
* EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO,
|
|
25 |
* PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR
|
|
26 |
* PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF
|
|
27 |
* LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING
|
|
28 |
* NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF THIS
|
|
29 |
* SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
|
|
30 |
*/
|
|
31 |
|
|
32 |
/* Monitor contention tracking and monitor wait handling. */
|
|
33 |
|
|
34 |
/*
|
|
35 |
* Monitor's under contention are unique per trace and signature.
|
|
36 |
* Two monitors with the same trace and signature will be treated
|
|
37 |
* the same as far as accumulated contention time.
|
|
38 |
*
|
|
39 |
* The tls table (or thread table) will be used to store the monitor in
|
|
40 |
* contention or being waited on.
|
|
41 |
*
|
|
42 |
* Monitor wait activity is emitted as it happens.
|
|
43 |
*
|
|
44 |
* Monitor contention is tabulated and summarized at dump time.
|
|
45 |
*
|
|
46 |
*/
|
|
47 |
|
|
48 |
#include "hprof.h"
|
|
49 |
|
|
50 |
typedef struct MonitorKey {
|
|
51 |
TraceIndex trace_index;
|
|
52 |
StringIndex sig_index;
|
|
53 |
} MonitorKey;
|
|
54 |
|
|
55 |
typedef struct MonitorInfo {
|
|
56 |
jint num_hits;
|
|
57 |
jlong contended_time;
|
|
58 |
} MonitorInfo;
|
|
59 |
|
|
60 |
typedef struct IterateInfo {
|
|
61 |
MonitorIndex *monitors;
|
|
62 |
int count;
|
|
63 |
jlong total_contended_time;
|
|
64 |
} IterateInfo;
|
|
65 |
|
|
66 |
/* Private internal functions. */
|
|
67 |
|
|
68 |
static MonitorKey*
|
|
69 |
get_pkey(MonitorIndex index)
|
|
70 |
{
|
|
71 |
void * key_ptr;
|
|
72 |
int key_len;
|
|
73 |
|
|
74 |
table_get_key(gdata->monitor_table, index, &key_ptr, &key_len);
|
|
75 |
HPROF_ASSERT(key_len==sizeof(MonitorKey));
|
|
76 |
HPROF_ASSERT(key_ptr!=NULL);
|
|
77 |
return (MonitorKey*)key_ptr;
|
|
78 |
}
|
|
79 |
|
|
80 |
static MonitorInfo *
|
|
81 |
get_info(MonitorIndex index)
|
|
82 |
{
|
|
83 |
MonitorInfo * info;
|
|
84 |
|
|
85 |
HPROF_ASSERT(index!=0);
|
|
86 |
info = (MonitorInfo*)table_get_info(gdata->monitor_table, index);
|
|
87 |
HPROF_ASSERT(info!=NULL);
|
|
88 |
return info;
|
|
89 |
}
|
|
90 |
|
|
91 |
static MonitorIndex
|
|
92 |
find_or_create_entry(JNIEnv *env, TraceIndex trace_index, jobject object)
|
|
93 |
{
|
|
94 |
static MonitorKey empty_key;
|
|
95 |
MonitorKey key;
|
|
96 |
MonitorIndex index;
|
|
97 |
char *sig;
|
|
98 |
|
|
99 |
HPROF_ASSERT(object!=NULL);
|
|
100 |
WITH_LOCAL_REFS(env, 1) {
|
|
101 |
jclass clazz;
|
|
102 |
|
|
103 |
clazz = getObjectClass(env, object);
|
|
104 |
getClassSignature(clazz, &sig, NULL);
|
|
105 |
} END_WITH_LOCAL_REFS;
|
|
106 |
|
|
107 |
key = empty_key;
|
|
108 |
key.trace_index = trace_index;
|
|
109 |
key.sig_index = string_find_or_create(sig);
|
|
110 |
jvmtiDeallocate(sig);
|
|
111 |
index = table_find_or_create_entry(gdata->monitor_table, &key,
|
|
112 |
(int)sizeof(key), NULL, NULL);
|
|
113 |
return index;
|
|
114 |
}
|
|
115 |
|
|
116 |
static void
|
|
117 |
cleanup_item(MonitorIndex index, void *key_ptr, int key_len, void *info_ptr, void *arg)
|
|
118 |
{
|
|
119 |
}
|
|
120 |
|
|
121 |
static void
|
|
122 |
list_item(TableIndex index, void *key_ptr, int key_len, void *info_ptr, void *arg)
|
|
123 |
{
|
|
124 |
MonitorInfo *info;
|
|
125 |
MonitorKey *pkey;
|
|
126 |
|
|
127 |
HPROF_ASSERT(key_len==sizeof(MonitorKey));
|
|
128 |
HPROF_ASSERT(key_ptr!=NULL);
|
|
129 |
HPROF_ASSERT(info_ptr!=NULL);
|
|
130 |
pkey = (MonitorKey*)key_ptr;
|
|
131 |
info = (MonitorInfo *)info_ptr;
|
|
132 |
debug_message(
|
|
133 |
"Monitor 0x%08x: trace=0x%08x, sig=0x%08x, "
|
|
134 |
"num_hits=%d, contended_time=(%d,%d)\n",
|
|
135 |
index,
|
|
136 |
pkey->trace_index,
|
|
137 |
pkey->sig_index,
|
|
138 |
info->num_hits,
|
|
139 |
jlong_high(info->contended_time),
|
|
140 |
jlong_low(info->contended_time));
|
|
141 |
}
|
|
142 |
|
|
143 |
static void
|
|
144 |
collect_iterator(MonitorIndex index, void *key_ptr, int key_len, void *info_ptr, void *arg)
|
|
145 |
{
|
|
146 |
MonitorInfo *info;
|
|
147 |
IterateInfo *iterate;
|
|
148 |
|
|
149 |
HPROF_ASSERT(key_len==sizeof(MonitorKey));
|
|
150 |
HPROF_ASSERT(info_ptr!=NULL);
|
|
151 |
HPROF_ASSERT(arg!=NULL);
|
|
152 |
iterate = (IterateInfo *)arg;
|
|
153 |
info = (MonitorInfo *)info_ptr;
|
|
154 |
iterate->monitors[iterate->count++] = index;
|
|
155 |
iterate->total_contended_time += info->contended_time;
|
|
156 |
}
|
|
157 |
|
|
158 |
static int
|
|
159 |
qsort_compare(const void *p_monitor1, const void *p_monitor2)
|
|
160 |
{
|
|
161 |
MonitorInfo * info1;
|
|
162 |
MonitorInfo * info2;
|
|
163 |
MonitorIndex monitor1;
|
|
164 |
MonitorIndex monitor2;
|
|
165 |
jlong result;
|
|
166 |
|
|
167 |
HPROF_ASSERT(p_monitor1!=NULL);
|
|
168 |
HPROF_ASSERT(p_monitor2!=NULL);
|
|
169 |
monitor1 = *(MonitorIndex *)p_monitor1;
|
|
170 |
monitor2 = *(MonitorIndex *)p_monitor2;
|
|
171 |
info1 = get_info(monitor1);
|
|
172 |
info2 = get_info(monitor2);
|
|
173 |
|
|
174 |
result = info2->contended_time - info1->contended_time;
|
|
175 |
if (result < (jlong)0) {
|
|
176 |
return -1;
|
|
177 |
} else if ( result > (jlong)0 ) {
|
|
178 |
return 1;
|
|
179 |
}
|
|
180 |
return info2->num_hits - info1->num_hits;
|
|
181 |
}
|
|
182 |
|
|
183 |
static void
|
|
184 |
clear_item(MonitorIndex index, void *key_ptr, int key_len, void *info_ptr, void *arg)
|
|
185 |
{
|
|
186 |
MonitorInfo *info;
|
|
187 |
|
|
188 |
HPROF_ASSERT(key_len==sizeof(MonitorKey));
|
|
189 |
HPROF_ASSERT(info_ptr!=NULL);
|
|
190 |
info = (MonitorInfo *)info_ptr;
|
|
191 |
info->contended_time = 0;
|
|
192 |
}
|
|
193 |
|
|
194 |
static TraceIndex
|
|
195 |
get_trace(TlsIndex tls_index, JNIEnv *env)
|
|
196 |
{
|
|
197 |
TraceIndex trace_index;
|
|
198 |
|
|
199 |
trace_index = tls_get_trace(tls_index, env, gdata->max_trace_depth, JNI_FALSE);
|
|
200 |
return trace_index;
|
|
201 |
}
|
|
202 |
|
|
203 |
/* External functions (called from hprof_init.c) */
|
|
204 |
|
|
205 |
void
|
|
206 |
monitor_init(void)
|
|
207 |
{
|
|
208 |
gdata->monitor_table = table_initialize("Monitor",
|
|
209 |
32, 32, 31, (int)sizeof(MonitorInfo));
|
|
210 |
}
|
|
211 |
|
|
212 |
void
|
|
213 |
monitor_list(void)
|
|
214 |
{
|
|
215 |
debug_message(
|
|
216 |
"------------------- Monitor Table ------------------------\n");
|
|
217 |
table_walk_items(gdata->monitor_table, &list_item, NULL);
|
|
218 |
debug_message(
|
|
219 |
"----------------------------------------------------------\n");
|
|
220 |
}
|
|
221 |
|
|
222 |
void
|
|
223 |
monitor_cleanup(void)
|
|
224 |
{
|
|
225 |
table_cleanup(gdata->monitor_table, &cleanup_item, (void*)NULL);
|
|
226 |
gdata->monitor_table = NULL;
|
|
227 |
}
|
|
228 |
|
|
229 |
void
|
|
230 |
monitor_clear(void)
|
|
231 |
{
|
|
232 |
table_walk_items(gdata->monitor_table, &clear_item, NULL);
|
|
233 |
}
|
|
234 |
|
|
235 |
/* Contended monitor output */
|
|
236 |
void
|
|
237 |
monitor_write_contended_time(JNIEnv *env, double cutoff)
|
|
238 |
{
|
|
239 |
int n_entries;
|
|
240 |
|
|
241 |
n_entries = table_element_count(gdata->monitor_table);
|
|
242 |
if ( n_entries == 0 ) {
|
|
243 |
return;
|
|
244 |
}
|
|
245 |
|
|
246 |
rawMonitorEnter(gdata->data_access_lock); {
|
|
247 |
IterateInfo iterate;
|
|
248 |
int i;
|
|
249 |
int n_items;
|
|
250 |
jlong total_contended_time;
|
|
251 |
|
|
252 |
/* First write all trace we might refer to. */
|
|
253 |
trace_output_unmarked(env);
|
|
254 |
|
|
255 |
/* Looking for an array of monitor index values of interest */
|
|
256 |
iterate.monitors = HPROF_MALLOC(n_entries*(int)sizeof(MonitorIndex));
|
|
257 |
(void)memset(iterate.monitors, 0, n_entries*(int)sizeof(MonitorIndex));
|
|
258 |
|
|
259 |
/* Get a combined total and an array of monitor index numbers */
|
|
260 |
iterate.total_contended_time = 0;
|
|
261 |
iterate.count = 0;
|
|
262 |
table_walk_items(gdata->monitor_table, &collect_iterator, &iterate);
|
|
263 |
|
|
264 |
/* Sort that list */
|
|
265 |
n_entries = iterate.count;
|
|
266 |
if ( n_entries > 0 ) {
|
|
267 |
qsort(iterate.monitors, n_entries, sizeof(MonitorIndex),
|
|
268 |
&qsort_compare);
|
|
269 |
}
|
|
270 |
|
|
271 |
/* Apply the cutoff */
|
|
272 |
n_items = 0;
|
|
273 |
for (i = 0; i < n_entries; i++) {
|
|
274 |
MonitorIndex index;
|
|
275 |
MonitorInfo *info;
|
|
276 |
double percent;
|
|
277 |
|
|
278 |
index = iterate.monitors[i];
|
|
279 |
info = get_info(index);
|
|
280 |
percent = (double)info->contended_time /
|
|
281 |
(double)iterate.total_contended_time;
|
|
282 |
if (percent < cutoff) {
|
|
283 |
break;
|
|
284 |
}
|
|
285 |
iterate.monitors[n_items++] = index;
|
|
286 |
}
|
|
287 |
|
|
288 |
/* Output the items that make sense */
|
|
289 |
total_contended_time = iterate.total_contended_time / 1000000;
|
|
290 |
|
|
291 |
if ( n_items > 0 && total_contended_time > 0 ) {
|
|
292 |
double accum;
|
|
293 |
|
|
294 |
/* Output the info on this monitor enter site */
|
|
295 |
io_write_monitor_header(total_contended_time);
|
|
296 |
|
|
297 |
accum = 0.0;
|
|
298 |
for (i = 0; i < n_items; i++) {
|
|
299 |
MonitorIndex index;
|
|
300 |
MonitorInfo *info;
|
|
301 |
MonitorKey *pkey;
|
|
302 |
double percent;
|
|
303 |
char *sig;
|
|
304 |
|
|
305 |
index = iterate.monitors[i];
|
|
306 |
pkey = get_pkey(index);
|
|
307 |
info = get_info(index);
|
|
308 |
|
|
309 |
sig = string_get(pkey->sig_index);
|
|
310 |
|
|
311 |
percent = (double)info->contended_time /
|
|
312 |
(double)iterate.total_contended_time * 100.0;
|
|
313 |
accum += percent;
|
|
314 |
io_write_monitor_elem(i + 1, percent, accum,
|
|
315 |
info->num_hits,
|
|
316 |
trace_get_serial_number(pkey->trace_index),
|
|
317 |
sig);
|
|
318 |
}
|
|
319 |
io_write_monitor_footer();
|
|
320 |
}
|
|
321 |
HPROF_FREE(iterate.monitors);
|
|
322 |
} rawMonitorExit(gdata->data_access_lock);
|
|
323 |
}
|
|
324 |
|
|
325 |
void
|
|
326 |
monitor_contended_enter_event(JNIEnv *env, jthread thread, jobject object)
|
|
327 |
{
|
|
328 |
TlsIndex tls_index;
|
|
329 |
MonitorIndex index;
|
|
330 |
TraceIndex trace_index;
|
|
331 |
|
|
332 |
HPROF_ASSERT(env!=NULL);
|
|
333 |
HPROF_ASSERT(thread!=NULL);
|
|
334 |
HPROF_ASSERT(object!=NULL);
|
|
335 |
|
|
336 |
tls_index = tls_find_or_create(env, thread);
|
|
337 |
HPROF_ASSERT(tls_get_monitor(tls_index)==0);
|
|
338 |
trace_index = get_trace(tls_index, env);
|
|
339 |
index = find_or_create_entry(env, trace_index, object);
|
|
340 |
tls_monitor_start_timer(tls_index);
|
|
341 |
tls_set_monitor(tls_index, index);
|
|
342 |
}
|
|
343 |
|
|
344 |
void
|
|
345 |
monitor_contended_entered_event(JNIEnv* env, jthread thread, jobject object)
|
|
346 |
{
|
|
347 |
TlsIndex tls_index;
|
|
348 |
MonitorInfo *info;
|
|
349 |
MonitorIndex index;
|
|
350 |
|
|
351 |
HPROF_ASSERT(env!=NULL);
|
|
352 |
HPROF_ASSERT(object!=NULL);
|
|
353 |
HPROF_ASSERT(thread!=NULL);
|
|
354 |
|
|
355 |
tls_index = tls_find_or_create(env, thread);
|
|
356 |
HPROF_ASSERT(tls_index!=0);
|
|
357 |
index = tls_get_monitor(tls_index);
|
|
358 |
HPROF_ASSERT(index!=0);
|
|
359 |
info = get_info(index);
|
|
360 |
info->contended_time += tls_monitor_stop_timer(tls_index);
|
|
361 |
info->num_hits++;
|
|
362 |
tls_set_monitor(tls_index, 0);
|
|
363 |
}
|
|
364 |
|
|
365 |
void
|
|
366 |
monitor_wait_event(JNIEnv *env, jthread thread, jobject object, jlong timeout)
|
|
367 |
{
|
|
368 |
TlsIndex tls_index;
|
|
369 |
MonitorKey *pkey;
|
|
370 |
MonitorIndex index;
|
|
371 |
TraceIndex trace_index;
|
|
372 |
|
|
373 |
HPROF_ASSERT(env!=NULL);
|
|
374 |
HPROF_ASSERT(object!=NULL);
|
|
375 |
HPROF_ASSERT(thread!=NULL);
|
|
376 |
|
|
377 |
tls_index = tls_find_or_create(env, thread);
|
|
378 |
HPROF_ASSERT(tls_index!=0);
|
|
379 |
HPROF_ASSERT(tls_get_monitor(tls_index)==0);
|
|
380 |
trace_index = get_trace(tls_index, env);
|
|
381 |
index = find_or_create_entry(env, trace_index, object);
|
|
382 |
pkey = get_pkey(index);
|
|
383 |
tls_monitor_start_timer(tls_index);
|
|
384 |
tls_set_monitor(tls_index, index);
|
|
385 |
|
|
386 |
rawMonitorEnter(gdata->data_access_lock); {
|
|
387 |
io_write_monitor_wait(string_get(pkey->sig_index), timeout,
|
|
388 |
tls_get_thread_serial_number(tls_index));
|
|
389 |
} rawMonitorExit(gdata->data_access_lock);
|
|
390 |
}
|
|
391 |
|
|
392 |
void
|
|
393 |
monitor_waited_event(JNIEnv *env, jthread thread,
|
|
394 |
jobject object, jboolean timed_out)
|
|
395 |
{
|
|
396 |
TlsIndex tls_index;
|
|
397 |
MonitorIndex index;
|
|
398 |
jlong time_waited;
|
|
399 |
|
|
400 |
tls_index = tls_find_or_create(env, thread);
|
|
401 |
HPROF_ASSERT(tls_index!=0);
|
|
402 |
time_waited = tls_monitor_stop_timer(tls_index);
|
|
403 |
index = tls_get_monitor(tls_index);
|
|
404 |
|
|
405 |
if ( index ==0 ) {
|
|
406 |
/* As best as I can tell, on Solaris X86 (not SPARC) I sometimes
|
|
407 |
* get a "waited" event on a thread that I have never seen before
|
|
408 |
* at all, so how did I get a WAITED event? Perhaps when I
|
|
409 |
* did the VM_INIT handling, a thread I've never seen had already
|
|
410 |
* done the WAIT (which I never saw?), and now I see this thread
|
|
411 |
* for the first time, and also as it finishes it's WAIT?
|
|
412 |
* Only happening on faster processors?
|
|
413 |
*/
|
|
414 |
tls_set_monitor(tls_index, 0);
|
|
415 |
return;
|
|
416 |
}
|
|
417 |
HPROF_ASSERT(index!=0);
|
|
418 |
tls_set_monitor(tls_index, 0);
|
|
419 |
if (object == NULL) {
|
|
420 |
rawMonitorEnter(gdata->data_access_lock); {
|
|
421 |
io_write_monitor_sleep(time_waited,
|
|
422 |
tls_get_thread_serial_number(tls_index));
|
|
423 |
} rawMonitorExit(gdata->data_access_lock);
|
|
424 |
} else {
|
|
425 |
MonitorKey *pkey;
|
|
426 |
|
|
427 |
pkey = get_pkey(index);
|
|
428 |
rawMonitorEnter(gdata->data_access_lock); {
|
|
429 |
io_write_monitor_waited(string_get(pkey->sig_index), time_waited,
|
|
430 |
tls_get_thread_serial_number(tls_index));
|
|
431 |
} rawMonitorExit(gdata->data_access_lock);
|
|
432 |
}
|
|
433 |
}
|