From 091fda3e77b106032e6756b34c6dbae3791c660b Mon Sep 17 00:00:00 2001 From: Michael Bayne Date: Sun, 25 Jun 2006 22:47:42 +0000 Subject: [PATCH] Revamped stats tracking so that it all happens on the same reporting interval. Turned off the very verbose unit profiles as we don't currently use them. Wired up SIGUSR1 to dump a report to the log. git-svn-id: svn+ssh://src.earth.threerings.net/narya/trunk@4218 542714f4-19e9-0310-aa3c-eee0fc999fb1 --- .../presents/server/PresentsDObjectMgr.java | 57 ++++++----- .../presents/server/PresentsInvoker.java | 94 ++++++++++--------- .../presents/server/PresentsServer.java | 41 +++++--- 3 files changed, 104 insertions(+), 88 deletions(-) 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) {