8316229: Enhance class initialization logging

Reviewed-by: shade, coleenp
This commit is contained in:
David Holmes 2023-09-21 00:50:33 +00:00
parent c04c9ea361
commit 84124794c2
4 changed files with 72 additions and 4 deletions

@ -770,20 +770,43 @@ void InstanceKlass::link_class(TRAPS) {
void InstanceKlass::check_link_state_and_wait(JavaThread* current) {
MonitorLocker ml(current, _init_monitor);
bool debug_logging_enabled = log_is_enabled(Debug, class, init);
// Another thread is linking this class, wait.
while (is_being_linked() && !is_init_thread(current)) {
if (debug_logging_enabled) {
ResourceMark rm(current);
log_debug(class, init)("Thread \"%s\" waiting for linking of %s by thread \"%s\"",
current->name(), external_name(), init_thread_name());
}
ml.wait();
}
// This thread is recursively linking this class, continue
if (is_being_linked() && is_init_thread(current)) {
if (debug_logging_enabled) {
ResourceMark rm(current);
log_debug(class, init)("Thread \"%s\" recursively linking %s",
current->name(), external_name());
}
return;
}
// If this class wasn't linked already, set state to being_linked
if (!is_linked()) {
if (debug_logging_enabled) {
ResourceMark rm(current);
log_debug(class, init)("Thread \"%s\" linking %s",
current->name(), external_name());
}
set_init_state(being_linked);
set_init_thread(current);
} else {
if (debug_logging_enabled) {
ResourceMark rm(current);
log_debug(class, init)("Thread \"%s\" found %s already linked",
current->name(), external_name());
}
}
}
@ -1058,13 +1081,21 @@ void InstanceKlass::initialize_impl(TRAPS) {
JavaThread* jt = THREAD;
bool debug_logging_enabled = log_is_enabled(Debug, class, init);
// refer to the JVM book page 47 for description of steps
// Step 1
{
MonitorLocker ml(THREAD, _init_monitor);
MonitorLocker ml(jt, _init_monitor);
// Step 2
while (is_being_initialized() && !is_init_thread(jt)) {
if (debug_logging_enabled) {
ResourceMark rm(jt);
log_debug(class, init)("Thread \"%s\" waiting for initialization of %s by thread \"%s\"",
jt->name(), external_name(), init_thread_name());
}
wait = true;
jt->set_class_to_be_initialized(this);
ml.wait();
@ -1073,24 +1104,44 @@ void InstanceKlass::initialize_impl(TRAPS) {
// Step 3
if (is_being_initialized() && is_init_thread(jt)) {
if (debug_logging_enabled) {
ResourceMark rm(jt);
log_debug(class, init)("Thread \"%s\" recursively initializing %s",
jt->name(), external_name());
}
DTRACE_CLASSINIT_PROBE_WAIT(recursive, -1, wait);
return;
}
// Step 4
if (is_initialized()) {
if (debug_logging_enabled) {
ResourceMark rm(jt);
log_debug(class, init)("Thread \"%s\" found %s already initialized",
jt->name(), external_name());
}
DTRACE_CLASSINIT_PROBE_WAIT(concurrent, -1, wait);
return;
}
// Step 5
if (is_in_error_state()) {
if (debug_logging_enabled) {
ResourceMark rm(jt);
log_debug(class, init)("Thread \"%s\" found %s is in error state",
jt->name(), external_name());
}
throw_error = true;
} else {
// Step 6
set_init_state(being_initialized);
set_init_thread(jt);
if (debug_logging_enabled) {
ResourceMark rm(jt);
log_debug(class, init)("Thread \"%s\" is initializing %s",
jt->name(), external_name());
}
}
}
@ -1564,7 +1615,9 @@ void InstanceKlass::call_class_initializer(TRAPS) {
LogStream ls(lt);
ls.print("%d Initializing ", call_class_initializer_counter++);
name()->print_value_on(&ls);
ls.print_cr("%s (" PTR_FORMAT ")", h_method() == nullptr ? "(no method)" : "", p2i(this));
ls.print_cr("%s (" PTR_FORMAT ") by thread \"%s\"",
h_method() == nullptr ? "(no method)" : "", p2i(this),
THREAD->name());
}
if (h_method() != nullptr) {
JavaCallArguments args; // No arguments
@ -4427,4 +4480,3 @@ void ClassHierarchyIterator::next() {
_current = _current->next_sibling();
return; // visit next sibling subclass
}

@ -495,6 +495,14 @@ public:
static void check_prohibited_package(Symbol* class_name,
ClassLoaderData* loader_data,
TRAPS);
JavaThread* init_thread() { return Atomic::load(&_init_thread); }
// We can safely access the name as long as we hold the _init_monitor.
const char* init_thread_name() {
assert(_init_monitor->owned_by_self(), "Must hold _init_monitor here");
return init_thread()->name_raw();
}
public:
// initialization state
bool is_loaded() const { return init_state() >= loaded; }
@ -504,7 +512,7 @@ public:
bool is_not_initialized() const { return init_state() < being_initialized; }
bool is_being_initialized() const { return init_state() == being_initialized; }
bool is_in_error_state() const { return init_state() == initialization_error; }
bool is_init_thread(JavaThread *thread) { return thread == Atomic::load(&_init_thread); }
bool is_init_thread(JavaThread *thread) { return thread == init_thread(); }
ClassState init_state() const { return Atomic::load(&_init_state); }
const char* init_state_name() const;
bool is_rewritten() const { return _misc_flags.rewritten(); }

@ -1588,6 +1588,13 @@ const char* JavaThread::name() const {
return Thread::name();
}
// Like name() but doesn't include the protection check. This must only be
// called when it is known to be safe, even though the protection check can't tell
// that e.g. when this thread is the init_thread() - see instanceKlass.cpp.
const char* JavaThread::name_raw() const {
return get_thread_name_string();
}
// Returns a non-null representation of this thread's name, or a suitable
// descriptive string if there is no set name.
const char* JavaThread::get_thread_name_string(char* buf, int buflen) const {

@ -900,6 +900,7 @@ private:
// Misc. operations
const char* name() const;
const char* name_raw() const;
const char* type_name() const { return "JavaThread"; }
static const char* name_for(oop thread_obj);