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 }