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 }