Metrics! Added support for a "state of the server" report, in which

managers can participate, reporting lies, damned lies and useful
statistics. Initial participants include the client manager, the
connection manager and the distributed object manager.


git-svn-id: svn+ssh://src.earth.threerings.net/narya/trunk@1894 542714f4-19e9-0310-aa3c-eee0fc999fb1

src/java/com/threerings/presents/server/ClientManager.java

@@ -1,5 +1,5 @@
 //
-// $Id: ClientManager.java,v 1.25 2002/10/31 21:04:19 mdb Exp $
+// $Id: ClientManager.java,v 1.26 2002/11/05 02:17:56 mdb Exp $
 
 package com.threerings.presents.server;
 
@@ -30,7 +30,8 @@ import com.threerings.presents.server.util.SafeInterval;
  * going away) and from the dobjmgr thread (when clients are given the
  * boot for application-defined reasons).
  */
-public class ClientManager implements ConnectionObserver
+public class ClientManager
+    implements ConnectionObserver, PresentsServer.Reporter
 {
     /**
      * Constructs a client manager that will interact with the supplied
@@ -49,6 +50,8 @@ public class ClientManager implements ConnectionObserver
             }
         }, CLIENT_FLUSH_INTERVAL, null, true);
 
+        // register as a "state of server" reporter
+        PresentsServer.registerReporter(this);
     }
 
     /**
@@ -325,6 +328,17 @@ public class ClientManager implements ConnectionObserver
         }
     }
 
+    // documentation inherited from interface PresentsServer.Reporter
+    public void appendReport (StringBuffer report, long now, long sinceLast)
+    {
+        report.append("* presents.ClientManager:\n");
+        report.append("- Sessions: ");
+        report.append(_usermap.size()).append(" total, ");
+        report.append(_conmap.size()).append(" connected, ");
+        report.append(_penders.size()).append(" pending\n");
+        report.append("- Mapped users: ").append(_objmap.size()).append("\n");
+    }
+
     /**
      * Called by the client instance when the client requests a logoff.
      * This is called from the conmgr thread.

src/java/com/threerings/presents/server/PresentsDObjectMgr.java

@@ -1,14 +1,16 @@
 //
-// $Id: PresentsDObjectMgr.java,v 1.25 2002/07/17 01:54:33 mdb Exp $
+// $Id: PresentsDObjectMgr.java,v 1.26 2002/11/05 02:17:56 mdb Exp $
 
 package com.threerings.presents.server;
 
 import java.lang.reflect.*;
 import java.util.HashMap;
+import java.util.Iterator;
 import java.util.List;
 
 import com.samskivert.util.HashIntMap;
 import com.samskivert.util.Queue;
+import com.samskivert.util.SortableArrayList;
 import com.samskivert.util.StringUtil;
 
 import com.threerings.presents.Log;
@@ -27,7 +29,8 @@ import com.threerings.presents.dobj.*;
  * application main thread which won't return until the manager has been
  * requested to shut down.
  */
-public class PresentsDObjectMgr implements RootDObjectManager
+public class PresentsDObjectMgr
+    implements RootDObjectManager, PresentsServer.Reporter
 {
     /**
      * Creates the dobjmgr and prepares it for operation.
@@ -40,6 +43,9 @@ public class PresentsDObjectMgr implements RootDObjectManager
         dummy.setOid(0);
         dummy.setManager(this);
         _objects.put(0, new DObject());
+
+        // register ourselves as a state of server reporter
+        PresentsServer.registerReporter(this);
     }
 
     /**
@@ -174,8 +180,8 @@ public class PresentsDObjectMgr implements RootDObjectManager
         // look up the target object
         DObject target = (DObject)_objects.get(event.getTargetOid());
         if (target == null) {
-            Log.warning("Event target no longer exists " +
-                        "[event=" + event + "].");
+            Log.debug("Event target no longer exists " +
+                      "[event=" + event + "].");
             return;
         }
 
@@ -215,6 +221,9 @@ public class PresentsDObjectMgr implements RootDObjectManager
                         ", target=" + target + "].");
             Log.logStackTrace(e);
         }
+
+        // track the number of events dispatched
+        ++_eventCount;
     }
 
     /**
@@ -462,6 +471,45 @@ public class PresentsDObjectMgr implements RootDObjectManager
         return _nextOid;
     }
 
+    // documentation inherited from interface PresentsServer.Reporter
+    public void appendReport (StringBuffer report, long now, long sinceLast)
+    {
+        report.append("* presents.PresentsDObjectMgr:\n");
+
+        long processed = (_eventCount - _lastEventCount);
+        report.append("- Events since last report: ").append(processed);
+        report.append("\n");
+        _lastEventCount = _eventCount;
+
+        // summarize the objects in our dobject table
+        HashMap ccount = new HashMap();
+        SortableArrayList clist = new SortableArrayList();
+        Iterator iter = _objects.values().iterator();
+        while (iter.hasNext()) {
+            DObject obj = (DObject)iter.next();
+            String clazz = obj.getClass().getName();
+            int[] count = (int[])ccount.get(clazz);
+            if (count == null) {
+                count = new int[] { 0 };
+                ccount.put(clazz, count);
+                clist.add(clazz);
+            }
+            count[0]++;
+        }
+
+        // sort our list of dobject types
+        clist.sort();
+
+        report.append("- DObject count: ").append(_objects.size());
+        report.append("\n");
+        for (int ii = 0; ii < clist.size(); ii++) {
+            String clazz = (String)clist.get(ii);
+            int count = ((int[])ccount.get(clazz))[0];
+            report.append("  ").append(clazz).append(": ").append(count);
+            report.append("\n");
+        }
+    }
+
     /**
      * Calls {@link Subscriber#objectAvailable} and catches and logs any
      * exception thrown by the subscriber during the call.
@@ -696,6 +744,15 @@ public class PresentsDObjectMgr implements RootDObjectManager
     /** Used to assign a unique oid to each distributed object. */
     protected int _nextOid = 0;
 
+    /** Used to track the number of events dispatched over time. */
+    protected long _eventCount = 0;
+
+    /** Used to track the number of events dispatched over of time. */
+    protected long _lastEventCount = 0;
+
+    /** The last time at which we generated a report. */
+    protected long _lastReportStamp;
+
     /** Used to track oid list references of distributed objects. */
     protected HashIntMap _refs = new HashIntMap();
 
@@ -703,6 +760,13 @@ public class PresentsDObjectMgr implements RootDObjectManager
      * objects. */
     protected AccessController _defaultController;
 
+    /** Check whether we should generate a report every 100 events. */
+    protected static final long REPORT_CHECK_PERIOD = 100;
+
+    /** Generate a report no more frequently than once per five
+     * minutes. */
+    protected static final long REPORT_PERIOD = 5 * 60 * 1000L;
+
     /** The default size of an oid list refs vector. */
     protected static final int DEFREFVEC_SIZE = 4;
 

src/java/com/threerings/presents/server/PresentsServer.java

@@ -1,12 +1,18 @@
 //
-// $Id: PresentsServer.java,v 1.26 2002/10/21 20:56:20 mdb Exp $
+// $Id: PresentsServer.java,v 1.27 2002/11/05 02:17:56 mdb Exp $
 
 package com.threerings.presents.server;
 
+import java.util.ArrayList;
+
+import com.samskivert.util.IntervalManager;
+import com.samskivert.util.StringUtil;
+
 import com.threerings.presents.Log;
 import com.threerings.presents.client.Client;
 import com.threerings.presents.dobj.DObjectManager;
 import com.threerings.presents.server.net.ConnectionManager;
+import com.threerings.presents.server.util.SafeInterval;
 import com.threerings.presents.util.Invoker;
 
 /**
@@ -21,6 +27,25 @@ import com.threerings.presents.util.Invoker;
  */
 public class PresentsServer
 {
+    /** Used to generate "state of the server" reports. See {@link
+     * #registerReporter}. */
+    public static interface Reporter
+    {
+        /**
+         * Requests that this reporter append its report to the supplied
+         * string buffer.
+         *
+         * @param buffer the string buffer to which the report text should
+         * be appended.
+         * @param now the time at which the report generation began, in
+         * epoch millis.
+         * @param sinceLast number of milliseconds since the last time we
+         * generated a report.
+         */
+        public void appendReport (
+            StringBuffer buffer, long now, long sinceLast);
+    }
+
     /** The manager of network connections. */
     public static ConnectionManager conmgr;
 
@@ -63,6 +88,13 @@ public class PresentsServer
 
         // initialize the time base services
         TimeBaseProvider.init(invmgr, omgr);
+
+        // queue up an interval which will generate reports
+        IntervalManager.register(new SafeInterval(omgr) {
+            public void run () {
+                generateReport(System.currentTimeMillis());
+            }
+        }, REPORT_INTERVAL, null, true);
     }
 
     /**
@@ -92,6 +124,58 @@ public class PresentsServer
         omgr.run();
     }
 
+    /**
+     * A report is generated by the presents server periodically in which
+     * server entities can participate by registering a {@link Reporter}
+     * with this method.
+     */
+    public static void registerReporter (Reporter reporter)
+    {
+        _reporters.add(reporter);
+    }
+
+    /**
+     * Generates and logs a "state of server" report.
+     */
+    protected void generateReport (long now)
+    {
+        long sinceLast = now - _lastReportStamp;
+        long uptime = now - _serverStartTime;
+        StringBuffer report = new StringBuffer("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 on the state of memory
+        Runtime rt = Runtime.getRuntime();
+        long total = rt.totalMemory(), max = rt.maxMemory();
+        long used = (total - rt.freeMemory());
+        report.append("- Memory: ").append(used/1024).append("k used, ");
+        report.append(total/1024).append("k total, ");
+        report.append(max/1024).append("k max\n");
+
+        for (int ii = 0; ii < _reporters.size(); ii++) {
+            Reporter rptr = (Reporter)_reporters.get(ii);
+            try {
+                rptr.appendReport(report, now, sinceLast);
+            } catch (Throwable t) {
+                Log.warning("Reporter choked [rptr=" + rptr + "].");
+                Log.logStackTrace(t);
+            }
+        }
+
+        // strip off the final newline
+        int blen = report.length();
+        if (report.charAt(blen-1) == '\n') {
+            report.delete(blen-1, blen);
+        }
+
+        Log.info(report.toString());
+        _lastReportStamp = now;
+    }
+
     /**
      * Requests that the server shut down.
      */
@@ -137,4 +221,16 @@ public class PresentsServer
             System.exit(-1);
         }
     }
+
+    /** The time at which the server was started. */
+    protected long _serverStartTime = System.currentTimeMillis();
+
+    /** The last time at which {@link #generateReport} was run. */
+    protected long _lastReportStamp = _serverStartTime;
+
+    /** Used to generate "state of server" reports. */
+    protected static ArrayList _reporters = new ArrayList();
+
+    /** The frequency with which we generate "state of server" reports. */
+    protected static final long REPORT_INTERVAL = 5 * 60 * 1000L;
 }

