void MConHandle::Close()
{
// Если установлен указатель на хэндл буфера - закрывать не будем
if (mpp_OutBuffer && *mpp_OutBuffer && (*mpp_OutBuffer != INVALID_HANDLE_VALUE))
{
return;
}
if (mh_Handle != INVALID_HANDLE_VALUE)
{
if (mn_StdMode)
{
LogHandle(Event::e_CloseHandleStd, mh_Handle);
mh_Handle = INVALID_HANDLE_VALUE;
}
else
{
HANDLE h = mh_Handle;
LogHandle(Event::e_CloseHandleStd, h);
mh_Handle = INVALID_HANDLE_VALUE;
mb_OpenFailed = FALSE;
CloseHandle(h);
}
}
};
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);
}
void Test_log_length() {
remove("loglengthoutput.txt");
// Write long message to output file
ResourceMark rm;
LogHandle(logging) log;
bool success = LogConfiguration::parse_log_arguments("loglengthoutput.txt", "logging=trace",
NULL, NULL, log.error_stream());
assert(success, "test unable to configure logging");
log.trace("01:1234567890-"
"02:1234567890-"
"03:1234567890-"
"04:1234567890-"
"05:1234567890-"
"06:1234567890-"
"07:1234567890-"
"08:1234567890-"
"09:1234567890-"
"10:1234567890-"
"11:1234567890-"
"12:1234567890-"
"13:1234567890-"
"14:1234567890-"
"15:1234567890-"
"16:1234567890-"
"17:1234567890-"
"18:1234567890-"
"19:1234567890-"
"20:1234567890-"
"21:1234567890-"
"22:1234567890-"
"23:1234567890-"
"24:1234567890-"
"25:1234567890-"
"26:1234567890-"
"27:1234567890-"
"28:1234567890-"
"29:1234567890-"
"30:1234567890-"
"31:1234567890-"
"32:1234567890-"
"33:1234567890-"
"34:1234567890-"
"35:1234567890-"
"36:1234567890-"
"37:1234567890-");
LogConfiguration::parse_log_arguments("loglengthoutput.txt", "all=off",
NULL, NULL, log.error_stream());
// Look for end of message in output file
FILE* fp = fopen("loglengthoutput.txt", "r");
assert(fp, "File read error");
char output[600];
if (fgets(output, 600, fp) != NULL) {
assert(strstr(output, "37:1234567890-"), "logging print size error");
}
fclose(fp);
remove("loglengthoutput.txt");
}
void CWsWindow::StatusDump(TDes &aBuf)
{
_LIT(KStatusString1,"CWsWindow[0x%x]RWindow[0x%x,%d],Pos(%d,%d),Size(%d,%d)");
_LIT(KStatusString3,",Mode=%d");
_LIT(KStatusInvisible,",Inv");
aBuf.AppendFormat(KStatusString1,this,iClientHandle,LogHandle(),iRel.iTl.iX,iRel.iTl.iY,Size().iWidth,Size().iHeight);
aBuf.AppendFormat(KStatusString3,(TInt)iScreen->DisplayMode());
if (!IsVisible())
aBuf.Append(KStatusInvisible);
}
void G1StringDedupTable::print_statistics() {
LogHandle(gc, stringdedup) log;
log.debug(" [Table]");
log.debug(" [Memory Usage: " G1_STRDEDUP_BYTES_FORMAT_NS "]",
G1_STRDEDUP_BYTES_PARAM(_table->_size * sizeof(G1StringDedupEntry*) + (_table->_entries + _entry_cache->size()) * sizeof(G1StringDedupEntry)));
log.debug(" [Size: " SIZE_FORMAT ", Min: " SIZE_FORMAT ", Max: " SIZE_FORMAT "]", _table->_size, _min_size, _max_size);
log.debug(" [Entries: " UINTX_FORMAT ", Load: " G1_STRDEDUP_PERCENT_FORMAT_NS ", Cached: " UINTX_FORMAT ", Added: " UINTX_FORMAT ", Removed: " UINTX_FORMAT "]",
_table->_entries, (double)_table->_entries / (double)_table->_size * 100.0, _entry_cache->size(), _entries_added, _entries_removed);
log.debug(" [Resize Count: " UINTX_FORMAT ", Shrink Threshold: " UINTX_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT_NS "), Grow Threshold: " UINTX_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT_NS ")]",
_resize_count, _table->_shrink_threshold, _shrink_load_factor * 100.0, _table->_grow_threshold, _grow_load_factor * 100.0);
log.debug(" [Rehash Count: " UINTX_FORMAT ", Rehash Threshold: " UINTX_FORMAT ", Hash Seed: 0x%x]", _rehash_count, _rehash_threshold, _table->_hash_seed);
log.debug(" [Age Threshold: " UINTX_FORMAT "]", StringDeduplicationAgeThreshold);
}
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();
}
}
MConHandle::operator const HANDLE()
{
if (mpp_OutBuffer && *mpp_OutBuffer && (*mpp_OutBuffer != INVALID_HANDLE_VALUE))
{
LogHandle(Event::e_GetHandlePtr, *mpp_OutBuffer);
return *mpp_OutBuffer;
}
if (mh_Handle == INVALID_HANDLE_VALUE)
{
if (mn_StdMode)
{
mh_Handle = GetStdHandle(mn_StdMode);
LogHandle(Event::e_CreateHandleStd, mh_Handle);
}
else
{
// Чтобы случайно не открыть хэндл несколько раз в разных потоках
MSectionLock CS; CS.Lock(&mcs_Handle, TRUE);
// Во время ожидания хэндл мог быт открыт в другом потоке
if (mh_Handle == INVALID_HANDLE_VALUE)
{
mh_Handle = CreateFileW(ms_Name, GENERIC_READ | GENERIC_WRITE, FILE_SHARE_READ | FILE_SHARE_WRITE,
0, OPEN_EXISTING, FILE_ATTRIBUTE_NORMAL, 0);
if (mh_Handle != INVALID_HANDLE_VALUE)
{
mb_OpenFailed = FALSE;
}
else
{
mn_LastError = GetLastError();
if (!mb_OpenFailed)
{
mb_OpenFailed = TRUE; // чтобы ошибка вываливалась только один раз!
char szErrMsg[512], szNameA[10], szSelfFull[MAX_PATH];
const char *pszSelf;
char *pszDot;
if (!GetModuleFileNameA(0,szSelfFull,MAX_PATH))
{
pszSelf = "???";
}
else
{
pszSelf = strrchr(szSelfFull, '\\');
if (pszSelf) pszSelf++; else pszSelf = szSelfFull;
pszDot = strrchr((char*)pszSelf, '.');
if (pszDot) *pszDot = 0;
}
WideCharToMultiByte(CP_OEMCP, 0, ms_Name, -1, szNameA, sizeof(szNameA), 0,0);
_wsprintfA(szErrMsg, SKIPLEN(countof(szErrMsg)) "%s: CreateFile(%s) failed, ErrCode=0x%08X\n", pszSelf, szNameA, mn_LastError);
HANDLE h = GetStdHandle(STD_OUTPUT_HANDLE);
if (h && h!=INVALID_HANDLE_VALUE)
{
DWORD dwWritten = 0;
WriteFile(h, szErrMsg, lstrlenA(szErrMsg), &dwWritten, 0);
}
}
}
LogHandle(Event::e_CreateHandle, mh_Handle);
}
}
}
LogHandle(Event::e_GetHandle, mh_Handle);
return mh_Handle;
};
// 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());
}
}
