diff --git a/src/java/com/threerings/presents/server/PresentsDObjectMgr.java b/src/java/com/threerings/presents/server/PresentsDObjectMgr.java index e132b8bac..17c7728ba 100644 --- a/src/java/com/threerings/presents/server/PresentsDObjectMgr.java +++ b/src/java/com/threerings/presents/server/PresentsDObjectMgr.java @@ -58,10 +58,10 @@ import com.threerings.presents.dobj.*; public class PresentsDObjectMgr implements RootDObjectManager, RunQueue, PresentsServer.Reporter { - /** Contains operational statistics that are tracked by the - * distributed object manager for a particular period of time (e.g. 5 - * minutes). The snapshot for the most recently completed period can - * be requested via {@link #getStats()}. . */ + /** Contains operational statistics that are tracked by the distributed + * object manager between {@link PresentsServer#Reporter} intervals. The + * snapshot for the most recently completed period can be requested via + * {@link #getStats()}. . */ public static class Stats { /** The largest size of the distributed object queue during the @@ -256,19 +256,6 @@ public class PresentsDObjectMgr _current.maxQueueSize = queueSize; } - // report and reset our largest queue size once every 5 minutes - long startMillis = start * 1000 / freq; - if (_nextStatsSnapshot < startMillis) { - _recent = _current; - _current = new Stats(); - if (_nextStatsSnapshot != 0L) { - _current.maxQueueSize = queueSize; - _nextStatsSnapshot += STATS_SNAPSHOT_INTERVAL; - } else { - _nextStatsSnapshot = startMillis + STATS_SNAPSHOT_INTERVAL; - } - } - try { if (unit instanceof Runnable) { // if this is a runnable, it's just an executable unit @@ -296,13 +283,13 @@ public class PresentsDObjectMgr // report excessively long units if (elapsed > 500000) { - Log.warning("Long dobj unit [unit=" + StringUtil.safeToString(unit) + + Log.warning("Long dobj unit [u=" + StringUtil.safeToString(unit) + " (" + StringUtil.shortClassName(unit) + ")" + ", time=" + (elapsed/1000) + "ms]."); } // periodically sample and record the time spent processing a unit - if (_eventCount % UNIT_PROFILING_INTERVAL == 0) { + if (UNIT_PROF_ENABLED && _eventCount % UNIT_PROF_INTERVAL == 0) { String cname; // do some jiggery pokery to get more fine grained profiling // details on certain "popular" unit types @@ -728,14 +715,27 @@ public class PresentsDObjectMgr public void appendReport (StringBuilder report, long now, long sinceLast) { report.append("* presents.PresentsDObjectMgr:\n"); - - report.append("- Unit profiles: ").append(_profiles.size()); + int queueSize = _evqueue.size(); + report.append("- Queue size: ").append(queueSize).append("\n"); + report.append("- Max queue size: ").append(_current.maxQueueSize); report.append("\n"); - for (Map.Entry entry : _profiles.entrySet()) { - report.append(" ").append(entry.getKey()); - report.append(" ").append(entry.getValue()); + report.append("- Units executed: ").append(_current.eventCount); + report.append("\n"); + + if (UNIT_PROF_ENABLED) { + report.append("- Unit profiles: ").append(_profiles.size()); report.append("\n"); + for (Map.Entry entry : _profiles.entrySet()) { + report.append(" ").append(entry.getKey()); + report.append(" ").append(entry.getValue()); + report.append("\n"); + } } + + // roll over stats + _recent = _current; + _current = new Stats(); + _current.maxQueueSize = queueSize; } /** @@ -1020,18 +1020,15 @@ public class PresentsDObjectMgr /** Used to track runtime statistics. */ protected Stats _recent = new Stats(), _current = _recent; - /** The time at which we last took a snapshot of our stats. */ - protected long _nextStatsSnapshot; + /** Whether or not unit profiling is enabled. */ + protected static final boolean UNIT_PROF_ENABLED = false; /** The frequency with which we take a profiling sample. */ - protected static final int UNIT_PROFILING_INTERVAL = 100; + protected static final int UNIT_PROF_INTERVAL = 100; /** The default size of an oid list refs vector. */ protected static final int DEFREFVEC_SIZE = 4; - /** The frequency with which we roll over our runtime stats. */ - protected static final long STATS_SNAPSHOT_INTERVAL = 5 * 60 * 1000L; - /** * This table maps event classes to helper methods that perform some * additional processing for particular events. diff --git a/src/java/com/threerings/presents/server/PresentsInvoker.java b/src/java/com/threerings/presents/server/PresentsInvoker.java index a7610dfa1..0ab10a255 100644 --- a/src/java/com/threerings/presents/server/PresentsInvoker.java +++ b/src/java/com/threerings/presents/server/PresentsInvoker.java @@ -23,8 +23,6 @@ package com.threerings.presents.server; import java.util.Iterator; -import com.samskivert.util.AuditLogger; -import com.samskivert.util.Histogram; import com.samskivert.util.Invoker; import com.samskivert.util.StringUtil; @@ -50,15 +48,6 @@ public class PresentsInvoker extends Invoker } } - /** - * Configures this manager with a log to which runtime statistics will - * be recorded. - */ - public void setStatsLog (AuditLogger logger) - { - _statslog = logger; - } - /** * Will do a sophisticated shutdown of both itself and the DObjectManager * thread. @@ -69,20 +58,33 @@ public class PresentsInvoker extends Invoker } // documentation inherited from interface - public void appendReport (StringBuilder buffer, long now, long sinceLast) + public void appendReport (StringBuilder buf, long now, long sinceLast) { - buffer.append("* presents.util.Invoker:\n"); - buffer.append("- Units executed: ").append(_unitsRun).append("\n"); - _unitsRun = 0; - for (Iterator iter = _tracker.keySet().iterator(); iter.hasNext(); ) { - Object key = iter.next(); - UnitProfile profile = (UnitProfile)_tracker.get(key); - if (key instanceof Class) { - key = StringUtil.shortClassName((Class)key); + buf.append("* presents.util.Invoker:\n"); + int qsize = _queue.size(); + buf.append("- Queue size: ").append(qsize).append("\n"); + synchronized (this) { + buf.append("- Max queue size: ").append(_maxQueueSize).append("\n"); + buf.append("- Units executed: ").append(_unitsRun).append("\n"); + _maxQueueSize = qsize; + _unitsRun = 0; + if (_currentUnit != null) { + String uname = StringUtil.safeToString(_currentUnit); + buf.append("- Current unit: ").append(uname).append(" "); + buf.append(now-_currentUnitStart).append("ms\n"); + } + } + + if (PresentsDObjectMgr.UNIT_PROF_ENABLED) { + for (Object key : _tracker.keySet()) { + UnitProfile profile = (UnitProfile)_tracker.get(key); + if (key instanceof Class) { + key = StringUtil.shortClassName((Class)key); + } + buf.append(" ").append(key).append(" "); + buf.append(profile).append("\n"); + profile.clear(); } - buffer.append(" ").append(key).append(" "); - buffer.append(profile).append("\n"); - profile.clear(); } } @@ -91,26 +93,28 @@ public class PresentsInvoker extends Invoker { super.willInvokeUnit(unit, start); - if (_statslog != null) { + int queueSize = _queue.size(); + synchronized (this) { // keep track of the largest queue size we've seen - int queueSize = _queue.size(); if (queueSize > _maxQueueSize) { _maxQueueSize = queueSize; } - // report and reset our largest queue size once every 5 minutes - if (_nextQueueReport < start) { - if (_nextQueueReport != 0L) { - _statslog.log("max_invoker_queue_size " + _maxQueueSize); - _maxQueueSize = queueSize; - _nextQueueReport += - PresentsDObjectMgr.STATS_SNAPSHOT_INTERVAL; + // note the currently invoking unit + _currentUnit = unit; + _currentUnitStart = start; + } + } - } else { - _nextQueueReport = - start + PresentsDObjectMgr.STATS_SNAPSHOT_INTERVAL; - } - } + // documentation inherited + protected void didInvokeUnit (Unit unit, long start) + { + super.didInvokeUnit(unit, start); + + synchronized (this) { + // clear out our currently invoking unit + _currentUnit = null; + _currentUnitStart = 0L; } } @@ -164,7 +168,7 @@ public class PresentsInvoker extends Invoker // because of passes if (_passCount >= MAX_PASSES) { Log.warning("Shutdown Unit passed 50 times without " + - "finishing, shutting down harshly."); + "finishing, shutting down harshly."); } doShutdown(); } @@ -177,7 +181,7 @@ public class PresentsInvoker extends Invoker { if (_loopCount > MAX_LOOPS) { Log.warning("Shutdown Unit looped on one thread 10000 times " + - "without finishing, shutting down harshly."); + "without finishing, shutting down harshly."); doShutdown(); return true; } @@ -217,12 +221,12 @@ public class PresentsInvoker extends Invoker /** The distributed object manager with which we interoperate. */ protected PresentsDObjectMgr _omgr; - /** Used to report runtime statistics. */ - protected AuditLogger _statslog; - - /** The largest queue size in the past minute. */ + /** The largest queue size since our last report. */ protected long _maxQueueSize; - /** The time at which we last reported our max queue size. */ - protected long _nextQueueReport; + /** Records the currently invoking unit. */ + protected Object _currentUnit; + + /** The time at which our current unit started. */ + protected long _currentUnitStart; } diff --git a/src/java/com/threerings/presents/server/PresentsServer.java b/src/java/com/threerings/presents/server/PresentsServer.java index 63658b34c..10577fba0 100644 --- a/src/java/com/threerings/presents/server/PresentsServer.java +++ b/src/java/com/threerings/presents/server/PresentsServer.java @@ -105,8 +105,9 @@ public class PresentsServer ", jvm=" + si.jvmToString() + ", mem=" + si.memoryToString() + "]."); - // register a ctrl-c handler + // register SIGINT (ctrl-c) and a SIGUSER1 handlers SignalManager.registerSignalHandler(SignalManager.SIGINT, this); + SignalManager.registerSignalHandler(SignalManager.SIGUSR1, this); // create our list of shutdowners _downers = new ObserverList(ObserverList.SAFE_IN_ORDER_NOTIFY); @@ -134,7 +135,7 @@ public class PresentsServer // queue up an interval which will generate reports new Interval(omgr) { public void expired () { - generateReport(System.currentTimeMillis()); + logReport(generateReport(System.currentTimeMillis())); } }.schedule(REPORT_INTERVAL, true); } @@ -193,9 +194,23 @@ public class PresentsServer // documentation inherited from interface public boolean signalReceived (int signo) { - // this is called when we receive a ctrl-c - Log.info("Shutdown initiated by received signal (" + signo + ")"); - queueShutdown(); + switch (signo) { + case SignalManager.SIGINT: + // this is called when we receive a ctrl-c + Log.info("Shutdown initiated by received signal (" + signo + ")"); + queueShutdown(); + break; + + case SignalManager.SIGUSR1: + // generate a system status report + Log.info(generateReport(System.currentTimeMillis())); + break; + + default: + Log.warning("Received unknown signal [signo=" + signo + "]."); + break; + } + return true; } @@ -212,16 +227,16 @@ public class PresentsServer /** * Generates and logs a "state of server" report. */ - protected void generateReport (long now) + protected String generateReport (long now) { long sinceLast = now - _lastReportStamp; long uptime = now - _serverStartTime; StringBuilder report = new StringBuilder("State of server report:\n"); report.append("- Uptime: "); - report.append(StringUtil.intervalToString(uptime)).append(", "); - report.append(StringUtil.intervalToString(sinceLast)); - report.append(" since last report\n"); + report.append(StringUtil.intervalToString(uptime)).append("\n"); + report.append("- Report period: "); + report.append(StringUtil.intervalToString(sinceLast)).append("\n"); // report on the state of memory Runtime rt = Runtime.getRuntime(); @@ -258,13 +273,13 @@ public class PresentsServer } _lastReportStamp = now; - logReport(report.toString()); + return report.toString(); } /** - * Logs the state of the server report via the default logging - * mechanism. Derived classes may wish to log the state of the server - * report via a different means. + * Logs the state of the server report via the default logging mechanism. + * Derived classes may wish to log the state of the server report via a + * different means. */ protected void logReport (String report) {