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 }