src/java/com/threerings/presents/server/net/Connection.java

@@ -1,5 +1,5 @@
 //
-// $Id: Connection.java,v 1.10 2002/10/29 23:51:26 mdb Exp $
+// $Id: Connection.java,v 1.11 2002/11/05 02:17:56 mdb Exp $
 
 package com.threerings.presents.server.net;
 
@@ -213,11 +213,12 @@ public abstract class Connection implements NetEventHandler
     /**
      * Called when our client socket has data available for reading.
      */
-    public void handleEvent (long when, Selectable source, short events)
+    public int handleEvent (long when, Selectable source, short events)
     {
         // make a note that we received an event as of this time
         _lastEvent = when;
 
+        int bytesIn = 0;
         try {
             // we're lazy about creating our input streams because we may
             // be inheriting them from our authing connection and we don't
@@ -229,6 +230,10 @@ public abstract class Connection implements NetEventHandler
 
             // read the available data and see if we have a whole frame
             if (_fin.readFrame(_in)) {
+                // make a note of how many bytes are in this frame
+                // (including the frame length bytes which aren't reported
+                // in available())
+                bytesIn = _fin.available() + 4;
                 // parse the message and pass it on
                 UpstreamMessage msg = (UpstreamMessage)_oin.readObject();
 //                 Log.info("Read message " + msg + ".");
@@ -252,6 +257,8 @@ public abstract class Connection implements NetEventHandler
             // deal with the failure
             handleFailure(ioe);
         }
+
+        return bytesIn;
     }
 
     // documentation inherited from interface

src/java/com/threerings/presents/server/net/ConnectionManager.java

@@ -1,5 +1,5 @@
 //
-// $Id: ConnectionManager.java,v 1.23 2002/10/29 23:51:26 mdb Exp $
+// $Id: ConnectionManager.java,v 1.24 2002/11/05 02:17:56 mdb Exp $
 
 package com.threerings.presents.server.net;
 
@@ -31,6 +31,7 @@ import com.threerings.presents.server.PresentsServer;
  * mechanism rather than via threads.
  */
 public class ConnectionManager extends LoopingThread
+    implements PresentsServer.Reporter
 {
     /**
      * Constructs and initialized a connection manager (binding the socket
@@ -42,6 +43,9 @@ public class ConnectionManager extends LoopingThread
         _port = port;
         _selset = new SelectSet();
 
+        // register as a "state of server" reporter
+        PresentsServer.registerReporter(this);
+
         try {
             // create our listening socket and add it to the select set
             _listener = new NonblockingServerSocket(_port);
@@ -54,9 +58,11 @@ public class ConnectionManager extends LoopingThread
         _litem = new SelectItem(_listener, Selectable.ACCEPT_READY);
         // when an ACCEPT_READY event happens, we do this:
         _litem.obj = new NetEventHandler() {
-            public void handleEvent (
-                long when, Selectable item, short events) {
+            public int handleEvent (long when, Selectable item, short events) {
                 acceptConnection();
+                // there's no easy way to measure bytes read when
+                // accepting a connection, so we claim nothing
+                return 0;
             }
             public void checkIdle (long now) {
                 // we're never idle
@@ -131,6 +137,32 @@ public class ConnectionManager extends LoopingThread
         _authq.append(conn);
     }
 
+    // documentation inherited from interface PresentsServer.Reporter
+    public void appendReport (StringBuffer report, long now, long sinceLast)
+    {
+        long bytesIn, bytesOut, msgsIn, msgsOut;
+        synchronized (this) {
+            bytesIn = _bytesIn; _bytesIn = 0L;
+            bytesOut = _bytesOut; _bytesOut = 0L;
+            msgsIn = _msgsIn; _msgsIn = 0;
+            msgsOut = _msgsOut; _msgsOut = 0;
+        }
+
+        report.append("* presents.net.ConnectionManager:\n");
+        report.append("- Network input: ");
+        report.append(bytesIn).append(" bytes, ");
+        report.append(msgsIn).append(" msgs, ");
+        long avgIn = (msgsIn == 0) ? 0 : (bytesIn/msgsIn);
+        report.append(avgIn).append(" avg size, ");
+        report.append(bytesIn*1000/sinceLast).append(" bps\n");
+        report.append("- Network output: ");
+        report.append(bytesOut).append(" bytes, ");
+        report.append(msgsOut).append(" msgs, ");
+        long avgOut = (msgsOut == 0) ? 0 : (bytesOut/msgsOut);
+        report.append(avgOut).append(" avg size, ");
+        report.append(bytesOut*1000/sinceLast).append(" bps\n");
+    }
+
     /**
      * Notifies the connection observers of a connection event. Used
      * internally.
@@ -217,7 +249,11 @@ public class ConnectionManager extends LoopingThread
                 oout.flush();
 
                 // then write framed message to real output stream
-                _framer.writeFrameAndReset(conn.getOutputStream());
+                int out = _framer.writeFrameAndReset(conn.getOutputStream());
+                synchronized (this) {
+                    _bytesOut += out;
+                    _msgsOut++;
+                }
 
             } catch (IOException ioe) {
                 // instruct the connection to deal with its failure
@@ -266,8 +302,17 @@ public class ConnectionManager extends LoopingThread
             try {
                 SelectItem item = active[i];
                 NetEventHandler handler = (NetEventHandler)item.obj;
-                handler.handleEvent(
+                int got = handler.handleEvent(
                     iterStamp, item.getSelectable(), item.revents);
+                if (got != 0) {
+                    synchronized (this) {
+                        _bytesIn += got;
+                        // we know that the handlers only report having
+                        // read bytes when they have a whole message, so
+                        // we can count thusly
+                        _msgsIn++;
+                    }
+                }
 
             } catch (Exception e) {
                 Log.warning("Error processing network data.");
@@ -377,14 +422,19 @@ public class ConnectionManager extends LoopingThread
     protected SelectItem _litem;
 
     protected Queue _deathq = new Queue();
+    protected Queue _authq = new Queue();
 
     protected Queue _outq = new Queue();
     protected FramingOutputStream _framer;
 
-    protected Queue _authq = new Queue();
-
     protected ArrayList _observers = new ArrayList();
 
+    /** Bytes in and out in the last reporting period. */
+    protected long _bytesIn, _bytesOut;
+
+    /** Messages read and written in the last reporting period. */
+    protected int _msgsIn, _msgsOut;
+
     /**
      * How long we wait for network events before checking our running
      * flag to see if we should still be running.

src/java/com/threerings/presents/server/net/NetEventHandler.java

@@ -1,5 +1,5 @@
 //
-// $Id: NetEventHandler.java,v 1.4 2002/10/29 23:51:26 mdb Exp $
+// $Id: NetEventHandler.java,v 1.5 2002/11/05 02:17:56 mdb Exp $
 
 package com.threerings.presents.server.net;
 
@@ -22,8 +22,11 @@ public interface NetEventHandler
      * Called when a network event has occurred on the supplied source.
      * The <code>events</code> parameter indicates which event or events
      * have occurred.
+     *
+     * @return the number of bytes read from the network as a result of
+     * handling this event.
      */
-    public void handleEvent (long when, Selectable source, short events);
+    public int handleEvent (long when, Selectable source, short events);
 
     /**
      * Called to ensure that this selectable has not been idle for longer