2005-10-08 jrandom

* Use the OS clock for stat timing, since it doesn't jump around (though
      still use the NTP'ed clock for display)
    * Added new DH stats

core/java/src/net/i2p/crypto/DHSessionKeyBuilder.java

@@ -66,11 +66,13 @@ public class DHSessionKeyBuilder {
     public final static String PROP_DH_PRECALC_MAX = "crypto.dh.precalc.max";
     public final static String PROP_DH_PRECALC_DELAY = "crypto.dh.precalc.delay";
     public final static String DEFAULT_DH_PRECALC_MIN = "5";
-    public final static String DEFAULT_DH_PRECALC_MAX = "10";
+    public final static String DEFAULT_DH_PRECALC_MAX = "50";
-    public final static String DEFAULT_DH_PRECALC_DELAY = "1000";
+    public final static String DEFAULT_DH_PRECALC_DELAY = "10000";
 
     static {
         I2PAppContext ctx = _context;
+        ctx.statManager().createRateStat("crypto.dhGeneratePublicTime", "How long it takes to create x and X", "Encryption", new long[] { 60*1000, 5*60*1000, 60*60*1000 });
+        ctx.statManager().createRateStat("crypto.dhCalculateSessionTime", "How long it takes to create the session key", "Encryption", new long[] { 60*1000, 5*60*1000, 60*60*1000 });        
         try {
             int val = Integer.parseInt(ctx.getProperty(PROP_DH_PRECALC_MIN, DEFAULT_DH_PRECALC_MIN));
             MIN_NUM_BUILDERS = val;
@@ -225,11 +227,12 @@ public class DHSessionKeyBuilder {
      *
      */
     public BigInteger generateMyValue() {
-        long start = Clock.getInstance().now();
+        long start = System.currentTimeMillis();
         _myPrivateValue = new NativeBigInteger(2048, RandomSource.getInstance());
         BigInteger myValue = CryptoConstants.elgg.modPow(_myPrivateValue, CryptoConstants.elgp);
-        long end = Clock.getInstance().now();
+        long end = System.currentTimeMillis();
         long diff = end - start;
+        _context.statManager().addRateData("crypto.dhGeneratePublicTime", diff, diff);
         if (diff > 1000) {
             if (_log.shouldLog(Log.WARN))
                 _log.warn("Took more than a second (" + diff + "ms) to generate local DH value");
@@ -339,7 +342,7 @@ public class DHSessionKeyBuilder {
      *
      */
     private final SessionKey calculateSessionKey(BigInteger myPrivateValue, BigInteger publicPeerValue) {
-        long start = Clock.getInstance().now();
+        long start = System.currentTimeMillis();
         SessionKey key = new SessionKey();
         BigInteger exchangedKey = publicPeerValue.modPow(myPrivateValue, CryptoConstants.elgp);
         byte buf[] = exchangedKey.toByteArray();
@@ -361,8 +364,10 @@ public class DHSessionKeyBuilder {
                 _log.debug("Storing " + remaining.length + " bytes from the end of the DH exchange");
         }
         key.setData(val);
-        long end = Clock.getInstance().now();
+        long end = System.currentTimeMillis();
         long diff = end - start;
+        
+        _context.statManager().addRateData("crypto.dhCalculateSessionTime", diff, diff);
         if (diff > 1000) {
             if (_log.shouldLog(Log.WARN)) _log.warn("Generating session key took too long (" + diff + " ms");
         } else {
@@ -490,10 +495,12 @@ public class DHSessionKeyBuilder {
                 curSize = startSize;
                 while (curSize < _minSize) {
                     while (curSize < _maxSize) {
+                        long curStart = System.currentTimeMillis();
                         curSize = addBuilder(precalc(curSize));
+                        long curCalc = System.currentTimeMillis() - curStart;
                         // for some relief...
                         try {
-                            Thread.sleep(CALC_DELAY);
+                            Thread.sleep(CALC_DELAY + curCalc * 10);
                         } catch (InterruptedException ie) { // nop
                         }
                     }

core/java/src/net/i2p/stat/Rate.java

@@ -454,7 +454,10 @@ public class Rate {
     }
 
     private final static long now() {
-        return Clock.getInstance().now();
+        // "event time" is in the stat log (and uses Clock).
+        // we just want sequential and stable time here, so use the OS time, since it doesn't
+        // skew periodically
+        return System.currentTimeMillis(); //Clock.getInstance().now();
     }
 
     public static void main(String args[]) {

history.txt

@@ -1,4 +1,9 @@
-$Id: history.txt,v 1.284 2005/10/07 05:23:01 jrandom Exp $
+$Id: history.txt,v 1.285 2005/10/07 15:19:04 jrandom Exp $
+
+2005-10-08  jrandom
+    * Use the OS clock for stat timing, since it doesn't jump around (though
+      still use the NTP'ed clock for display)
+    * Added new DH stats
 
 * 2005-10-07  0.6.1.2 released
 

router/java/src/net/i2p/router/RouterVersion.java

@@ -15,9 +15,9 @@ import net.i2p.CoreVersion;
  *
  */
 public class RouterVersion {
-    public final static String ID = "$Revision: 1.259 $ $Date: 2005/10/07 05:23:01 $";
+    public final static String ID = "$Revision: 1.260 $ $Date: 2005/10/07 15:19:07 $";
     public final static String VERSION = "0.6.1.2";
-    public final static long BUILD = 0;
+    public final static long BUILD = 1;
     public static void main(String args[]) {
         System.out.println("I2P Router version: " + VERSION + "-" + BUILD);
         System.out.println("Router ID: " + RouterVersion.ID);

router/java/src/net/i2p/router/transport/tcp/TCPListener.java

@@ -60,6 +60,9 @@ class TCPListener {
         _transport = transport;
         _pendingSockets = new ArrayList(10);
         _handlers = new ArrayList(CONCURRENT_HANDLERS);
+        _context.statManager().createRateStat("tcp.conReceiveOK", "How long does it take to receive a valid connection", "TCP", new long[] { 60*1000, 5*60*1000, 10*60*1000 });
+        _context.statManager().createRateStat("tcp.conReceiveFail", "How long does it take to receive a failed connection", "TCP", new long[] { 60*1000, 5*60*1000, 10*60*1000 });
+        _context.statManager().createRateStat("tcp.conUnhandled", "How often do we receive a connection but take too long on other ones to handle it", "TCP", new long[] { 60*1000, 5*60*1000, 10*60*1000 });
     }
         
     /** Make sure we are listening per the transport's config */
@@ -230,6 +233,7 @@ class TCPListener {
                 removed = _pendingSockets.remove(_cur);
             }
             if (removed) {
+                _context.statManager().addRateData("tcp.conUnhandled", 1, 0);
                 // handlers hadn't taken it yet, so close it
                 if (_log.shouldLog(Log.WARN))
                     _log.warn("Closing unhandled socket " + _cur);
@@ -294,7 +298,13 @@ class TCPListener {
             ConnectionHandler ch = new ConnectionHandler(_context, _transport, _socket);
             TCPConnection con = null;
             try {
+                long before = System.currentTimeMillis();
                 con = ch.receiveConnection();
+                long duration = System.currentTimeMillis() - before;
+                if (con != null)
+                    _context.statManager().addRateData("tcp.conReceiveOK", duration, duration);
+                else
+                    _context.statManager().addRateData("tcp.conReceiveFail", duration, duration);
             } catch (Exception e) {
                 _log.log(Log.CRIT, "Unhandled exception receiving a connection on " + _socket, e);
             }