/* * Copyright (c) 2014, 2015, Dynatrace and/or its affiliates. All rights reserved. * * This file is part of the Lock Contention Tracing Subsystem for the HotSpot * Virtual Machine, which is developed at Christian Doppler Laboratory on * Monitoring and Evolution of Very-Large-Scale Software Systems. Please * contact us at if you need additional information * or have any questions. * * This code is free software; you can redistribute it and/or modify it * under the terms of the GNU General Public License version 2 only, as * published by the Free Software Foundation. * * This code is distributed in the hope that it will be useful, but WITHOUT * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License * version 2 for more details (a copy is included in the LICENSE file that * accompanied this code). * * You should have received a copy of the GNU General Public License version * 2 along with this work. If not, see . * */ #include "evtrace/traceEvents.hpp" #include "evtrace/traceWriter.hpp" #include "evtrace/traceManager.hpp" #include "evtrace/traceMetadata.hpp" #include "runtime/vframe.hpp" void TraceEvents::initialize() { assert(_event_max <= UINT8_MAX, "event type does not fit"); assert(_park_return_code_max <= UINT8_MAX, "park return code does not fit"); assert(_safepoint_reason_max <= UINT8_MAX, "safepoint reason does not fit"); assert(_monitor_enter_wait_max <= UINT8_MAX, "monitor wait code does not fit"); assert(_monitor_entered_flags_max <= UINT8_MAX, "monitor entered flags do not fit"); } inline bool TraceEvents::can_write() { return TraceManager::is_initialized(); } inline TraceTypes::timestamp TraceEvents::time_now() { return TraceManager::metadata()->time_now(); } inline TraceTypes::thread_id TraceEvents::thread_id_for(Thread* t) { return TraceManager::metadata()->thread_id(t); } inline TraceTypes::object_id TraceEvents::object_id_for(oop obj) { return TraceManager::metadata()->object_id(obj); } inline TraceTypes::objmonitor_id TraceEvents::objmonitor_id_for(ObjectMonitor* om) { return TraceManager::metadata()->objmonitor_id(om); } inline TraceTypes::object_id TraceEvents::objmonitor_object_id_for(ObjectMonitor* om) { return TraceManager::metadata()->objmonitor_object_id(om); } inline TraceTypes::classloader_id TraceEvents::classloader_id_for(ClassLoaderData* cld) { return TraceManager::metadata()->classloader_id(cld); } inline TraceTypes::method_id TraceEvents::method_id_for(Method* m) { bool added; method_id mid = TraceManager::metadata()->method_id(m, added); assert(!added, "must have been known"); return mid; } void TraceEvents::write_thread_start() { if (!can_write()) return; Thread *t = Thread::current(); assert(t != NULL, "thread not attached"); ResourceMark rm; const char *name = NULL; if (t->is_Java_thread()) { name = ((JavaThread *) t)->get_thread_name(); } else if (t->is_Named_thread()) { name = ((NamedThread *) t)->name(); } const size_t name_nbytes = TraceWriter::nbytes_for_utf8str(name, 64); TraceWriter wr(sizeof(event_type) + sizeof(timestamp) + name_nbytes); wr.put_event_type(event_thread_start); wr.put_timestamp(time_now()); wr.put_utf8str(name, name_nbytes); } void TraceEvents::write_thread_name_change(Thread *t) { assert(t != NULL, "null thread"); if (!can_write()) return; ResourceMark rm; const char *name = NULL; if (t->is_Java_thread()) { name = ((JavaThread *) t)->get_thread_name(); } const size_t name_nbytes = TraceWriter::nbytes_for_utf8str(name, 64); TraceWriter wr(sizeof(event_type) + sizeof(timestamp) + sizeof(thread_id) + name_nbytes); wr.put_event_type(event_thread_name_change); wr.put_timestamp(time_now()); wr.put_thread_id(thread_id_for(t)); wr.put_utf8str(name, name_nbytes); } void TraceEvents::write_thread_state_change(Thread *t) { assert(t != NULL, "null thread"); if (!can_write()) return; TraceWriter wr(sizeof(event_type) + sizeof(timestamp) + sizeof(thread_id) + sizeof(thread_state)); wr.put_event_type(event_thread_state_change); wr.put_timestamp(time_now()); wr.put_thread_id(thread_id_for(t)); wr.put_thread_state(TraceManager::metadata()->thread_state(t)); } void TraceEvents::write_thread_interrupt(Thread *t) { assert(t != NULL, "null thread"); if (!can_write()) return; TraceWriter wr(sizeof(event_type) + sizeof(timestamp) + sizeof(seq_num) + sizeof(thread_id)); wr.put_event_type(event_thread_interrupt); wr.put_timestamp(time_now()); wr.put_seq_num(TraceManager::metadata()->next_global_seq()); wr.put_thread_id(thread_id_for(t)); } void TraceEvents::write_thread_exit() { if (!can_write()) return; TraceWriter wr(sizeof(event_type) + sizeof(timestamp)); wr.put_event_type(event_thread_exit); wr.put_timestamp(time_now()); } void TraceEvents::write_thread_park_begin(JavaThread *t, bool is_absolute, timestamp park_time) { assert(t != NULL, "null thread"); if (!can_write()) return; Klass* klass = NULL; object_id oid = 0; { oop blocker = t->current_park_blocker(); if (blocker != NULL) { klass = blocker->klass(); oid = object_id_for(blocker); assert(oid != 0, "just checking"); } } // blocker oop may not be valid anymore after object_id_for() // recheck necessary, because object_id_for can cause a safepoint check if (!can_write()) return; class_id cid = 0; if (klass != NULL) { cid = retrieve_class_id_or_write_metadata(klass); assert(cid != 0, "just checking"); } assert(t->has_last_Java_frame(), "must have"); stack_id stid = retrieve_stack_id_or_write_metadata(t); int nesting_level = t->nesting_level(); if (nesting_level > UINT8_MAX) { nesting_level = UINT8_MAX; } No_Safepoint_Verifier nsv(true, false); seq_num seq = TraceManager::metadata()->next_global_seq(); t->set_park_last_global_seq(seq); TraceWriter wr(sizeof(event_type) + sizeof(timestamp) + sizeof(seq_num) + sizeof(object_id) + sizeof(class_id) + sizeof(stack_id) + sizeof(u1) + sizeof(u1) + sizeof(timestamp)); wr.put_event_type(event_thread_park_begin); wr.put_timestamp(time_now()); wr.put_seq_num(seq); wr.put_object_id(oid); wr.put_class_id(cid); wr.put_stack_id(stid); wr.put_u1(nesting_level); wr.put_u1(is_absolute); wr.put_timestamp(park_time); } void TraceEvents::write_thread_park_end(Thread *t, seq_num seq, seq_num unpark_seq, park_return_code return_code) { assert(t != NULL, "null thread"); assert(return_code > _park_return_code_min && return_code < _park_return_code_max, "invalid return_code"); if (!can_write()) return; TraceWriter wr(sizeof(event_type) + sizeof(timestamp) + sizeof(seq_num) + sizeof(seq_num) + sizeof(u1)); wr.put_event_type(event_thread_park_end); wr.put_timestamp(time_now()); wr.put_seq_num(seq); wr.put_seq_num(unpark_seq); wr.put_u1(return_code); } void TraceEvents::write_thread_unpark(thread_id thread, seq_num seq, seq_num chained_seq) { if (!can_write()) return; stack_id stid = 0; Thread *t = Thread::current(); if (t->is_Java_thread()) { JavaThread *jt = (JavaThread*) t; assert(jt->has_last_Java_frame(), "must have"); stid = retrieve_stack_id_or_write_metadata(jt); } TraceWriter wr(sizeof(event_type) + sizeof(timestamp) + sizeof(seq_num) + sizeof(seq_num) + sizeof(thread_id) + sizeof(stack_id)); wr.put_event_type(event_thread_unpark); wr.put_timestamp(time_now()); wr.put_seq_num(seq); wr.put_seq_num(chained_seq); wr.put_thread_id(thread); wr.put_stack_id(stid); } void TraceEvents::write_monitor_inflate(ObjectMonitor* m, seq_num seq) { if (!can_write()) return; class_id cid = retrieve_class_id_or_write_metadata(((oop)m->object())->klass()); TraceWriter wr(sizeof(event_type) + sizeof(timestamp) + sizeof(seq_num) + sizeof(objmonitor_id) + sizeof(object_id) + sizeof(class_id)); wr.put_event_type(event_monitor_inflate); wr.put_timestamp(time_now()); wr.put_seq_num(seq); wr.put_objmonitor_id(objmonitor_id_for(m)); wr.put_object_id(objmonitor_object_id_for(m)); wr.put_class_id(cid); } void TraceEvents::write_monitor_deflate(ObjectMonitor* m) { if (!can_write()) return; TraceWriter wr(sizeof(event_type) + sizeof(timestamp) + sizeof(seq_num) + sizeof(objmonitor_id)); wr.put_event_type(event_monitor_deflate); wr.put_timestamp(time_now()); wr.put_seq_num(m->next_trace_seq()); wr.put_objmonitor_id(objmonitor_id_for(m)); } TraceTypes::class_id TraceEvents::retrieve_class_id_or_write_metadata(Klass *klass) { assert(can_write(), "caller's responsibility"); bool is_new; class_id id = TraceManager::metadata()->class_id(klass, is_new); if (is_new) { ResourceMark rm; const char *name = klass->name()->as_utf8(); const size_t name_nbytes = TraceWriter::nbytes_for_utf8str(name, 256); TraceWriter wr(sizeof(event_type) + sizeof(class_id) + sizeof(classloader_id) + name_nbytes); wr.put_event_type(event_class_metadata); wr.put_class_id(id); wr.put_classloader_id(classloader_id_for(klass->class_loader_data())); wr.put_utf8str(name, name_nbytes); } return id; } TraceTypes::method_id TraceEvents::retrieve_method_id_or_write_metadata(Method *method) { assert(can_write(), "caller's responsibility"); bool is_new; method_id id = TraceManager::metadata()->method_id(method, is_new); if (is_new) { class_id holder_id = retrieve_class_id_or_write_metadata(method->method_holder()); ResourceMark rm; const char *name = method->name()->as_utf8(), *sig = method->signature()->as_utf8(); const size_t name_nbytes = TraceWriter::nbytes_for_utf8str(name, 256), sig_nbytes = TraceWriter::nbytes_for_utf8str(sig, 1024); TraceWriter wr(sizeof(event_type) + sizeof(method_id) + sizeof(class_id) + name_nbytes + sig_nbytes); wr.put_event_type(event_method_metadata); wr.put_method_id(id); wr.put_class_id(holder_id); wr.put_utf8str(name, name_nbytes); wr.put_utf8str(sig, sig_nbytes); } return id; } TraceTypes::stack_id TraceEvents::retrieve_stack_id_or_write_metadata(JavaThread *t, stack_id preallocated_id) { class StatsUpdate : StackObj { public: bool truncated; intptr_t frames, reused_memento_frames; StatsUpdate() : truncated(false), frames(0), reused_memento_frames(0) {} ~StatsUpdate() { TraceManager::update_stack_trace_stats(truncated, frames, reused_memento_frames); } }; assert(can_write(), "caller's responsibility"); if (!EnableEventTracingStackTraces) { assert(preallocated_id == 0, "no preallocation allowed"); return (TraceTypes::stack_id) 0; } StatsUpdate stats; bool have_memento = (t->memento_original_return_address() != NULL); const CachedTraceStack *memento_stack = NULL; if (have_memento) { // we have patched a stack frame earlier and it has not returned yet memento_stack = t->memento_stack_trace(); // NOTE: after metadata has been purged, memento stack trace is NULL (safe to ignore) } TraceStackBuilder sb; bool new_memento = false; RegisterMap rm(t, false); frame fr = t->last_frame(); int index = -1; while (!fr.is_first_frame() && !sb.is_full()) { if ((fr.cb() != NULL && fr.cb()->is_nmethod()) || fr.is_interpreted_frame()) { index++; sb.add_frame(&fr); if (memento_stack != NULL) { // if the memento stack trace is truncated, we can't use it if we have fewer // frames above the patched frame or we'll be missing frames at the bottom if (!memento_stack->is_truncated() || index >= EventTracingStackMementoFrame) { if (fr.is_memento_marked(t)) { break; } } } else if (!have_memento && index == EventTracingStackMementoFrame) { fr.memento_mark(t); new_memento = true; } } fr = fr.sender(&rm); } if (!fr.is_first_frame() && sb.is_full()) { sb.set_truncated(); } CompositeTraceStack cps(sb); if (memento_stack != NULL && !fr.is_first_frame()) { // reached memento frame #ifdef ASSERT // another stack walk for validation TraceStackBuilder sb0; RegisterMap rm0(t, false); frame fr0 = t->last_frame(); while (!fr0.is_first_frame() && !sb0.is_full()) { if (fr0.is_interpreted_frame() || fr0.is_compiled_frame() || fr0.is_native_frame()) { sb0.add_frame(&fr0); } fr0 = fr0.sender(&rm0); } if (!fr0.is_first_frame()) { assert(sb0.is_full(), "incomplete stack walk"); sb0.set_truncated(); } CompositeTraceStack cps0(sb0); #endif if (index == EventTracingStackMementoFrame && sb.range_equals(0, memento_stack, 0, index + 1)) { // top frames are equal, exact match assert(cps0.equals(memento_stack), "sanity"); stats.frames = memento_stack->count(); stats.reused_memento_frames = stats.frames - sb.count(); // still had to walk the top frames stats.truncated = memento_stack->is_truncated(); return memento_stack->id(); } // complete with frames from cache cps.set_bottom(memento_stack, EventTracingStackMementoFrame + 1); stats.reused_memento_frames = cps.count() - sb.count(); assert(cps.equals(cps0), "sanity"); } stats.frames = cps.count(); stats.truncated = cps.is_truncated(); bool is_known; const CachedTraceStack *cached = TraceManager::metadata()->get_or_try_add_stack(cps, is_known, preallocated_id); TraceTypes::stack_id id; if (cached != NULL) { id = cached->id(); assert(is_known || preallocated_id == 0 || cached->id() == preallocated_id, "sanity"); } else { // insert failed (full) id = preallocated_id; if (id == 0) { // allocate a one-time id // FIXME: wasteful, since get_or_try_add_stack() likely also allocated an id and threw it away id = TraceManager::metadata()->next_stack_id(); } } if (!is_known) { write_stack_metadata(id, cps); } else if (preallocated_id != 0) { write_identical_stacks_metadata(preallocated_id, cached->id()); } if (new_memento) { t->set_memento_stack_trace(cached); } return id; } void TraceEvents::write_stack_metadata(stack_id id, const CompositeTraceStack &ts) { assert(can_write(), "caller's responsibility"); // TODO: with heavy inlining, stack traces can become so large // that they no longer fit in a single trace buffer size_t count = 0; // make methods known TraceStackVframeIterator it(ts); while (it.has_next()) { it.next(); retrieve_class_id_or_write_metadata(it.method()->method_holder()); retrieve_method_id_or_write_metadata(it.method()); count++; } it.reset(); TraceWriter wr(sizeof(event_type) + sizeof(stack_id) + sizeof(u1) + sizeof(u2) + count * (sizeof(method_id) + sizeof(method_bci))); wr.put_event_type(event_stack_metadata); wr.put_stack_id(id); wr.put_u1(ts.is_truncated() ? 0 : 1); assert(count == (u2) count, "must fit"); wr.put_u2(count); while (it.has_next()) { it.next(); wr.put_method_id(method_id_for(it.method())); wr.put_method_bci(it.bci()); } } void TraceEvents::write_identical_stacks_metadata(stack_id id, stack_id known) { assert(can_write(), "caller's responsibility"); TraceWriter wr(sizeof(event_type) + sizeof(stack_id) + sizeof(stack_id)); wr.put_event_type(event_identical_stacks_metadata); wr.put_stack_id(id); wr.put_stack_id(known); } void TraceEvents::write_class_loader_unload(ClassLoaderData* cld) { if(!can_write()) return; TraceWriter wr(sizeof(event_type) + sizeof(classloader_id)); wr.put_event_type(event_class_loader_unload); wr.put_classloader_id(classloader_id_for(cld)); } void TraceEvents::write_monitor_contended_enter(ObjectMonitor *m, monitor_enter_wait wait) { if (!can_write()) return; stack_id stid = 0; if (JavaThread::current()->has_last_Java_frame()) { stid = retrieve_stack_id_or_write_metadata(JavaThread::current()); } TraceWriter wr(sizeof(event_type) + sizeof(timestamp) + sizeof(seq_num) + sizeof(objmonitor_id) + sizeof(stack_id) + sizeof(u1)); wr.put_event_type(event_monitor_contended_enter); wr.put_timestamp(time_now()); wr.put_seq_num(m->next_trace_seq()); wr.put_objmonitor_id(objmonitor_id_for(m)); wr.put_stack_id(stid); wr.put_u1(wait); } void TraceEvents::write_monitor_contended_entered(ObjectMonitor *m, monitor_entered_flags flags) { if (!can_write()) return; TraceWriter wr(sizeof(event_type) + sizeof(timestamp) + sizeof(seq_num) + sizeof(objmonitor_id) + sizeof(u1)); wr.put_event_type(event_monitor_contended_entered); wr.put_timestamp(time_now()); wr.put_seq_num(m->next_trace_seq()); wr.put_objmonitor_id(objmonitor_id_for(m)); wr.put_u1(flags); } void TraceEvents::write_monitor_contended_exited(ObjectMonitor *m, seq_num seq, stack_id preallocated_stack_id, bool resolve_stack) { if (!can_write()) return; TraceTypes::stack_id stid = preallocated_stack_id; if (resolve_stack) { if (JavaThread::current()->has_last_Java_frame()) { stid = retrieve_stack_id_or_write_metadata(JavaThread::current(), preallocated_stack_id); } else if (preallocated_stack_id != 0) { // we preallocated a stack id, so we must resolve it to the unknown stack write_identical_stacks_metadata(preallocated_stack_id, 0); } } TraceWriter wr(sizeof(event_type) + sizeof(timestamp) + sizeof(seq_num) + sizeof(objmonitor_id) + sizeof(stack_id)); wr.put_event_type(event_monitor_contended_exited); wr.put_timestamp(time_now()); wr.put_seq_num(seq); wr.put_objmonitor_id(objmonitor_id_for(m)); wr.put_stack_id(stid); } void TraceEvents::write_monitor_dummy(ObjectMonitor *m, seq_num seq) { if (!can_write()) return; TraceWriter wr(sizeof(event_type) + sizeof(seq_num) + sizeof(objmonitor_id)); wr.put_event_type(event_monitor_dummy); wr.put_seq_num(seq); wr.put_objmonitor_id(objmonitor_id_for(m)); } void TraceEvents::write_safepoint_begin(safepoint_reason reason) { assert(reason > _safepoint_reason_min && reason < _safepoint_reason_max, "invalid reason"); if (!can_write()) return; TraceWriter wr(sizeof(event_type) + sizeof(timestamp) + sizeof(u1)); wr.put_event_type(event_safepoint_begin); wr.put_timestamp(time_now()); wr.put_u1((u1) reason); } void TraceEvents::write_safepoint_end(u4 vmops_processed) { if (!can_write()) return; if (vmops_processed > UINT8_MAX) vmops_processed = UINT8_MAX; TraceWriter wr(sizeof(event_type) + sizeof(timestamp) + sizeof(u1)); wr.put_event_type(event_safepoint_end); wr.put_timestamp(time_now()); wr.put_u1((u1) vmops_processed); } void TraceEvents::write_vm_end() { if (!can_write()) return; TraceWriter wr(sizeof(event_type) + sizeof(timestamp)); wr.put_event_type(event_vm_end); wr.put_timestamp(time_now()); } void TraceEvents::write_metadata_reset() { if (!can_write()) return; TraceWriter wr(sizeof(event_type)); wr.put_event_type(event_metadata_reset); } void TraceEvents::write_group(JavaThread* t, seq_num park_global_seq_begin_ref, oop source) { assert(t != NULL, "null thread"); assert(source != NULL, "null source"); if (!can_write()) return; Klass* klass = source->klass(); object_id oid = object_id_for(source); source = NULL; // source oop may not be valid anymore after object_id_for() assert(oid != 0, "just checking"); // recheck necessary, because object_id_for() can cause a safepoint check if (!can_write()) return; class_id cid = retrieve_class_id_or_write_metadata(klass); assert(cid != 0, "just checking"); TraceWriter wr(sizeof(event_type) + sizeof(timestamp) + sizeof(seq_num) + sizeof(seq_num) + sizeof(object_id) + sizeof(class_id)); wr.put_event_type(event_group); wr.put_timestamp(time_now()); wr.put_seq_num(TraceManager::metadata()->next_global_seq()); wr.put_seq_num(park_global_seq_begin_ref); wr.put_object_id(oid); wr.put_class_id(cid); } void TraceEvents::write_marker(const char *label) { if (!can_write()) return; const size_t label_nbytes = TraceWriter::nbytes_for_utf8str(label, 64); TraceWriter wr(sizeof(event_type) + sizeof(timestamp) + label_nbytes); wr.put_event_type(event_marker); wr.put_timestamp(time_now()); wr.put_utf8str(label, label_nbytes); } void TraceEventThreadParkEnd::do_write() { TraceEvents::write_thread_park_end(_thread, _seq, _unpark_seq, _return_code); } void TraceEventThreadUnpark::do_write() { assert(_chained_seq != -1, "chained_seq not set"); TraceEvents::write_thread_unpark(_thread_id, _seq, _chained_seq); }