0N/A/*
2362N/A * Copyright (c) 1997, 2011, Oracle and/or its affiliates. All rights reserved.
0N/A * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
0N/A *
0N/A * This code is free software; you can redistribute it and/or modify it
0N/A * under the terms of the GNU General Public License version 2 only, as
2362N/A * published by the Free Software Foundation.
0N/A *
2362N/A * This code is distributed in the hope that it will be useful, but WITHOUT
0N/A * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
0N/A * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
0N/A * version 2 for more details (a copy is included in the LICENSE file that
0N/A * accompanied this code).
0N/A *
0N/A * You should have received a copy of the GNU General Public License version
0N/A * 2 along with this work; if not, write to the Free Software Foundation,
0N/A * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
0N/A *
0N/A * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
0N/A * or visit www.oracle.com if you need additional information or have any
2362N/A * questions.
2362N/A *
2362N/A */
0N/A
0N/A#include "precompiled.hpp"
0N/A#include "code/codeCache.hpp"
0N/A#include "code/nmethod.hpp"
0N/A#include "compiler/compileBroker.hpp"
0N/A#include "memory/resourceArea.hpp"
0N/A#include "oops/methodOop.hpp"
0N/A#include "runtime/atomic.hpp"
0N/A#include "runtime/compilationPolicy.hpp"
0N/A#include "runtime/mutexLocker.hpp"
0N/A#include "runtime/os.hpp"
0N/A#include "runtime/sweeper.hpp"
0N/A#include "runtime/vm_operations.hpp"
0N/A#include "trace/tracing.hpp"
0N/A#include "utilities/events.hpp"
0N/A#include "utilities/xmlstream.hpp"
0N/A
0N/A#ifdef ASSERT
0N/A
0N/A#define SWEEP(nm) record_sweep(nm, __LINE__)
0N/A// Sweeper logging code
0N/Aclass SweeperRecord {
0N/A public:
0N/A int traversal;
0N/A int invocation;
0N/A int compile_id;
0N/A long traversal_mark;
0N/A int state;
0N/A const char* kind;
0N/A address vep;
0N/A address uep;
0N/A int line;
0N/A
0N/A void print() {
0N/A tty->print_cr("traversal = %d invocation = %d compile_id = %d %s uep = " PTR_FORMAT " vep = "
0N/A PTR_FORMAT " state = %d traversal_mark %d line = %d",
0N/A traversal,
0N/A invocation,
0N/A compile_id,
0N/A kind == NULL ? "" : kind,
0N/A uep,
0N/A vep,
0N/A state,
0N/A traversal_mark,
0N/A line);
0N/A }
0N/A};
0N/A
0N/Astatic int _sweep_index = 0;
0N/Astatic SweeperRecord* _records = NULL;
0N/A
0N/Avoid NMethodSweeper::report_events(int id, address entry) {
0N/A if (_records != NULL) {
0N/A for (int i = _sweep_index; i < SweeperLogEntries; i++) {
0N/A if (_records[i].uep == entry ||
0N/A _records[i].vep == entry ||
0N/A _records[i].compile_id == id) {
0N/A _records[i].print();
0N/A }
0N/A }
0N/A for (int i = 0; i < _sweep_index; i++) {
0N/A if (_records[i].uep == entry ||
0N/A _records[i].vep == entry ||
0N/A _records[i].compile_id == id) {
0N/A _records[i].print();
0N/A }
0N/A }
0N/A }
0N/A}
0N/A
0N/Avoid NMethodSweeper::report_events() {
0N/A if (_records != NULL) {
0N/A for (int i = _sweep_index; i < SweeperLogEntries; i++) {
0N/A // skip empty records
0N/A if (_records[i].vep == NULL) continue;
0N/A _records[i].print();
0N/A }
0N/A for (int i = 0; i < _sweep_index; i++) {
0N/A // skip empty records
0N/A if (_records[i].vep == NULL) continue;
0N/A _records[i].print();
0N/A }
0N/A }
0N/A}
0N/A
0N/Avoid NMethodSweeper::record_sweep(nmethod* nm, int line) {
0N/A if (_records != NULL) {
0N/A _records[_sweep_index].traversal = _traversals;
0N/A _records[_sweep_index].traversal_mark = nm->_stack_traversal_mark;
0N/A _records[_sweep_index].invocation = _invocations;
0N/A _records[_sweep_index].compile_id = nm->compile_id();
0N/A _records[_sweep_index].kind = nm->compile_kind();
0N/A _records[_sweep_index].state = nm->_state;
0N/A _records[_sweep_index].vep = nm->verified_entry_point();
0N/A _records[_sweep_index].uep = nm->entry_point();
0N/A _records[_sweep_index].line = line;
0N/A
0N/A _sweep_index = (_sweep_index + 1) % SweeperLogEntries;
0N/A }
0N/A}
0N/A#else
0N/A#define SWEEP(nm)
0N/A#endif
0N/A
0N/A
0N/Along NMethodSweeper::_traversals = 0; // No. of stack traversals performed
0N/Anmethod* NMethodSweeper::_current = NULL; // Current nmethod
0N/Aint NMethodSweeper::_seen = 0 ; // No. of nmethods we have currently processed in current pass of CodeCache
0N/Aint NMethodSweeper::_flushed_count = 0; // Nof. nmethods flushed in current sweep
0N/Aint NMethodSweeper::_zombified_count = 0; // Nof. nmethods made zombie in current sweep
0N/Aint NMethodSweeper::_marked_count = 0; // Nof. nmethods marked for reclaim in current sweep
0N/A
0N/Avolatile int NMethodSweeper::_invocations = 0; // No. of invocations left until we are completed with this pass
0N/Avolatile int NMethodSweeper::_sweep_started = 0; // Whether a sweep is in progress.
0N/A
0N/Ajint NMethodSweeper::_locked_seen = 0;
0N/Ajint NMethodSweeper::_not_entrant_seen_on_stack = 0;
0N/Abool NMethodSweeper::_rescan = false;
0N/Abool NMethodSweeper::_do_sweep = false;
0N/Abool NMethodSweeper::_was_full = false;
0N/Ajint NMethodSweeper::_advise_to_sweep = 0;
0N/Ajlong NMethodSweeper::_last_was_full = 0;
0N/Auint NMethodSweeper::_highest_marked = 0;
0N/Along NMethodSweeper::_was_full_traversal = 0;
0N/A
0N/Aint NMethodSweeper::_number_of_flushes = 0; // Total of full traversals caused by full cache
0N/Aint NMethodSweeper::_total_nof_methods_reclaimed = 0;
0N/Ajlong NMethodSweeper::_total_time_sweeping = 0;
0N/Ajlong NMethodSweeper::_total_time_this_sweep = 0;
0N/Ajlong NMethodSweeper::_peak_sweep_time = 0;
0N/Ajlong NMethodSweeper::_peak_sweep_fraction_time = 0;
0N/Ajlong NMethodSweeper::_total_disconnect_time = 0;
0N/Ajlong NMethodSweeper::_peak_disconnect_time = 0;
0N/A
0N/Aclass MarkActivationClosure: public CodeBlobClosure {
0N/Apublic:
0N/A virtual void do_code_blob(CodeBlob* cb) {
0N/A // If we see an activation belonging to a non_entrant nmethod, we mark it.
0N/A if (cb->is_nmethod() && ((nmethod*)cb)->is_not_entrant()) {
0N/A ((nmethod*)cb)->mark_as_seen_on_stack();
0N/A }
0N/A }
0N/A};
0N/Astatic MarkActivationClosure mark_activation_closure;
0N/A
0N/Avoid NMethodSweeper::scan_stacks() {
0N/A assert(SafepointSynchronize::is_at_safepoint(), "must be executed at a safepoint");
0N/A if (!MethodFlushing) return;
0N/A _do_sweep = true;
0N/A
0N/A // No need to synchronize access, since this is always executed at a
0N/A // safepoint. If we aren't in the middle of scan and a rescan
0N/A // hasn't been requested then just return. If UseCodeCacheFlushing is on and
0N/A // code cache flushing is in progress, don't skip sweeping to help make progress
0N/A // clearing space in the code cache.
0N/A if ((_current == NULL && !_rescan) && !(UseCodeCacheFlushing && !CompileBroker::should_compile_new_jobs())) {
0N/A _do_sweep = false;
0N/A return;
0N/A }
0N/A
0N/A // Make sure CompiledIC_lock in unlocked, since we might update some
0N/A // inline caches. If it is, we just bail-out and try later.
0N/A if (CompiledIC_lock->is_locked() || Patching_lock->is_locked()) return;
0N/A
0N/A // Check for restart
0N/A assert(CodeCache::find_blob_unsafe(_current) == _current, "Sweeper nmethod cached state invalid");
0N/A if (_current == NULL) {
0N/A _seen = 0;
0N/A _invocations = NmethodSweepFraction;
0N/A _current = CodeCache::first_nmethod();
0N/A _traversals += 1;
0N/A _total_time_this_sweep = 0;
0N/A
0N/A if (PrintMethodFlushing) {
0N/A tty->print_cr("### Sweep: stack traversal %d", _traversals);
0N/A }
0N/A Threads::nmethods_do(&mark_activation_closure);
0N/A
0N/A // reset the flags since we started a scan from the beginning.
0N/A _rescan = false;
0N/A _locked_seen = 0;
0N/A _not_entrant_seen_on_stack = 0;
0N/A }
0N/A
0N/A if (UseCodeCacheFlushing) {
0N/A if (!CodeCache::needs_flushing()) {
0N/A // scan_stacks() runs during a safepoint, no race with setters
0N/A _advise_to_sweep = 0;
0N/A }
0N/A
0N/A if (was_full()) {
0N/A // There was some progress so attempt to restart the compiler
0N/A jlong now = os::javaTimeMillis();
0N/A jlong max_interval = (jlong)MinCodeCacheFlushingInterval * (jlong)1000;
0N/A jlong curr_interval = now - _last_was_full;
0N/A if ((!CodeCache::needs_flushing()) && (curr_interval > max_interval)) {
0N/A CompileBroker::set_should_compile_new_jobs(CompileBroker::run_compilation);
0N/A set_was_full(false);
0N/A
0N/A // Update the _last_was_full time so we can tell how fast the
0N/A // code cache is filling up
0N/A _last_was_full = os::javaTimeMillis();
0N/A
0N/A log_sweep("restart_compiler");
0N/A }
0N/A }
0N/A }
0N/A}
0N/A
0N/Avoid NMethodSweeper::possibly_sweep() {
0N/A assert(JavaThread::current()->thread_state() == _thread_in_vm, "must run in vm mode");
0N/A if ((!MethodFlushing) || (!_do_sweep)) return;
0N/A
0N/A if (_invocations > 0) {
0N/A // Only one thread at a time will sweep
0N/A jint old = Atomic::cmpxchg( 1, &_sweep_started, 0 );
0N/A if (old != 0) {
0N/A return;
0N/A }
0N/A#ifdef ASSERT
0N/A if (LogSweeper && _records == NULL) {
// Create the ring buffer for the logging code
_records = NEW_C_HEAP_ARRAY(SweeperRecord, SweeperLogEntries, mtGC);
memset(_records, 0, sizeof(SweeperRecord) * SweeperLogEntries);
}
#endif
if (_invocations > 0) {
sweep_code_cache();
_invocations--;
}
_sweep_started = 0;
}
}
void NMethodSweeper::sweep_code_cache() {
jlong sweep_start_counter = os::elapsed_counter();
_flushed_count = 0;
_zombified_count = 0;
_marked_count = 0;
if (PrintMethodFlushing && Verbose) {
tty->print_cr("### Sweep at %d out of %d. Invocations left: %d", _seen, CodeCache::nof_nmethods(), _invocations);
}
// We want to visit all nmethods after NmethodSweepFraction
// invocations so divide the remaining number of nmethods by the
// remaining number of invocations. This is only an estimate since
// the number of nmethods changes during the sweep so the final
// stage must iterate until it there are no more nmethods.
int todo = (CodeCache::nof_nmethods() - _seen) / _invocations;
assert(!SafepointSynchronize::is_at_safepoint(), "should not be in safepoint when we get here");
assert(!CodeCache_lock->owned_by_self(), "just checking");
{
MutexLockerEx mu(CodeCache_lock, Mutex::_no_safepoint_check_flag);
// The last invocation iterates until there are no more nmethods
for (int i = 0; (i < todo || _invocations == 1) && _current != NULL; i++) {
if (SafepointSynchronize::is_synchronizing()) { // Safepoint request
if (PrintMethodFlushing && Verbose) {
tty->print_cr("### Sweep at %d out of %d, invocation: %d, yielding to safepoint", _seen, CodeCache::nof_nmethods(), _invocations);
}
MutexUnlockerEx mu(CodeCache_lock, Mutex::_no_safepoint_check_flag);
assert(Thread::current()->is_Java_thread(), "should be java thread");
JavaThread* thread = (JavaThread*)Thread::current();
ThreadBlockInVM tbivm(thread);
thread->java_suspend_self();
}
// Since we will give up the CodeCache_lock, always skip ahead
// to the next nmethod. Other blobs can be deleted by other
// threads but nmethods are only reclaimed by the sweeper.
nmethod* next = CodeCache::next_nmethod(_current);
// Now ready to process nmethod and give up CodeCache_lock
{
MutexUnlockerEx mu(CodeCache_lock, Mutex::_no_safepoint_check_flag);
process_nmethod(_current);
}
_seen++;
_current = next;
}
}
assert(_invocations > 1 || _current == NULL, "must have scanned the whole cache");
if (_current == NULL && !_rescan && (_locked_seen || _not_entrant_seen_on_stack)) {
// we've completed a scan without making progress but there were
// nmethods we were unable to process either because they were
// locked or were still on stack. We don't have to aggresively
// clean them up so just stop scanning. We could scan once more
// but that complicates the control logic and it's unlikely to
// matter much.
if (PrintMethodFlushing) {
tty->print_cr("### Couldn't make progress on some nmethods so stopping sweep");
}
}
jlong sweep_end_counter = os::elapsed_counter();
jlong sweep_time = sweep_end_counter - sweep_start_counter;
_total_time_sweeping += sweep_time;
_total_time_this_sweep += sweep_time;
_peak_sweep_fraction_time = MAX2(sweep_time, _peak_sweep_fraction_time);
_total_nof_methods_reclaimed += _flushed_count;
EventSweepCodeCache event(UNTIMED);
if (event.should_commit()) {
event.set_starttime(sweep_start_counter);
event.set_endtime(sweep_end_counter);
event.set_sweepIndex(_traversals);
event.set_sweepFractionIndex(NmethodSweepFraction - _invocations + 1);
event.set_sweptCount(todo);
event.set_flushedCount(_flushed_count);
event.set_markedCount(_marked_count);
event.set_zombifiedCount(_zombified_count);
event.commit();
}
#ifdef ASSERT
if(PrintMethodFlushing) {
tty->print_cr("### sweeper: sweep time(%d): " INT64_FORMAT, _invocations, (jlong)sweep_time);
}
#endif
if (_invocations == 1) {
_peak_sweep_time = MAX2(_peak_sweep_time, _total_time_this_sweep);
log_sweep("finished");
}
}
class NMethodMarker: public StackObj {
private:
CompilerThread* _thread;
public:
NMethodMarker(nmethod* nm) {
_thread = CompilerThread::current();
_thread->set_scanned_nmethod(nm);
}
~NMethodMarker() {
_thread->set_scanned_nmethod(NULL);
}
};
void NMethodSweeper::process_nmethod(nmethod *nm) {
assert(!CodeCache_lock->owned_by_self(), "just checking");
// Make sure this nmethod doesn't get unloaded during the scan,
// since the locks acquired below might safepoint.
NMethodMarker nmm(nm);
SWEEP(nm);
// Skip methods that are currently referenced by the VM
if (nm->is_locked_by_vm()) {
// But still remember to clean-up inline caches for alive nmethods
if (nm->is_alive()) {
// Clean-up all inline caches that points to zombie/non-reentrant methods
MutexLocker cl(CompiledIC_lock);
nm->cleanup_inline_caches();
SWEEP(nm);
} else {
_locked_seen++;
SWEEP(nm);
}
return;
}
if (nm->is_zombie()) {
// If it is first time, we see nmethod then we mark it. Otherwise,
// we reclame it. When we have seen a zombie method twice, we know that
// there are no inline caches that refer to it.
if (nm->is_marked_for_reclamation()) {
assert(!nm->is_locked_by_vm(), "must not flush locked nmethods");
if (PrintMethodFlushing && Verbose) {
tty->print_cr("### Nmethod %3d/" PTR_FORMAT " (marked for reclamation) being flushed", nm->compile_id(), nm);
}
MutexLockerEx mu(CodeCache_lock, Mutex::_no_safepoint_check_flag);
nm->flush();
_flushed_count++;
} else {
if (PrintMethodFlushing && Verbose) {
tty->print_cr("### Nmethod %3d/" PTR_FORMAT " (zombie) being marked for reclamation", nm->compile_id(), nm);
}
nm->mark_for_reclamation();
_marked_count++;
_rescan = true;
SWEEP(nm);
}
} else if (nm->is_not_entrant()) {
// If there is no current activations of this method on the
// stack we can safely convert it to a zombie method
if (nm->can_not_entrant_be_converted()) {
if (PrintMethodFlushing && Verbose) {
tty->print_cr("### Nmethod %3d/" PTR_FORMAT " (not entrant) being made zombie", nm->compile_id(), nm);
}
nm->make_zombie();
_zombified_count++;
_rescan = true;
SWEEP(nm);
} else {
// Still alive, clean up its inline caches
MutexLocker cl(CompiledIC_lock);
nm->cleanup_inline_caches();
// we coudn't transition this nmethod so don't immediately
// request a rescan. If this method stays on the stack for a
// long time we don't want to keep rescanning the code cache.
_not_entrant_seen_on_stack++;
SWEEP(nm);
}
} else if (nm->is_unloaded()) {
// Unloaded code, just make it a zombie
if (PrintMethodFlushing && Verbose)
tty->print_cr("### Nmethod %3d/" PTR_FORMAT " (unloaded) being made zombie", nm->compile_id(), nm);
if (nm->is_osr_method()) {
// No inline caches will ever point to osr methods, so we can just remove it
MutexLockerEx mu(CodeCache_lock, Mutex::_no_safepoint_check_flag);
SWEEP(nm);
nm->flush();
_flushed_count++;
} else {
nm->make_zombie();
_zombified_count++;
_rescan = true;
SWEEP(nm);
}
} else {
assert(nm->is_alive(), "should be alive");
if (UseCodeCacheFlushing) {
if ((nm->method()->code() != nm) && !(nm->is_locked_by_vm()) && !(nm->is_osr_method()) &&
(_traversals > _was_full_traversal+2) && (((uint)nm->compile_id()) < _highest_marked) &&
CodeCache::needs_flushing()) {
// This method has not been called since the forced cleanup happened
nm->make_not_entrant();
}
}
// Clean-up all inline caches that points to zombie/non-reentrant methods
MutexLocker cl(CompiledIC_lock);
nm->cleanup_inline_caches();
SWEEP(nm);
}
}
// Code cache unloading: when compilers notice the code cache is getting full,
// they will call a vm op that comes here. This code attempts to speculatively
// unload the oldest half of the nmethods (based on the compile job id) by
// saving the old code in a list in the CodeCache. Then
// execution resumes. If a method so marked is not called by the second sweeper
// stack traversal after the current one, the nmethod will be marked non-entrant and
// got rid of by normal sweeping. If the method is called, the methodOop's
// _code field is restored and the methodOop/nmethod
// go back to their normal state.
void NMethodSweeper::handle_full_code_cache(bool is_full) {
// Only the first one to notice can advise us to start early cleaning
if (!is_full){
jint old = Atomic::cmpxchg( 1, &_advise_to_sweep, 0 );
if (old != 0) {
return;
}
}
if (is_full) {
// Since code cache is full, immediately stop new compiles
bool did_set = CompileBroker::set_should_compile_new_jobs(CompileBroker::stop_compilation);
if (!did_set){
// only the first to notice can start the cleaning,
// others will go back and block
return;
}
set_was_full(true);
// If we run out within MinCodeCacheFlushingInterval of the last unload time, give up
jlong now = os::javaTimeMillis();
jlong max_interval = (jlong)MinCodeCacheFlushingInterval * (jlong)1000;
jlong curr_interval = now - _last_was_full;
if (curr_interval < max_interval) {
_rescan = true;
log_sweep("disable_compiler", "flushing_interval='" UINT64_FORMAT "'",
curr_interval/1000);
return;
}
}
VM_HandleFullCodeCache op(is_full);
VMThread::execute(&op);
// rescan again as soon as possible
_rescan = true;
}
void NMethodSweeper::speculative_disconnect_nmethods(bool is_full) {
// If there was a race in detecting full code cache, only run
// one vm op for it or keep the compiler shut off
if ((!was_full()) && (is_full)) {
if (!CodeCache::needs_flushing()) {
log_sweep("restart_compiler");
CompileBroker::set_should_compile_new_jobs(CompileBroker::run_compilation);
return;
}
}
jlong disconnect_start_counter = os::elapsed_counter();
// Traverse the code cache trying to dump the oldest nmethods
uint curr_max_comp_id = CompileBroker::get_compilation_id();
uint flush_target = ((curr_max_comp_id - _highest_marked) >> 1) + _highest_marked;
log_sweep("start_cleaning");
nmethod* nm = CodeCache::alive_nmethod(CodeCache::first());
jint disconnected = 0;
jint made_not_entrant = 0;
while ((nm != NULL)){
uint curr_comp_id = nm->compile_id();
// OSR methods cannot be flushed like this. Also, don't flush native methods
// since they are part of the JDK in most cases
if (nm->is_in_use() && (!nm->is_osr_method()) && (!nm->is_locked_by_vm()) &&
(!nm->is_native_method()) && ((curr_comp_id < flush_target))) {
if ((nm->method()->code() == nm)) {
// This method has not been previously considered for
// unloading or it was restored already
CodeCache::speculatively_disconnect(nm);
disconnected++;
} else if (nm->is_speculatively_disconnected()) {
// This method was previously considered for preemptive unloading and was not called since then
CompilationPolicy::policy()->delay_compilation(nm->method());
nm->make_not_entrant();
made_not_entrant++;
}
if (curr_comp_id > _highest_marked) {
_highest_marked = curr_comp_id;
}
}
nm = CodeCache::alive_nmethod(CodeCache::next(nm));
}
log_sweep("stop_cleaning",
"disconnected='" UINT32_FORMAT "' made_not_entrant='" UINT32_FORMAT "'",
disconnected, made_not_entrant);
// Shut off compiler. Sweeper will start over with a new stack scan and
// traversal cycle and turn it back on if it clears enough space.
if (was_full()) {
_last_was_full = os::javaTimeMillis();
CompileBroker::set_should_compile_new_jobs(CompileBroker::stop_compilation);
}
jlong disconnect_end_counter = os::elapsed_counter();
jlong disconnect_time = disconnect_end_counter - disconnect_start_counter;
_total_disconnect_time += disconnect_time;
_peak_disconnect_time = MAX2(disconnect_time, _peak_disconnect_time);
EventCleanCodeCache event(UNTIMED);
if (event.should_commit()) {
event.set_starttime(disconnect_start_counter);
event.set_endtime(disconnect_end_counter);
event.set_disconnectedCount(disconnected);
event.set_madeNonEntrantCount(made_not_entrant);
event.commit();
}
_number_of_flushes++;
// After two more traversals the sweeper will get rid of unrestored nmethods
_was_full_traversal = _traversals;
#ifdef ASSERT
if(PrintMethodFlushing && Verbose) {
tty->print_cr("### sweeper: unload time: " INT64_FORMAT, (jlong)disconnect_time);
}
#endif
}
// Print out some state information about the current sweep and the
// state of the code cache if it's requested.
void NMethodSweeper::log_sweep(const char* msg, const char* format, ...) {
if (PrintMethodFlushing) {
stringStream s;
// Dump code cache state into a buffer before locking the tty,
// because log_state() will use locks causing lock conflicts.
CodeCache::log_state(&s);
ttyLocker ttyl;
tty->print("### sweeper: %s ", msg);
if (format != NULL) {
va_list ap;
va_start(ap, format);
tty->vprint(format, ap);
va_end(ap);
}
tty->print_cr(s.as_string());
}
if (LogCompilation && (xtty != NULL)) {
stringStream s;
// Dump code cache state into a buffer before locking the tty,
// because log_state() will use locks causing lock conflicts.
CodeCache::log_state(&s);
ttyLocker ttyl;
xtty->begin_elem("sweeper state='%s' traversals='" INTX_FORMAT "' ", msg, (intx)traversal_count());
if (format != NULL) {
va_list ap;
va_start(ap, format);
xtty->vprint(format, ap);
va_end(ap);
}
xtty->print(s.as_string());
xtty->stamp();
xtty->end_elem();
}
}