void Test_configure_stdout() {
ResourceMark rm;
LogHandle(logging) log;
LogOutput* stdoutput = LogOutput::Stdout;
// Save current stdout config and clear it
char* saved_config = os::strdup_check_oom(stdoutput->config_string());
LogConfiguration::parse_log_arguments("stdout", "all=off", NULL, NULL, log.error_stream());
// Enable 'logging=info', verifying it has been set
LogConfiguration::configure_stdout(LogLevel::Info, true, LOG_TAGS(logging));
assert_str_eq("logging=info,", stdoutput->config_string());
assert(log_is_enabled(Info, logging), "logging was not properly enabled");
// Enable 'gc=debug' (no wildcard), verifying no other tags are enabled
LogConfiguration::configure_stdout(LogLevel::Debug, true, LOG_TAGS(gc));
// No '+' character means only single tags are enabled, and no combinations
assert_char_not_in('+', stdoutput->config_string());
assert(log_is_enabled(Debug, gc), "logging was not properly enabled");
// Enable 'gc*=trace' (with wildcard), verifying at least one tag combination is enabled (gc+...)
LogConfiguration::configure_stdout(LogLevel::Trace, false, LOG_TAGS(gc));
assert_char_in('+', stdoutput->config_string());
assert(log_is_enabled(Trace, gc), "logging was not properly enabled");
// Disable 'gc*' and 'logging', verifying all logging is properly disabled
LogConfiguration::configure_stdout(LogLevel::Off, false, LOG_TAGS(gc));
LogConfiguration::configure_stdout(LogLevel::Off, true, LOG_TAGS(logging));
assert_str_eq("all=off", stdoutput->config_string());
// Restore saved configuration
LogConfiguration::parse_log_arguments("stdout", saved_config, NULL, NULL, log.error_stream());
os::free(saved_config);
}
// Unpacks one or more frames into user-supplied buffers.
// Updates the end index, and returns the number of unpacked frames.
// Always start with the existing vfst.method and bci.
// Do not call vfst.next to advance over the last returned value.
// In other words, do not leave any stale data in the vfst.
//
// Parameters:
// mode Restrict which frames to be decoded.
// BaseFrameStream stream of frames
// max_nframes Maximum number of frames to be filled.
// start_index Start index to the user-supplied buffers.
// frames_array Buffer to store Class or StackFrame in, starting at start_index.
// frames array is a Class<?>[] array when only getting caller
// reference, and a StackFrameInfo[] array (or derivative)
// otherwise. It should never be null.
// end_index End index to the user-supplied buffers with unpacked frames.
//
// Returns the number of frames whose information was transferred into the buffers.
//
int StackWalk::fill_in_frames(jlong mode, BaseFrameStream& stream,
int max_nframes, int start_index,
objArrayHandle frames_array,
int& end_index, TRAPS) {
log_debug(stackwalk)("fill_in_frames limit=%d start=%d frames length=%d",
max_nframes, start_index, frames_array->length());
assert(max_nframes > 0, "invalid max_nframes");
assert(start_index + max_nframes <= frames_array->length(), "oob");
int frames_decoded = 0;
for (; !stream.at_end(); stream.next()) {
Method* method = stream.method();
if (method == NULL) continue;
// skip hidden frames for default StackWalker option (i.e. SHOW_HIDDEN_FRAMES
// not set) and when StackWalker::getCallerClass is called
if (!ShowHiddenFrames && (skip_hidden_frames(mode) || get_caller_class(mode))) {
if (method->is_hidden()) {
if (log_is_enabled(Debug, stackwalk)) {
ResourceMark rm(THREAD);
outputStream* st = Log(stackwalk)::debug_stream();
st->print(" hidden method: ");
method->print_short_name(st);
st->cr();
}
continue;
}
}
int index = end_index++;
if (log_is_enabled(Debug, stackwalk)) {
ResourceMark rm(THREAD);
outputStream* st = Log(stackwalk)::debug_stream();
st->print(" %d: frame method: ", index);
method->print_short_name(st);
st->print_cr(" bci=%d", stream.bci());
}
if (!need_method_info(mode) && get_caller_class(mode) &&
index == start_index && method->caller_sensitive()) {
ResourceMark rm(THREAD);
THROW_MSG_0(vmSymbols::java_lang_UnsupportedOperationException(),
err_msg("StackWalker::getCallerClass called from @CallerSensitive %s method",
method->name_and_sig_as_C_string()));
}
// fill in StackFrameInfo and initialize MemberName
stream.fill_frame(index, frames_array, method, CHECK_0);
if (++frames_decoded >= max_nframes) break;
}
return frames_decoded;
}
// -----------------------------------------------------------------------
int log_enable()
{
if (log_is_enabled()) {
return E_OK;
}
// Open log file
log_f = fopen(log_file, "a");
if (!log_f) {
return E_FILE_OPEN;
}
log_log_timestamp(L_EM4H, 0, "Opened log");
// start up flusher thread
log_flusher_stop = 0;
if (pthread_create(&log_flusher_th, NULL, log_flusher, NULL) != 0) {
fclose(log_f);
return E_THREAD;
}
atom_store_release(&log_enabled, 1);
return E_OK;
}
void VM_Version_init() {
VM_Version::initialize();
if (log_is_enabled(Info, os, cpu)) {
char buf[1024];
ResourceMark rm;
outputStream* log = Log(os, cpu)::info_stream();
os::print_cpu_info(log, buf, sizeof(buf));
}
}
// -----------------------------------------------------------------------
int ectl_log_state_get()
{
int state = log_is_enabled();
LOG(L_ECTL, "ECTL log state get: %i", state);
if (state) {
return ECTL_ON;
} else {
return ECTL_OFF;
}
}
uint ageTable::compute_tenuring_threshold(size_t survivor_capacity, GCPolicyCounters* gc_counters) {
size_t desired_survivor_size = (size_t)((((double) survivor_capacity)*TargetSurvivorRatio)/100);
uint result;
if (AlwaysTenure || NeverTenure) {
assert(MaxTenuringThreshold == 0 || MaxTenuringThreshold == markOopDesc::max_age + 1,
"MaxTenuringThreshold should be 0 or markOopDesc::max_age + 1, but is " UINTX_FORMAT, MaxTenuringThreshold);
result = MaxTenuringThreshold;
} else {
size_t total = 0;
uint age = 1;
assert(sizes[0] == 0, "no objects with age zero should be recorded");
while (age < table_size) {
total += sizes[age];
// check if including objects of age 'age' made us pass the desired
// size, if so 'age' is the new threshold
if (total > desired_survivor_size) break;
age++;
}
result = age < MaxTenuringThreshold ? age : MaxTenuringThreshold;
}
log_debug(gc, age)("Desired survivor size " SIZE_FORMAT " bytes, new threshold " UINTX_FORMAT " (max threshold " UINTX_FORMAT ")",
desired_survivor_size*oopSize, (uintx) result, MaxTenuringThreshold);
if (log_is_enabled(Trace, gc, age) || UsePerfData) {
size_t total = 0;
uint age = 1;
while (age < table_size) {
total += sizes[age];
if (sizes[age] > 0) {
log_trace(gc, age)("- age %3u: " SIZE_FORMAT_W(10) " bytes, " SIZE_FORMAT_W(10) " total",
age, sizes[age]*oopSize, total*oopSize);
}
if (UsePerfData) {
_perf_sizes[age]->set_value(sizes[age]*oopSize);
}
age++;
}
if (UsePerfData) {
gc_counters->tenuring_threshold()->set_value(result);
gc_counters->desired_survivor_size()->set_value(
desired_survivor_size*oopSize);
}
}
return result;
}
GCTraceCPUTime::GCTraceCPUTime() :
_active(log_is_enabled(Info, gc, cpu)),
_starting_user_time(0.0),
_starting_system_time(0.0),
_starting_real_time(0.0)
{
if (_active) {
bool valid = os::getTimesSecs(&_starting_real_time,
&_starting_user_time,
&_starting_system_time);
if (!valid) {
log_warning(gc, cpu)("TraceCPUTime: os::getTimesSecs() returned invalid result");
_active = false;
}
}
}
void VM_Operation::evaluate() {
ResourceMark rm;
outputStream* debugstream;
bool enabled = log_is_enabled(Debug, vmoperation);
if (enabled) {
debugstream = LogHandle(vmoperation)::debug_stream();
debugstream->print("begin ");
print_on_error(debugstream);
debugstream->cr();
}
doit();
if (enabled) {
debugstream->print("end ");
print_on_error(debugstream);
debugstream->cr();
}
}
// -----------------------------------------------------------------------
void log_disable()
{
if (!log_is_enabled()) {
return;
}
log_log_timestamp(L_EM4H, 0, "Closing log");
atom_store_release(&log_enabled, 0);
// stop flusher thread
pthread_mutex_lock(&log_mutex);
log_flusher_stop = 1;
pthread_mutex_unlock(&log_mutex);
pthread_join(log_flusher_th, NULL);
if (log_f) {
fclose(log_f);
}
}
void G1HeapTransition::print() {
Data after(_g1_heap);
size_t eden_capacity_length_after_gc = _g1_heap->g1_policy()->young_list_target_length() - after._survivor_length;
size_t survivor_capacity_length_after_gc = _g1_heap->g1_policy()->max_survivor_regions();
DetailedUsage usage;
if (log_is_enabled(Trace, gc, heap)) {
DetailedUsageClosure blk;
_g1_heap->heap_region_iterate(&blk);
usage = blk._usage;
assert(usage._eden_region_count == 0, "Expected no eden regions, but got " SIZE_FORMAT, usage._eden_region_count);
assert(usage._survivor_region_count == after._survivor_length, "Expected survivors to be " SIZE_FORMAT " but was " SIZE_FORMAT,
after._survivor_length, usage._survivor_region_count);
assert(usage._old_region_count == after._old_length, "Expected old to be " SIZE_FORMAT " but was " SIZE_FORMAT,
after._old_length, usage._old_region_count);
assert(usage._humongous_region_count == after._humongous_length, "Expected humongous to be " SIZE_FORMAT " but was " SIZE_FORMAT,
after._humongous_length, usage._humongous_region_count);
}
log_info(gc, heap)("Eden regions: " SIZE_FORMAT "->" SIZE_FORMAT "(" SIZE_FORMAT ")",
_before._eden_length, after._eden_length, eden_capacity_length_after_gc);
log_trace(gc, heap)(" Used: 0K, Waste: 0K");
log_info(gc, heap)("Survivor regions: " SIZE_FORMAT "->" SIZE_FORMAT "(" SIZE_FORMAT ")",
_before._survivor_length, after._survivor_length, survivor_capacity_length_after_gc);
log_trace(gc, heap)(" Used: " SIZE_FORMAT "K, Waste: " SIZE_FORMAT "K",
usage._survivor_used / K, ((after._survivor_length * HeapRegion::GrainBytes) - usage._survivor_used) / K);
log_info(gc, heap)("Old regions: " SIZE_FORMAT "->" SIZE_FORMAT,
_before._old_length, after._old_length);
log_trace(gc, heap)(" Used: " SIZE_FORMAT "K, Waste: " SIZE_FORMAT "K",
usage._old_used / K, ((after._old_length * HeapRegion::GrainBytes) - usage._old_used) / K);
log_info(gc, heap)("Humongous regions: " SIZE_FORMAT "->" SIZE_FORMAT,
_before._humongous_length, after._humongous_length);
log_trace(gc, heap)(" Used: " SIZE_FORMAT "K, Waste: " SIZE_FORMAT "K",
usage._humongous_used / K, ((after._humongous_length * HeapRegion::GrainBytes) - usage._humongous_used) / K);
MetaspaceAux::print_metaspace_change(_before._metaspace_used_bytes);
}
void ClassLoadingService::notify_class_unloaded(InstanceKlass* k) {
DTRACE_CLASSLOAD_PROBE(unloaded, k, false);
// Classes that can be unloaded must be non-shared
_classes_unloaded_count->inc();
if (UsePerfData) {
// add the class size
size_t size = compute_class_size(k);
_classbytes_unloaded->inc(size);
// Compute method size & subtract from running total.
// We are called during phase 1 of mark sweep, so it's
// still ok to iterate through Method*s here.
Array<Method*>* methods = k->methods();
for (int i = 0; i < methods->length(); i++) {
_class_methods_size->inc(-methods->at(i)->size());
}
}
if (log_is_enabled(Info, classunload)) {
ResourceMark rm;
log_info(classunload)("unloading class %s " INTPTR_FORMAT , k->external_name(), p2i(k));
}
}
void JvmtiTrace::initialize() {
if (_initialized) {
return;
}
SafeResourceMark rm;
const char *very_end;
const char *curr;
if (TraceJVMTI != NULL) {
curr = TraceJVMTI;
} else {
curr = ""; // hack in fixed tracing here
}
// Enable UL for JVMTI tracing
if (strlen(curr) > 0) {
if (!log_is_enabled(Trace, jvmti)) {
log_warning(arguments)("-XX:+TraceJVMTI specified, "
"but no log output configured for the 'jvmti' tag on Trace level. "
"Defaulting to -Xlog:jvmti=trace");
LogConfiguration::configure_stdout(LogLevel::Trace, true, LOG_TAGS(jvmti));
}
}
very_end = curr + strlen(curr);
while (curr < very_end) {
const char *curr_end = strchr(curr, ',');
if (curr_end == NULL) {
curr_end = very_end;
}
const char *op_pos = strchr(curr, '+');
const char *minus_pos = strchr(curr, '-');
if (minus_pos != NULL && (minus_pos < op_pos || op_pos == NULL)) {
op_pos = minus_pos;
}
char op;
const char *flags = op_pos + 1;
const char *flags_end = curr_end;
if (op_pos == NULL || op_pos > curr_end) {
flags = "ies";
flags_end = flags + strlen(flags);
op_pos = curr_end;
op = '+';
} else {
op = *op_pos;
}
jbyte bits = 0;
for (; flags < flags_end; ++flags) {
switch (*flags) {
case 'i':
bits |= SHOW_IN;
break;
case 'I':
bits |= SHOW_IN_DETAIL;
break;
case 'e':
bits |= SHOW_ERROR;
break;
case 'o':
bits |= SHOW_OUT;
break;
case 'O':
bits |= SHOW_OUT_DETAIL;
break;
case 't':
bits |= SHOW_EVENT_TRIGGER;
break;
case 's':
bits |= SHOW_EVENT_SENT;
break;
default:
log_warning(jvmti)("Invalid trace flag '%c'", *flags);
break;
}
}
const int FUNC = 1;
const int EXCLUDE = 2;
const int ALL_FUNC = 4;
const int EVENT = 8;
const int ALL_EVENT = 16;
int domain = 0;
size_t len = op_pos - curr;
if (op_pos == curr) {
domain = ALL_FUNC | FUNC | ALL_EVENT | EVENT | EXCLUDE;
} else if (len==3 && strncmp(curr, "all", 3)==0) {
domain = ALL_FUNC | FUNC | ALL_EVENT | EVENT;
} else if (len==7 && strncmp(curr, "allfunc", 7)==0) {
domain = ALL_FUNC | FUNC;
} else if (len==4 && strncmp(curr, "func", 4)==0) {
domain = ALL_FUNC | FUNC | EXCLUDE;
} else if (len==8 && strncmp(curr, "allevent", 8)==0) {
domain = ALL_EVENT | EVENT;
} else if (len==5 && strncmp(curr, "event", 5)==0) {
domain = ALL_EVENT | EVENT;
} else if (len==2 && strncmp(curr, "ec", 2)==0) {
_trace_event_controller = true;
log_trace(jvmti)("Tracing the event controller");
} else {
domain = FUNC | EVENT; // go searching
}
int exclude_index = 0;
if (domain & FUNC) {
if (domain & ALL_FUNC) {
if (domain & EXCLUDE) {
log_trace(jvmti)("Tracing all significant functions");
} else {
log_trace(jvmti)("Tracing all functions");
}
}
for (int i = 0; i <= _max_function_index; ++i) {
if (domain & EXCLUDE && i == _exclude_functions[exclude_index]) {
++exclude_index;
} else {
bool do_op = false;
if (domain & ALL_FUNC) {
do_op = true;
} else {
const char *fname = function_name(i);
if (fname != NULL) {
size_t fnlen = strlen(fname);
if (len==fnlen && strncmp(curr, fname, fnlen)==0) {
log_trace(jvmti)("Tracing the function: %s", fname);
do_op = true;
}
}
}
if (do_op) {
if (op == '+') {
_trace_flags[i] |= bits;
} else {
_trace_flags[i] &= ~bits;
}
_on = true;
}
}
}
}
if (domain & EVENT) {
if (domain & ALL_EVENT) {
log_trace(jvmti)("Tracing all events");
}
for (int i = 0; i <= _max_event_index; ++i) {
bool do_op = false;
if (domain & ALL_EVENT) {
do_op = true;
} else {
const char *ename = event_name(i);
if (ename != NULL) {
size_t evtlen = strlen(ename);
if (len==evtlen && strncmp(curr, ename, evtlen)==0) {
log_trace(jvmti)("Tracing the event: %s", ename);
do_op = true;
}
}
}
if (do_op) {
if (op == '+') {
_event_trace_flags[i] |= bits;
} else {
_event_trace_flags[i] &= ~bits;
}
_on = true;
}
}
}
if (!_on && (domain & (FUNC|EVENT))) {
log_warning(jvmti)("Trace domain not found");
}
curr = curr_end + 1;
}
_initialized = true;
}
TEST_F(LogConfigurationTest, configure_stdout) {
// Start out with all logging disabled
LogConfiguration::disable_logging();
// Enable 'logging=info', verifying it has been set
LogConfiguration::configure_stdout(LogLevel::Info, true, LOG_TAGS(logging));
EXPECT_TRUE(log_is_enabled(Info, logging));
EXPECT_FALSE(log_is_enabled(Debug, logging));
EXPECT_FALSE(log_is_enabled(Info, gc));
LogTagSet* logging_ts = &LogTagSetMapping<LOG_TAGS(logging)>::tagset();
EXPECT_EQ(LogLevel::Info, logging_ts->level_for(&StdoutLog));
// Enable 'gc=debug' (no wildcard), verifying no other tags are enabled
LogConfiguration::configure_stdout(LogLevel::Debug, true, LOG_TAGS(gc));
EXPECT_TRUE(log_is_enabled(Debug, gc));
EXPECT_TRUE(log_is_enabled(Info, logging));
EXPECT_FALSE(log_is_enabled(Debug, gc, heap));
for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
if (ts->contains(PREFIX_LOG_TAG(gc))) {
if (ts->ntags() == 1) {
EXPECT_EQ(LogLevel::Debug, ts->level_for(&StdoutLog));
} else {
EXPECT_EQ(LogLevel::Off, ts->level_for(&StdoutLog));
}
}
}
// Enable 'gc*=trace' (with wildcard), verifying that all tag combinations with gc are enabled (gc+...)
LogConfiguration::configure_stdout(LogLevel::Trace, false, LOG_TAGS(gc));
EXPECT_TRUE(log_is_enabled(Trace, gc));
EXPECT_TRUE(log_is_enabled(Trace, gc, heap));
for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
if (ts->contains(PREFIX_LOG_TAG(gc))) {
EXPECT_EQ(LogLevel::Trace, ts->level_for(&StdoutLog));
} else if (ts == logging_ts) {
// Previous setting for 'logging' should remain
EXPECT_EQ(LogLevel::Info, ts->level_for(&StdoutLog));
} else {
EXPECT_EQ(LogLevel::Off, ts->level_for(&StdoutLog));
}
}
// Disable 'gc*' and 'logging', verifying all logging is properly disabled
LogConfiguration::configure_stdout(LogLevel::Off, true, LOG_TAGS(logging));
EXPECT_FALSE(log_is_enabled(Error, logging));
LogConfiguration::configure_stdout(LogLevel::Off, false, LOG_TAGS(gc));
EXPECT_FALSE(log_is_enabled(Error, gc));
EXPECT_FALSE(log_is_enabled(Error, gc, heap));
for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
EXPECT_EQ(LogLevel::Off, ts->level_for(&StdoutLog));
}
}
// Roll all threads forward to a safepoint and suspend them all
void SafepointSynchronize::begin() {
Thread* myThread = Thread::current();
assert(myThread->is_VM_thread(), "Only VM thread may execute a safepoint");
if (PrintSafepointStatistics || PrintSafepointStatisticsTimeout > 0) {
_safepoint_begin_time = os::javaTimeNanos();
_ts_of_current_safepoint = tty->time_stamp().seconds();
}
#if INCLUDE_ALL_GCS
if (UseConcMarkSweepGC) {
// In the future we should investigate whether CMS can use the
// more-general mechanism below. DLD (01/05).
ConcurrentMarkSweepThread::synchronize(false);
} else if (UseG1GC) {
SuspendibleThreadSet::synchronize();
}
#endif // INCLUDE_ALL_GCS
// By getting the Threads_lock, we assure that no threads are about to start or
// exit. It is released again in SafepointSynchronize::end().
Threads_lock->lock();
assert( _state == _not_synchronized, "trying to safepoint synchronize with wrong state");
int nof_threads = Threads::number_of_threads();
log_debug(safepoint)("Safepoint synchronization initiated. (%d)", nof_threads);
RuntimeService::record_safepoint_begin();
MutexLocker mu(Safepoint_lock);
// Reset the count of active JNI critical threads
_current_jni_active_count = 0;
// Set number of threads to wait for, before we initiate the callbacks
_waiting_to_block = nof_threads;
TryingToBlock = 0 ;
int still_running = nof_threads;
// Save the starting time, so that it can be compared to see if this has taken
// too long to complete.
jlong safepoint_limit_time = 0;
timeout_error_printed = false;
// PrintSafepointStatisticsTimeout can be specified separately. When
// specified, PrintSafepointStatistics will be set to true in
// deferred_initialize_stat method. The initialization has to be done
// early enough to avoid any races. See bug 6880029 for details.
if (PrintSafepointStatistics || PrintSafepointStatisticsTimeout > 0) {
deferred_initialize_stat();
}
// Begin the process of bringing the system to a safepoint.
// Java threads can be in several different states and are
// stopped by different mechanisms:
//
// 1. Running interpreted
// The interpreter dispatch table is changed to force it to
// check for a safepoint condition between bytecodes.
// 2. Running in native code
// When returning from the native code, a Java thread must check
// the safepoint _state to see if we must block. If the
// VM thread sees a Java thread in native, it does
// not wait for this thread to block. The order of the memory
// writes and reads of both the safepoint state and the Java
// threads state is critical. In order to guarantee that the
// memory writes are serialized with respect to each other,
// the VM thread issues a memory barrier instruction
// (on MP systems). In order to avoid the overhead of issuing
// a memory barrier for each Java thread making native calls, each Java
// thread performs a write to a single memory page after changing
// the thread state. The VM thread performs a sequence of
// mprotect OS calls which forces all previous writes from all
// Java threads to be serialized. This is done in the
// os::serialize_thread_states() call. This has proven to be
// much more efficient than executing a membar instruction
// on every call to native code.
// 3. Running compiled Code
// Compiled code reads a global (Safepoint Polling) page that
// is set to fault if we are trying to get to a safepoint.
// 4. Blocked
// A thread which is blocked will not be allowed to return from the
// block condition until the safepoint operation is complete.
// 5. In VM or Transitioning between states
// If a Java thread is currently running in the VM or transitioning
// between states, the safepointing code will wait for the thread to
// block itself when it attempts transitions to a new state.
//
_state = _synchronizing;
OrderAccess::fence();
// Flush all thread states to memory
if (!UseMembar) {
os::serialize_thread_states();
}
// Make interpreter safepoint aware
Interpreter::notice_safepoints();
if (DeferPollingPageLoopCount < 0) {
// Make polling safepoint aware
guarantee (PageArmed == 0, "invariant") ;
PageArmed = 1 ;
os::make_polling_page_unreadable();
}
// Consider using active_processor_count() ... but that call is expensive.
int ncpus = os::processor_count() ;
#ifdef ASSERT
for (JavaThread *cur = Threads::first(); cur != NULL; cur = cur->next()) {
assert(cur->safepoint_state()->is_running(), "Illegal initial state");
// Clear the visited flag to ensure that the critical counts are collected properly.
cur->set_visited_for_critical_count(false);
}
#endif // ASSERT
if (SafepointTimeout)
safepoint_limit_time = os::javaTimeNanos() + (jlong)SafepointTimeoutDelay * MICROUNITS;
// Iterate through all threads until it have been determined how to stop them all at a safepoint
unsigned int iterations = 0;
int steps = 0 ;
while(still_running > 0) {
for (JavaThread *cur = Threads::first(); cur != NULL; cur = cur->next()) {
assert(!cur->is_ConcurrentGC_thread(), "A concurrent GC thread is unexpectly being suspended");
ThreadSafepointState *cur_state = cur->safepoint_state();
if (cur_state->is_running()) {
cur_state->examine_state_of_thread();
if (!cur_state->is_running()) {
still_running--;
// consider adjusting steps downward:
// steps = 0
// steps -= NNN
// steps >>= 1
// steps = MIN(steps, 2000-100)
// if (iterations != 0) steps -= NNN
}
if (log_is_enabled(Trace, safepoint)) {
ResourceMark rm;
cur_state->print_on(LogHandle(safepoint)::debug_stream());
}
}
}
if (PrintSafepointStatistics && iterations == 0) {
begin_statistics(nof_threads, still_running);
}
if (still_running > 0) {
// Check for if it takes to long
if (SafepointTimeout && safepoint_limit_time < os::javaTimeNanos()) {
print_safepoint_timeout(_spinning_timeout);
}
// Spin to avoid context switching.
// There's a tension between allowing the mutators to run (and rendezvous)
// vs spinning. As the VM thread spins, wasting cycles, it consumes CPU that
// a mutator might otherwise use profitably to reach a safepoint. Excessive
// spinning by the VM thread on a saturated system can increase rendezvous latency.
// Blocking or yielding incur their own penalties in the form of context switching
// and the resultant loss of $ residency.
//
// Further complicating matters is that yield() does not work as naively expected
// on many platforms -- yield() does not guarantee that any other ready threads
// will run. As such we revert to naked_short_sleep() after some number of iterations.
// nakes_short_sleep() is implemented as a short unconditional sleep.
// Typical operating systems round a "short" sleep period up to 10 msecs, so sleeping
// can actually increase the time it takes the VM thread to detect that a system-wide
// stop-the-world safepoint has been reached. In a pathological scenario such as that
// described in CR6415670 the VMthread may sleep just before the mutator(s) become safe.
// In that case the mutators will be stalled waiting for the safepoint to complete and the
// the VMthread will be sleeping, waiting for the mutators to rendezvous. The VMthread
// will eventually wake up and detect that all mutators are safe, at which point
// we'll again make progress.
//
// Beware too that that the VMThread typically runs at elevated priority.
// Its default priority is higher than the default mutator priority.
// Obviously, this complicates spinning.
//
// Note too that on Windows XP SwitchThreadTo() has quite different behavior than Sleep(0).
// Sleep(0) will _not yield to lower priority threads, while SwitchThreadTo() will.
//
// See the comments in synchronizer.cpp for additional remarks on spinning.
//
// In the future we might:
// 1. Modify the safepoint scheme to avoid potentially unbounded spinning.
// This is tricky as the path used by a thread exiting the JVM (say on
// on JNI call-out) simply stores into its state field. The burden
// is placed on the VM thread, which must poll (spin).
// 2. Find something useful to do while spinning. If the safepoint is GC-related
// we might aggressively scan the stacks of threads that are already safe.
// 3. Use Solaris schedctl to examine the state of the still-running mutators.
// If all the mutators are ONPROC there's no reason to sleep or yield.
// 4. YieldTo() any still-running mutators that are ready but OFFPROC.
// 5. Check system saturation. If the system is not fully saturated then
// simply spin and avoid sleep/yield.
// 6. As still-running mutators rendezvous they could unpark the sleeping
// VMthread. This works well for still-running mutators that become
// safe. The VMthread must still poll for mutators that call-out.
// 7. Drive the policy on time-since-begin instead of iterations.
// 8. Consider making the spin duration a function of the # of CPUs:
// Spin = (((ncpus-1) * M) + K) + F(still_running)
// Alternately, instead of counting iterations of the outer loop
// we could count the # of threads visited in the inner loop, above.
// 9. On windows consider using the return value from SwitchThreadTo()
// to drive subsequent spin/SwitchThreadTo()/Sleep(N) decisions.
if (int(iterations) == DeferPollingPageLoopCount) {
guarantee (PageArmed == 0, "invariant") ;
PageArmed = 1 ;
os::make_polling_page_unreadable();
}
// Instead of (ncpus > 1) consider either (still_running < (ncpus + EPSILON)) or
// ((still_running + _waiting_to_block - TryingToBlock)) < ncpus)
++steps ;
if (ncpus > 1 && steps < SafepointSpinBeforeYield) {
SpinPause() ; // MP-Polite spin
} else
if (steps < DeferThrSuspendLoopCount) {
os::naked_yield() ;
} else {
os::naked_short_sleep(1);
}
iterations ++ ;
}
assert(iterations < (uint)max_jint, "We have been iterating in the safepoint loop too long");
}
assert(still_running == 0, "sanity check");
if (PrintSafepointStatistics) {
update_statistics_on_spin_end();
}
// wait until all threads are stopped
while (_waiting_to_block > 0) {
log_debug(safepoint)("Waiting for %d thread(s) to block", _waiting_to_block);
if (!SafepointTimeout || timeout_error_printed) {
Safepoint_lock->wait(true); // true, means with no safepoint checks
} else {
// Compute remaining time
jlong remaining_time = safepoint_limit_time - os::javaTimeNanos();
// If there is no remaining time, then there is an error
if (remaining_time < 0 || Safepoint_lock->wait(true, remaining_time / MICROUNITS)) {
print_safepoint_timeout(_blocking_timeout);
}
}
}
assert(_waiting_to_block == 0, "sanity check");
#ifndef PRODUCT
if (SafepointTimeout) {
jlong current_time = os::javaTimeNanos();
if (safepoint_limit_time < current_time) {
tty->print_cr("# SafepointSynchronize: Finished after "
INT64_FORMAT_W(6) " ms",
((current_time - safepoint_limit_time) / MICROUNITS +
(jlong)SafepointTimeoutDelay));
}
}
#endif
assert((_safepoint_counter & 0x1) == 0, "must be even");
assert(Threads_lock->owned_by_self(), "must hold Threads_lock");
_safepoint_counter ++;
// Record state
_state = _synchronized;
OrderAccess::fence();
#ifdef ASSERT
for (JavaThread *cur = Threads::first(); cur != NULL; cur = cur->next()) {
// make sure all the threads were visited
assert(cur->was_visited_for_critical_count(), "missed a thread");
}
#endif // ASSERT
// Update the count of active JNI critical regions
GC_locker::set_jni_lock_count(_current_jni_active_count);
if (log_is_enabled(Debug, safepoint)) {
VM_Operation *op = VMThread::vm_operation();
log_debug(safepoint)("Entering safepoint region: %s",
(op != NULL) ? op->name() : "no vm operation");
}
RuntimeService::record_safepoint_synchronized();
if (PrintSafepointStatistics) {
update_statistics_on_sync_end(os::javaTimeNanos());
}
// Call stuff that needs to be run when a safepoint is just about to be completed
do_cleanup_tasks();
if (PrintSafepointStatistics) {
// Record how much time spend on the above cleanup tasks
update_statistics_on_cleanup_end(os::javaTimeNanos());
}
}
static bool enabled() {
return UseParallelGC &&
UseAdaptiveSizePolicy &&
log_is_enabled(Debug, gc, ergo);
}
oop StackWalk::fetchFirstBatch(BaseFrameStream& stream, Handle stackStream,
jlong mode, int skip_frames, int frame_count,
int start_index, objArrayHandle frames_array, TRAPS) {
methodHandle m_doStackWalk(THREAD, Universe::do_stack_walk_method());
{
Klass* stackWalker_klass = SystemDictionary::StackWalker_klass();
Klass* abstractStackWalker_klass = SystemDictionary::AbstractStackWalker_klass();
while (!stream.at_end()) {
InstanceKlass* ik = stream.method()->method_holder();
if (ik != stackWalker_klass &&
ik != abstractStackWalker_klass && ik->super() != abstractStackWalker_klass) {
break;
}
if (log_is_enabled(Debug, stackwalk)) {
ResourceMark rm(THREAD);
outputStream* st = Log(stackwalk)::debug_stream();
st->print(" skip ");
stream.method()->print_short_name(st);
st->cr();
}
stream.next();
}
// stack frame has been traversed individually and resume stack walk
// from the stack frame at depth == skip_frames.
for (int n=0; n < skip_frames && !stream.at_end(); stream.next(), n++) {
if (log_is_enabled(Debug, stackwalk)) {
ResourceMark rm(THREAD);
outputStream* st = Log(stackwalk)::debug_stream();
st->print(" skip ");
stream.method()->print_short_name(st);
st->cr();
}
}
}
int end_index = start_index;
int numFrames = 0;
if (!stream.at_end()) {
numFrames = fill_in_frames(mode, stream, frame_count, start_index,
frames_array, end_index, CHECK_NULL);
if (numFrames < 1) {
THROW_MSG_(vmSymbols::java_lang_InternalError(), "stack walk: decode failed", NULL);
}
}
// JVM_CallStackWalk walks the stack and fills in stack frames, then calls to
// Java method java.lang.StackStreamFactory.AbstractStackWalker::doStackWalk
// which calls the implementation to consume the stack frames.
// When JVM_CallStackWalk returns, it invalidates the stack stream.
JavaValue result(T_OBJECT);
JavaCallArguments args(stackStream);
args.push_long(stream.address_value());
args.push_int(skip_frames);
args.push_int(frame_count);
args.push_int(start_index);
args.push_int(end_index);
// Link the thread and vframe stream into the callee-visible object
stream.setup_magic_on_entry(frames_array);
JavaCalls::call(&result, m_doStackWalk, &args, THREAD);
// Do this before anything else happens, to disable any lingering stream objects
bool ok = stream.cleanup_magic_on_exit(frames_array);
// Throw pending exception if we must
(void) (CHECK_NULL);
if (!ok) {
THROW_MSG_(vmSymbols::java_lang_InternalError(), "doStackWalk: corrupted buffers on exit", NULL);
}
// Return normally
return (oop)result.get_jobject();
}
bool AdaptiveSizePolicy::print() const {
assert(UseAdaptiveSizePolicy, "UseAdaptiveSizePolicy need to be enabled.");
if (!log_is_enabled(Debug, gc, ergo)) {
return false;
}
// Print goal for which action is needed.
char* action = NULL;
bool change_for_pause = false;
if ((change_old_gen_for_maj_pauses() ==
decrease_old_gen_for_maj_pauses_true) ||
(change_young_gen_for_min_pauses() ==
decrease_young_gen_for_min_pauses_true)) {
action = (char*) " *** pause time goal ***";
change_for_pause = true;
} else if ((change_old_gen_for_throughput() ==
increase_old_gen_for_throughput_true) ||
(change_young_gen_for_throughput() ==
increase_young_gen_for_througput_true)) {
action = (char*) " *** throughput goal ***";
} else if (decrease_for_footprint()) {
action = (char*) " *** reduced footprint ***";
} else {
// No actions were taken. This can legitimately be the
// situation if not enough data has been gathered to make
// decisions.
return false;
}
// Pauses
// Currently the size of the old gen is only adjusted to
// change the major pause times.
char* young_gen_action = NULL;
char* tenured_gen_action = NULL;
char* shrink_msg = (char*) "(attempted to shrink)";
char* grow_msg = (char*) "(attempted to grow)";
char* no_change_msg = (char*) "(no change)";
if (change_young_gen_for_min_pauses() ==
decrease_young_gen_for_min_pauses_true) {
young_gen_action = shrink_msg;
} else if (change_for_pause) {
young_gen_action = no_change_msg;
}
if (change_old_gen_for_maj_pauses() == decrease_old_gen_for_maj_pauses_true) {
tenured_gen_action = shrink_msg;
} else if (change_for_pause) {
tenured_gen_action = no_change_msg;
}
// Throughput
if (change_old_gen_for_throughput() == increase_old_gen_for_throughput_true) {
assert(change_young_gen_for_throughput() ==
increase_young_gen_for_througput_true,
"Both generations should be growing");
young_gen_action = grow_msg;
tenured_gen_action = grow_msg;
} else if (change_young_gen_for_throughput() ==
increase_young_gen_for_througput_true) {
// Only the young generation may grow at start up (before
// enough full collections have been done to grow the old generation).
young_gen_action = grow_msg;
tenured_gen_action = no_change_msg;
}
// Minimum footprint
if (decrease_for_footprint() != 0) {
young_gen_action = shrink_msg;
tenured_gen_action = shrink_msg;
}
log_debug(gc, ergo)("UseAdaptiveSizePolicy actions to meet %s", action);
log_debug(gc, ergo)(" GC overhead (%%)");
log_debug(gc, ergo)(" Young generation: %7.2f\t %s",
100.0 * avg_minor_gc_cost()->average(), young_gen_action);
log_debug(gc, ergo)(" Tenured generation: %7.2f\t %s",
100.0 * avg_major_gc_cost()->average(), tenured_gen_action);
return true;
}
