hprof_monitor.c

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