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