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

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
+    /** Contains operational statistics that are tracked by the distributed
-     * distributed object manager for a particular period of time (e.g. 5
+     * object manager between {@link PresentsServer#Reporter} intervals. The
-     * minutes). The snapshot for the most recently completed period can
+     * snapshot for the most recently completed period can be requested via
-     * be requested via {@link #getStats()}. . */
+     * {@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");
-
+        int queueSize = _evqueue.size();
-        report.append("- Unit profiles: ").append(_profiles.size());
+        report.append("- Queue size: ").append(queueSize).append("\n");
+        report.append("- Max queue size: ").append(_current.maxQueueSize);
         report.append("\n");
-        for (Map.Entry<String,UnitProfile> entry : _profiles.entrySet()) {
+        report.append("- Units executed: ").append(_current.eventCount);
-            report.append("  ").append(entry.getKey());
+        report.append("\n");
-            report.append(" ").append(entry.getValue());
+
+        if (UNIT_PROF_ENABLED) {
+            report.append("- Unit profiles: ").append(_profiles.size());
             report.append("\n");
+            for (Map.Entry<String,UnitProfile> 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. */
+    /** Whether or not unit profiling is enabled. */
-    protected long _nextStatsSnapshot;
+    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.

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");
+        buf.append("* presents.util.Invoker:\n");
-        buffer.append("- Units executed: ").append(_unitsRun).append("\n");
+        int qsize = _queue.size();
-        _unitsRun = 0;
+        buf.append("- Queue size: ").append(qsize).append("\n");
-        for (Iterator iter = _tracker.keySet().iterator(); iter.hasNext(); ) {
+        synchronized (this) {
-            Object key = iter.next();
+            buf.append("- Max queue size: ").append(_maxQueueSize).append("\n");
-            UnitProfile profile = (UnitProfile)_tracker.get(key);
+            buf.append("- Units executed: ").append(_unitsRun).append("\n");
-            if (key instanceof Class) {
+            _maxQueueSize = qsize;
-                key = StringUtil.shortClassName((Class)key);
+            _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
+            // note the currently invoking unit
-            if (_nextQueueReport < start) {
+            _currentUnit = unit;
-                if (_nextQueueReport != 0L) {
+            _currentUnitStart = start;
-                    _statslog.log("max_invoker_queue_size " + _maxQueueSize);
+        }
-                    _maxQueueSize = queueSize;
+    }
-                    _nextQueueReport +=
-                        PresentsDObjectMgr.STATS_SNAPSHOT_INTERVAL;
 
-                } else {
+    // documentation inherited
-                    _nextQueueReport =
+    protected void didInvokeUnit (Unit unit, long start)
-                        start + PresentsDObjectMgr.STATS_SNAPSHOT_INTERVAL;
+    {
-                }
+        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. */
+    /** The largest queue size since our last report. */
-    protected AuditLogger _statslog;
-
-    /** The largest queue size in the past minute. */
     protected long _maxQueueSize;
 
-    /** The time at which we last reported our max queue size. */
+    /** Records the currently invoking unit. */
-    protected long _nextQueueReport;
+    protected Object _currentUnit;
+
+    /** The time at which our current unit started. */
+    protected long _currentUnitStart;
 }

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
+        switch (signo) {
-        Log.info("Shutdown initiated by received signal (" + signo + ")");
+        case SignalManager.SIGINT:
-        queueShutdown();
+            // 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(uptime)).append("\n");
-        report.append(StringUtil.intervalToString(sinceLast));
+        report.append("- Report period: ");
-        report.append(" since last report\n");
+        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
+     * Logs the state of the server report via the default logging mechanism.
-     * mechanism. Derived classes may wish to log the state of the server
+     * Derived classes may wish to log the state of the server report via a
-     * report via a different means.
+     * different means.
      */
     protected void logReport (String report)
     {