hprof_monitor.c

Go to the documentation of this file.

/*
 * @(#)hprof_monitor.c  1.38 10/03/23
 * 
 * Copyright (c) 2006, 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:
 * 
 * -Redistribution of source code must retain the above copyright notice, this
 *  list of conditions and the following disclaimer.
 * 
 * -Redistribution 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 or the names of contributors may 
 * be used to endorse or promote products derived from this software without 
 * specific prior written permission.
 * 
 * This software is provided "AS IS," without a warranty of any kind. ALL 
 * EXPRESS OR IMPLIED CONDITIONS, REPRESENTATIONS AND WARRANTIES, INCLUDING
 * ANY IMPLIED WARRANTY OF MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE
 * OR NON-INFRINGEMENT, ARE HEREBY EXCLUDED. SUN MICROSYSTEMS, INC. ("SUN")
 * AND ITS LICENSORS SHALL NOT BE LIABLE FOR ANY DAMAGES SUFFERED BY LICENSEE
 * AS A RESULT OF USING, MODIFYING OR DISTRIBUTING THIS SOFTWARE OR ITS
 * DERIVATIVES. IN NO EVENT WILL SUN OR ITS LICENSORS BE LIABLE FOR ANY LOST 
 * REVENUE, PROFIT OR DATA, OR FOR DIRECT, INDIRECT, SPECIAL, CONSEQUENTIAL, 
 * INCIDENTAL OR PUNITIVE DAMAGES, HOWEVER CAUSED AND REGARDLESS OF THE THEORY 
 * OF LIABILITY, ARISING OUT OF THE USE OF OR INABILITY TO USE THIS SOFTWARE, 
 * EVEN IF SUN HAS BEEN ADVISED OF THE POSSIBILITY OF SUCH DAMAGES.
 * 
 * You acknowledge that this software is not designed, licensed or intended
 * for use in the design, construction, operation or maintenance of any
 * nuclear facility.
 */

/* 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);
    }
}

---