/* * Copyright (c) 2003, 2011, Oracle and/or its affiliates. All rights reserved. * * Redistribution and use in source and binary forms, with or without * modification, are permitted provided that the following conditions * are met: * * - Redistributions of source code must retain the above copyright * notice, this list of conditions and the following disclaimer. * * - Redistributions in binary form must reproduce the above copyright * notice, this list of conditions and the following disclaimer in the * documentation and/or other materials provided with the distribution. * * - Neither the name of Oracle nor the names of its * contributors may be used to endorse or promote products derived * from this software without specific prior written permission. * * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS * IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, * THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR * PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT OWNER OR * CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, * EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, * PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR * PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF * LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING * NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF THIS * SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. */ /* * This source code is provided to illustrate the usage of a given feature * or technique and has been deliberately simplified. Additional steps * required for a production-quality application, such as security checks, * input validation and proper error handling, might not be present in * this sample code. */ /* Monitor contention tracking and monitor wait handling. */ /* * Monitor's under contention are unique per trace and signature. * Two monitors with the same trace and signature will be treated * the same as far as accumulated contention time. * * The tls table (or thread table) will be used to store the monitor in * contention or being waited on. * * Monitor wait activity is emitted as it happens. * * Monitor contention is tabulated and summarized at dump time. * */ #include "hprof.h" typedef struct MonitorKey { TraceIndex trace_index; StringIndex sig_index; } MonitorKey; typedef struct MonitorInfo { jint num_hits; jlong contended_time; } MonitorInfo; typedef struct IterateInfo { MonitorIndex *monitors; int count; jlong total_contended_time; } IterateInfo; /* Private internal functions. */ static MonitorKey* get_pkey(MonitorIndex index) { void * key_ptr; int key_len; table_get_key(gdata->monitor_table, index, &key_ptr, &key_len); HPROF_ASSERT(key_len==sizeof(MonitorKey)); HPROF_ASSERT(key_ptr!=NULL); return (MonitorKey*)key_ptr; } static MonitorInfo * get_info(MonitorIndex index) { MonitorInfo * info; HPROF_ASSERT(index!=0); info = (MonitorInfo*)table_get_info(gdata->monitor_table, index); HPROF_ASSERT(info!=NULL); return info; } static MonitorIndex find_or_create_entry(JNIEnv *env, TraceIndex trace_index, jobject object) { static MonitorKey empty_key; MonitorKey key; MonitorIndex index; char *sig; HPROF_ASSERT(object!=NULL); WITH_LOCAL_REFS(env, 1) { jclass clazz; clazz = getObjectClass(env, object); getClassSignature(clazz, &sig, NULL); } END_WITH_LOCAL_REFS; key = empty_key; key.trace_index = trace_index; key.sig_index = string_find_or_create(sig); jvmtiDeallocate(sig); index = table_find_or_create_entry(gdata->monitor_table, &key, (int)sizeof(key), NULL, NULL); return index; } static void cleanup_item(MonitorIndex index, void *key_ptr, int key_len, void *info_ptr, void *arg) { } static void list_item(TableIndex index, void *key_ptr, int key_len, void *info_ptr, void *arg) { MonitorInfo *info; MonitorKey *pkey; HPROF_ASSERT(key_len==sizeof(MonitorKey)); HPROF_ASSERT(key_ptr!=NULL); HPROF_ASSERT(info_ptr!=NULL); pkey = (MonitorKey*)key_ptr; info = (MonitorInfo *)info_ptr; debug_message( "Monitor 0x%08x: trace=0x%08x, sig=0x%08x, " "num_hits=%d, contended_time=(%d,%d)\n", index, pkey->trace_index, pkey->sig_index, info->num_hits, jlong_high(info->contended_time), jlong_low(info->contended_time)); } static void collect_iterator(MonitorIndex index, void *key_ptr, int key_len, void *info_ptr, void *arg) { MonitorInfo *info; IterateInfo *iterate; HPROF_ASSERT(key_len==sizeof(MonitorKey)); HPROF_ASSERT(info_ptr!=NULL); HPROF_ASSERT(arg!=NULL); iterate = (IterateInfo *)arg; info = (MonitorInfo *)info_ptr; iterate->monitors[iterate->count++] = index; iterate->total_contended_time += info->contended_time; } static int qsort_compare(const void *p_monitor1, const void *p_monitor2) { MonitorInfo * info1; MonitorInfo * info2; MonitorIndex monitor1; MonitorIndex monitor2; jlong result; HPROF_ASSERT(p_monitor1!=NULL); HPROF_ASSERT(p_monitor2!=NULL); monitor1 = *(MonitorIndex *)p_monitor1; monitor2 = *(MonitorIndex *)p_monitor2; info1 = get_info(monitor1); info2 = get_info(monitor2); result = info2->contended_time - info1->contended_time; if (result < (jlong)0) { return -1; } else if ( result > (jlong)0 ) { return 1; } return info2->num_hits - info1->num_hits; } static void clear_item(MonitorIndex index, void *key_ptr, int key_len, void *info_ptr, void *arg) { MonitorInfo *info; HPROF_ASSERT(key_len==sizeof(MonitorKey)); HPROF_ASSERT(info_ptr!=NULL); info = (MonitorInfo *)info_ptr; info->contended_time = 0; } static TraceIndex get_trace(TlsIndex tls_index, JNIEnv *env) { TraceIndex trace_index; trace_index = tls_get_trace(tls_index, env, gdata->max_trace_depth, JNI_FALSE); return trace_index; } /* External functions (called from hprof_init.c) */ void monitor_init(void) { gdata->monitor_table = table_initialize("Monitor", 32, 32, 31, (int)sizeof(MonitorInfo)); } void monitor_list(void) { debug_message( "------------------- Monitor Table ------------------------\n"); table_walk_items(gdata->monitor_table, &list_item, NULL); debug_message( "----------------------------------------------------------\n"); } void monitor_cleanup(void) { table_cleanup(gdata->monitor_table, &cleanup_item, (void*)NULL); gdata->monitor_table = NULL; } void monitor_clear(void) { table_walk_items(gdata->monitor_table, &clear_item, NULL); } /* Contended monitor output */ void monitor_write_contended_time(JNIEnv *env, double cutoff) { int n_entries; n_entries = table_element_count(gdata->monitor_table); if ( n_entries == 0 ) { return; } rawMonitorEnter(gdata->data_access_lock); { IterateInfo iterate; int i; int n_items; jlong total_contended_time; /* First write all trace we might refer to. */ trace_output_unmarked(env); /* Looking for an array of monitor index values of interest */ iterate.monitors = HPROF_MALLOC(n_entries*(int)sizeof(MonitorIndex)); (void)memset(iterate.monitors, 0, n_entries*(int)sizeof(MonitorIndex)); /* Get a combined total and an array of monitor index numbers */ iterate.total_contended_time = 0; iterate.count = 0; table_walk_items(gdata->monitor_table, &collect_iterator, &iterate); /* Sort that list */ n_entries = iterate.count; if ( n_entries > 0 ) { qsort(iterate.monitors, n_entries, sizeof(MonitorIndex), &qsort_compare); } /* Apply the cutoff */ n_items = 0; for (i = 0; i < n_entries; i++) { MonitorIndex index; MonitorInfo *info; double percent; index = iterate.monitors[i]; info = get_info(index); percent = (double)info->contended_time / (double)iterate.total_contended_time; if (percent < cutoff) { break; } iterate.monitors[n_items++] = index; } /* Output the items that make sense */ total_contended_time = iterate.total_contended_time / 1000000; if ( n_items > 0 && total_contended_time > 0 ) { double accum; /* Output the info on this monitor enter site */ io_write_monitor_header(total_contended_time); accum = 0.0; for (i = 0; i < n_items; i++) { MonitorIndex index; MonitorInfo *info; MonitorKey *pkey; double percent; char *sig; index = iterate.monitors[i]; pkey = get_pkey(index); info = get_info(index); sig = string_get(pkey->sig_index); percent = (double)info->contended_time / (double)iterate.total_contended_time * 100.0; accum += percent; io_write_monitor_elem(i + 1, percent, accum, info->num_hits, trace_get_serial_number(pkey->trace_index), sig); } io_write_monitor_footer(); } HPROF_FREE(iterate.monitors); } rawMonitorExit(gdata->data_access_lock); } void monitor_contended_enter_event(JNIEnv *env, jthread thread, jobject object) { TlsIndex tls_index; MonitorIndex index; TraceIndex trace_index; HPROF_ASSERT(env!=NULL); HPROF_ASSERT(thread!=NULL); HPROF_ASSERT(object!=NULL); tls_index = tls_find_or_create(env, thread); HPROF_ASSERT(tls_get_monitor(tls_index)==0); trace_index = get_trace(tls_index, env); index = find_or_create_entry(env, trace_index, object); tls_monitor_start_timer(tls_index); tls_set_monitor(tls_index, index); } void monitor_contended_entered_event(JNIEnv* env, jthread thread, jobject object) { TlsIndex tls_index; MonitorInfo *info; MonitorIndex index; HPROF_ASSERT(env!=NULL); HPROF_ASSERT(object!=NULL); HPROF_ASSERT(thread!=NULL); tls_index = tls_find_or_create(env, thread); HPROF_ASSERT(tls_index!=0); index = tls_get_monitor(tls_index); HPROF_ASSERT(index!=0); info = get_info(index); info->contended_time += tls_monitor_stop_timer(tls_index); info->num_hits++; tls_set_monitor(tls_index, 0); } void monitor_wait_event(JNIEnv *env, jthread thread, jobject object, jlong timeout) { TlsIndex tls_index; MonitorKey *pkey; MonitorIndex index; TraceIndex trace_index; HPROF_ASSERT(env!=NULL); HPROF_ASSERT(object!=NULL); HPROF_ASSERT(thread!=NULL); tls_index = tls_find_or_create(env, thread); HPROF_ASSERT(tls_index!=0); HPROF_ASSERT(tls_get_monitor(tls_index)==0); trace_index = get_trace(tls_index, env); index = find_or_create_entry(env, trace_index, object); pkey = get_pkey(index); tls_monitor_start_timer(tls_index); tls_set_monitor(tls_index, index); rawMonitorEnter(gdata->data_access_lock); { io_write_monitor_wait(string_get(pkey->sig_index), timeout, tls_get_thread_serial_number(tls_index)); } rawMonitorExit(gdata->data_access_lock); } void monitor_waited_event(JNIEnv *env, jthread thread, jobject object, jboolean timed_out) { TlsIndex tls_index; MonitorIndex index; jlong time_waited; tls_index = tls_find_or_create(env, thread); HPROF_ASSERT(tls_index!=0); time_waited = tls_monitor_stop_timer(tls_index); index = tls_get_monitor(tls_index); if ( index ==0 ) { /* As best as I can tell, on Solaris X86 (not SPARC) I sometimes * get a "waited" event on a thread that I have never seen before * at all, so how did I get a WAITED event? Perhaps when I * did the VM_INIT handling, a thread I've never seen had already * done the WAIT (which I never saw?), and now I see this thread * for the first time, and also as it finishes it's WAIT? * Only happening on faster processors? */ tls_set_monitor(tls_index, 0); return; } HPROF_ASSERT(index!=0); tls_set_monitor(tls_index, 0); if (object == NULL) { rawMonitorEnter(gdata->data_access_lock); { io_write_monitor_sleep(time_waited, tls_get_thread_serial_number(tls_index)); } rawMonitorExit(gdata->data_access_lock); } else { MonitorKey *pkey; pkey = get_pkey(index); rawMonitorEnter(gdata->data_access_lock); { io_write_monitor_waited(string_get(pkey->sig_index), time_waited, tls_get_thread_serial_number(tls_index)); } rawMonitorExit(gdata->data_access_lock); } }