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