Author: zothar
Date: 2006-11-05 03:26:39 +0000 (Sun, 05 Nov 2006)
New Revision: 10821
Modified:
trunk/freenet/src/freenet/io/comm/UdpSocketManager.java
trunk/freenet/src/freenet/io/xfer/BlockTransmitter.java
trunk/freenet/src/freenet/node/FNPPacketMangler.java
trunk/freenet/src/freenet/node/KeyTracker.java
trunk/freenet/src/freenet/node/Node.java
trunk/freenet/src/freenet/support/TimeUtil.java
Log:
Format some log message times. Add fractional seconds to TimeUtil. Fix a node
statistic via FCP bug.
Modified: trunk/freenet/src/freenet/io/comm/UdpSocketManager.java
===================================================================
--- trunk/freenet/src/freenet/io/comm/UdpSocketManager.java 2006-11-05
02:28:23 UTC (rev 10820)
+++ trunk/freenet/src/freenet/io/comm/UdpSocketManager.java 2006-11-05
03:26:39 UTC (rev 10821)
@@ -31,6 +31,7 @@
import freenet.node.PeerNode;
import freenet.support.FileLoggerHook;
import freenet.support.Logger;
+import freenet.support.TimeUtil;
public class UdpSocketManager extends Thread {
@@ -400,9 +401,9 @@
Message removed =
(Message)_unclaimed.removeFirst();
long messageLifeTime =
System.currentTimeMillis() - removed.localInstantiationTime;
if ((removed.getSource()) instanceof
PeerNode) {
- Logger.normal(this, "Dropping
unclaimed from "+removed.getSource().getPeer()+", lived "+messageLifeTime+"ms :
"+removed);
+ Logger.normal(this, "Dropping
unclaimed from "+removed.getSource().getPeer()+", lived
"+TimeUtil.formatTime(messageLifeTime, 2, true)+" : "+removed);
} else {
- Logger.normal(this, "Dropping
unclaimed, lived "+messageLifeTime+"ms : "+removed);
+ Logger.normal(this, "Dropping
unclaimed, lived "+TimeUtil.formatTime(messageLifeTime, 2, true)+" : "+removed);
}
}
_unclaimed.addLast(m);
Modified: trunk/freenet/src/freenet/io/xfer/BlockTransmitter.java
===================================================================
--- trunk/freenet/src/freenet/io/xfer/BlockTransmitter.java 2006-11-05
02:28:23 UTC (rev 10820)
+++ trunk/freenet/src/freenet/io/xfer/BlockTransmitter.java 2006-11-05
03:26:39 UTC (rev 10821)
@@ -35,6 +35,7 @@
import freenet.support.BitArray;
import freenet.support.DoubleTokenBucket;
import freenet.support.Logger;
+import freenet.support.TimeUtil;
/**
* @author ian
@@ -248,7 +249,7 @@
_sendComplete = true;
_senderThread.notifyAll();
}
- Logger.error(this, "Terminating send
"+_uid+" to "+_destination+" from "+_usm.getPortNumber()+" as we haven't heard
from receiver in "+(now - timeAllSent)+"ms.");
+ Logger.error(this, "Terminating send
"+_uid+" to "+_destination+" from "+_usm.getPortNumber()+" as we haven't heard
from receiver in "+TimeUtil.formatTime((now - timeAllSent), 2, true)+".");
return false;
} else {
if(logMINOR) Logger.minor(this,
"Ignoring timeout: timeAllSent="+timeAllSent+" ("+(System.currentTimeMillis() -
timeAllSent)+"), getNumSent="+getNumSent()+"/"+_prb.getNumPackets());
Modified: trunk/freenet/src/freenet/node/FNPPacketMangler.java
===================================================================
--- trunk/freenet/src/freenet/node/FNPPacketMangler.java 2006-11-05
02:28:23 UTC (rev 10820)
+++ trunk/freenet/src/freenet/node/FNPPacketMangler.java 2006-11-05
03:26:39 UTC (rev 10821)
@@ -20,6 +20,7 @@
import freenet.support.Fields;
import freenet.support.HexUtil;
import freenet.support.Logger;
+import freenet.support.TimeUtil;
import freenet.support.WouldBlockException;
/**
@@ -215,7 +216,7 @@
int packetType = payload[2];
int version = payload[0];
- if(logMINOR) Logger.minor(this, "Received auth packet for
"+pn.getPeer()+" (pt="+packetType+", v="+version+", nt="+negType+") (last
packet sent "+delta+"ms ago) from "+replyTo+"");
+ if(logMINOR) Logger.minor(this, "Received auth packet for
"+pn.getPeer()+" (pt="+packetType+", v="+version+", nt="+negType+") (last
packet sent "+TimeUtil.formatTime(delta, 2, true)+" ago) from "+replyTo+"");
/* Format:
* 1 byte - version number (1)
@@ -435,13 +436,13 @@
*/
private void sendAuthPacket(int version, int negType, int phase, byte[]
data, PeerNode pn, Peer replyTo) {
long now = System.currentTimeMillis();
- int delta = (int) (now - pn.lastSentPacketTime());
+ long delta = now - pn.lastSentPacketTime();
byte[] output = new byte[data.length+3];
output[0] = (byte) version;
output[1] = (byte) negType;
output[2] = (byte) phase;
System.arraycopy(data, 0, output, 3, data.length);
- if(logMINOR) Logger.minor(this, "Sending auth packet for
"+pn.getPeer()+" (ph="+phase+", v="+version+", nt="+negType+") (last packet
sent "+delta+"ms ago) to "+replyTo+" data.length="+data.length);
+ if(logMINOR) Logger.minor(this, "Sending auth packet for
"+pn.getPeer()+" (ph="+phase+", v="+version+", nt="+negType+") (last packet
sent "+TimeUtil.formatTime(delta, 2, true)+" ago) to "+replyTo+"
data.length="+data.length);
sendAuthPacket(output, pn, replyTo);
}
@@ -849,7 +850,7 @@
if((seqNumber != -1) && tracker.alreadyReceived(seqNumber)) {
tracker.queueAck(seqNumber);
- Logger.error(this, "Received packet twice ("+seqNumber+") from
"+tracker.pn.getPeer()+": "+seqNumber+" ("+(int)
tracker.pn.pingAverage.currentValue()+"ms ping avg)");
+ Logger.error(this, "Received packet twice ("+seqNumber+") from
"+tracker.pn.getPeer()+": "+seqNumber+" ("+TimeUtil.formatTime((long)
tracker.pn.pingAverage.currentValue(), 2, true)+" ping avg)");
return;
}
Modified: trunk/freenet/src/freenet/node/KeyTracker.java
===================================================================
--- trunk/freenet/src/freenet/node/KeyTracker.java 2006-11-05 02:28:23 UTC
(rev 10820)
+++ trunk/freenet/src/freenet/node/KeyTracker.java 2006-11-05 03:26:39 UTC
(rev 10821)
@@ -17,6 +17,7 @@
import freenet.support.LimitedRangeIntByteArrayMapElement;
import freenet.support.Logger;
import freenet.support.ReceivedPacketNumbers;
+import freenet.support.TimeUtil;
import freenet.support.UpdatableSortedLinkedListItem;
import freenet.support.UpdatableSortedLinkedListKilledException;
import freenet.support.UpdatableSortedLinkedListWithForeignIndex;
@@ -342,7 +343,7 @@
public void onAcked() {
long t = Math.max(0, System.currentTimeMillis() -
createdTime);
pn.pingAverage.report(t);
- if(logMINOR) Logger.minor(this, "Reported round-trip
time of "+t+"ms on "+pn.getPeer()+" (avg "+pn.pingAverage.currentValue()+"ms,
#"+packetNumber+")");
+ if(logMINOR) Logger.minor(this, "Reported round-trip
time of "+TimeUtil.formatTime(t, 2, true)+" on "+pn.getPeer()+" (avg
"+TimeUtil.formatTime((long)pn.pingAverage.currentValue(),2,true)+",
#"+packetNumber+")");
}
long urgentDelay() {
@@ -564,7 +565,7 @@
QueuedAckRequest qr =
(QueuedAckRequest)ackRequestQueue.removeByKey(new Integer(seqNo));
if(qr != null) qr.onAcked();
else
- Logger.normal(this, "Removing ack request twice? Null on
"+seqNo+" from "+pn.getPeer()+" ("+(int) pn.pingAverage.currentValue()+"ms ping
avg)");
+ Logger.normal(this, "Removing ack request twice? Null on
"+seqNo+" from "+pn.getPeer()+" ("+TimeUtil.formatTime((int)
pn.pingAverage.currentValue(), 2, true)+" ping avg)");
}
/**
Modified: trunk/freenet/src/freenet/node/Node.java
===================================================================
--- trunk/freenet/src/freenet/node/Node.java 2006-11-05 02:28:23 UTC (rev
10820)
+++ trunk/freenet/src/freenet/node/Node.java 2006-11-05 03:26:39 UTC (rev
10821)
@@ -97,6 +97,7 @@
import freenet.support.LRUQueue;
import freenet.support.Logger;
import freenet.support.SimpleFieldSet;
+import freenet.support.TimeUtil;
import freenet.support.TokenBucket;
import freenet.support.math.RunningAverage;
import freenet.support.math.TimeDecayingRunningAverage;
@@ -1553,13 +1554,13 @@
if(logMINOR) Logger.minor(this,
"Accepting request anyway (take one every 10 secs to keep bwlimitDelayTime
updated)");
} else {
pInstantRejectIncoming.report(1.0);
- return ">MAX_PING_TIME ("+pingTime+")";
+ return ">MAX_PING_TIME
("+TimeUtil.formatTime((long)pingTime, 2, true)+")";
}
} else if(pingTime > SUB_MAX_PING_TIME) {
double x = ((double)(pingTime -
SUB_MAX_PING_TIME)) / (MAX_PING_TIME - SUB_MAX_PING_TIME);
if(random.nextDouble() < x) {
pInstantRejectIncoming.report(1.0);
- return ">SUB_MAX_PING_TIME
("+pingTime+")";
+ return ">SUB_MAX_PING_TIME
("+TimeUtil.formatTime((long)pingTime, 2, true)+")";
}
}
@@ -1569,13 +1570,13 @@
if(logMINOR) Logger.minor(this,
"Accepting request anyway (take one every 10 secs to keep bwlimitDelayTime
updated)");
} else {
pInstantRejectIncoming.report(1.0);
- return ">MAX_THROTTLE_DELAY
("+bwlimitDelayTime+")";
+ return ">MAX_THROTTLE_DELAY
("+TimeUtil.formatTime((long)bwlimitDelayTime, 2, true)+")";
}
} else if(bwlimitDelayTime > SUB_MAX_THROTTLE_DELAY) {
double x = ((double)(bwlimitDelayTime -
SUB_MAX_THROTTLE_DELAY)) / (MAX_THROTTLE_DELAY - SUB_MAX_THROTTLE_DELAY);
if(random.nextDouble() < x) {
pInstantRejectIncoming.report(1.0);
- return ">SUB_MAX_THROTTLE_DELAY
("+bwlimitDelayTime+")";
+ return ">SUB_MAX_THROTTLE_DELAY
("+TimeUtil.formatTime((long)bwlimitDelayTime, 2, true)+")";
}
}
@@ -1867,7 +1868,7 @@
fs.put("storeHits", Long.toString(storeHits));
fs.put("storeMisses", Long.toString(storeMisses));
fs.put("storeAccesses", Long.toString(storeAccesses));
- fs.put("percentCachedStoreHitsOfAccesses",
Double.toString(percentCachedStoreHitsOfAccesses));
+ fs.put("percentStoreHitsOfAccesses",
Double.toString(percentStoreHitsOfAccesses));
fs.put("overallAccesses", Long.toString(overallAccesses));
fs.put("avgStoreAccessRate",
Double.toString(avgStoreAccessRate));
Modified: trunk/freenet/src/freenet/support/TimeUtil.java
===================================================================
--- trunk/freenet/src/freenet/support/TimeUtil.java 2006-11-05 02:28:23 UTC
(rev 10820)
+++ trunk/freenet/src/freenet/support/TimeUtil.java 2006-11-05 03:26:39 UTC
(rev 10821)
@@ -18,58 +18,79 @@
package freenet.support;
+import java.text.DecimalFormat;
+
/**
* Time formatting utility.
- * Formats milliseconds into a week/day/hour/second string (without
milliseconds).
+ * Formats milliseconds into a week/day/hour/second/milliseconds string.
*/
public class TimeUtil {
- public static String formatTime(long timeInterval, int maxTerms) {
+ public static String formatTime(long timeInterval, int maxTerms,
boolean withSecondFractions) {
StringBuffer sb = new StringBuffer(64);
- long l = timeInterval / 1000; // ms -> s
+ long l = timeInterval;
int termCount = 0;
//
- int weeks = (int)(l / (7*24*60*60));
+ int weeks = (int)(l / ((long)7*24*60*60*1000));
if (weeks > 0) {
sb.append(weeks + "w");
termCount++;
- l = l - (weeks * (7*24*60*60));
+ l = l - ((long)weeks * ((long)7*24*60*60*1000));
}
//
- int days = (int)(l / (24*60*60));
+ int days = (int)(l / ((long)24*60*60*1000));
if (days > 0) {
sb.append(days + "d");
termCount++;
- l = l - (days * (24*60*60));
+ l = l - ((long)days * ((long)24*60*60*1000));
}
if(termCount >= maxTerms) {
return sb.toString();
}
//
- int hours = (int)(l / (60*60));
+ int hours = (int)(l / ((long)60*60*1000));
if (hours > 0) {
sb.append(hours + "h");
termCount++;
- l = l - (hours * (60*60));
+ l = l - ((long)hours * ((long)60*60*1000));
}
if(termCount >= maxTerms) {
return sb.toString();
}
//
- int minutes = (int)(l / 60);
+ int minutes = (int)(l / ((long)60*1000));
if (minutes > 0) {
sb.append(minutes + "m");
termCount++;
- l = l - (minutes * 60);
+ l = l - ((long)minutes * ((long)60*1000));
}
if(termCount >= maxTerms) {
return sb.toString();
}
+ if(withSecondFractions && ((maxTerms - termCount) >= 2)) {
+ if (l > 0) {
+ double fractionalSeconds = ((double) l) /
((double) 1000.0);
+ DecimalFormat fix4 = new
DecimalFormat("0.0000");
+ sb.append(fix4.format(fractionalSeconds) + "s");
+ termCount++;
+ l = l - ((long)fractionalSeconds * (long)1000);
+ }
+ } else {
+ int seconds = (int)(l / (long)1000);
+ if (seconds > 0) {
+ sb.append(seconds + "s");
+ termCount++;
+ l = l - ((long)seconds * (long)1000);
+ }
+ }
//
- sb.append(l + "s");
return sb.toString();
}
public static String formatTime(long timeInterval) {
- return formatTime(timeInterval, 2);
+ return formatTime(timeInterval, 2, false);
}
+
+ public static String formatTime(long timeInterval, int maxTerms) {
+ return formatTime(timeInterval, maxTerms, false);
+ }
}
