Matthew Toseland wrote:
> I've worked on this sort of timing issues ... below a certain level,
> it's not worth it; java just produces random delays sometimes... at
> least with as many threads as we use...
>
The complaint times are probably a little aggressive, but
DiffieHellmanContext.generateContext() taking seconds from PacketSender
is good or no? Do we just figure we'll have hiccups in PacketSender
every now and then and they shouldn't get to be over say a minute (which
is why we restart at 3 minutes)?
> On Sun, Jun 18, 2006 at 05:35:33PM +0000, zothar at freenetproject.org wrote:
>
>> Author: zothar
>> Date: 2006-06-18 17:35:22 +0000 (Sun, 18 Jun 2006)
>> New Revision: 9303
>>
>> Modified:
>> trunk/freenet/src/freenet/crypt/DiffieHellman.java
>> trunk/freenet/src/freenet/node/FNPPacketMangler.java
>> trunk/freenet/src/freenet/node/PeerNode.java
>> Log:
>> More time and complaint. A few logging and other minor tweaks.
>>
>> Modified: trunk/freenet/src/freenet/crypt/DiffieHellman.java
>> ===================================================================
>> --- trunk/freenet/src/freenet/crypt/DiffieHellman.java 2006-06-18
>> 16:36:39 UTC (rev 9302)
>> +++ trunk/freenet/src/freenet/crypt/DiffieHellman.java 2006-06-18
>> 17:35:22 UTC (rev 9303)
>> @@ -9,6 +9,7 @@
>> import java.util.Random;
>> import java.util.Stack;
>>
>> +import freenet.support.Logger;
>> import net.i2p.util.NativeBigInteger;
>>
>> public class DiffieHellman {
>> @@ -97,13 +98,18 @@
>> }
>> }
>>
>> - /**
>> - * Create a DiffieHellmanContext. This will include this side's DH
>> params.
>> - */
>> - public static DiffieHellmanContext generateContext() {
>> - NativeBigInteger[] params = getParams();
>> - return new DiffieHellmanContext(params[0], params[1], group);
>> - }
>> + /**
>> + * Create a DiffieHellmanContext. This will include this side's DH
>> params.
>> + */
>> + public static DiffieHellmanContext generateContext() {
>> + long time1 = System.currentTimeMillis();
>> + NativeBigInteger[] params = getParams();
>> + long time2 = System.currentTimeMillis();
>> + if((time2 - time1) > 300) {
>> + Logger.error(null, "DiffieHellman.generateContext():
>> time2 is more than 300ms after time1 ("+(time2 - time1)+")");
>> + }
>> + return new DiffieHellmanContext(params[0], params[1], group);
>> + }
>>
>> public static NativeBigInteger[] getParams() {
>> synchronized (precalcBuffer) {
>>
>> Modified: trunk/freenet/src/freenet/node/FNPPacketMangler.java
>> ===================================================================
>> --- trunk/freenet/src/freenet/node/FNPPacketMangler.java 2006-06-18
>> 16:36:39 UTC (rev 9302)
>> +++ trunk/freenet/src/freenet/node/FNPPacketMangler.java 2006-06-18
>> 17:35:22 UTC (rev 9303)
>> @@ -310,6 +310,7 @@
>> * @param replyTo
>> */
>> private void sendFirstHalfDHPacket(int phase, NativeBigInteger integer,
>> PeerNode pn, Peer replyTo) {
>> + long time1 = System.currentTimeMillis();
>> Logger.minor(this, "Sending ("+phase+") "+integer.toHexString()+"
>> to "+pn.getPeer());
>> byte[] data = integer.toByteArray();
>> int targetLength = DiffieHellman.modulusLengthInBytes();
>> @@ -326,19 +327,32 @@
>> data = newData;
>> }
>> Logger.minor(this, "Processed: "+HexUtil.bytesToHex(data));
>> + long time2 = System.currentTimeMillis();
>> + if((time2 - time1) > 200) {
>> + Logger.error(this, "sendFirstHalfDHPacket: time2 is more than
>> 200ms after time1 ("+(time2 - time1)+") working on "+replyTo+" of
>> "+pn.getName());
>> + }
>> sendAuthPacket(1, 0, phase, data, pn, replyTo);
>> + long time3 = System.currentTimeMillis();
>> + if((time3 - time2) > 500) {
>> + Logger.error(this, "sendFirstHalfDHPacket:sendAuthPacket() time3
>> is more than half a second after time2 ("+(time3 - time2)+") working on
>> "+replyTo+" of "+pn.getName());
>> + }
>> + if((time3 - time1) > 500) {
>> + Logger.error(this, "sendFirstHalfDHPacket: time3 is more than
>> half a second after time1 ("+(time3 - time1)+") working on "+replyTo+" of
>> "+pn.getName());
>> + }
>> }
>>
>> /**
>> * Send an auth packet.
>> */
>> 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());
>> 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);
>> - Logger.minor(this, "Sending auth packet ("+version+","+negType+" to
>> "+replyTo+" - version="+version+" negType="+negType+" phase="+phase+"
>> data.length="+data.length+" for "+pn);
>> + Logger.minor(this, "Sending auth packet ("+version+","+negType+" to
>> "+replyTo+" - version="+version+" negType="+negType+" phase="+phase+"
>> data.length="+data.length+" for "+pn.getPeer()+" (last packet sent
>> "+delta+"ms ago)");
>> sendAuthPacket(output, pn, replyTo);
>> }
>>
>> @@ -1292,23 +1306,23 @@
>> handshakeIPs = pn.getHandshakeIPs();
>> long secondTime = System.currentTimeMillis();
>> if((secondTime - firstTime) > 1000)
>> - Logger.normal(this, "getHandshakeIPs() took more than a second
>> to execute ("+(secondTime - firstTime)+") working on "+pn.getName());
>> + Logger.error(this, "getHandshakeIPs() took more than a second
>> to execute ("+(secondTime - firstTime)+") working on "+pn.getName());
>> if(handshakeIPs.length == 0) {
>> pn.couldNotSendHandshake();
>> long thirdTime = System.currentTimeMillis();
>> if((thirdTime - secondTime) > 1000)
>> - Logger.normal(this, "couldNotSendHandshake() (after
>> getHandshakeIPs()) took more than a second to execute ("+(thirdTime -
>> secondTime)+") working on "+pn.getName());
>> + Logger.error(this, "couldNotSendHandshake() (after
>> getHandshakeIPs()) took more than a second to execute ("+(thirdTime -
>> secondTime)+") working on "+pn.getName());
>> return;
>> } else {
>> long DHTime1 = System.currentTimeMillis();
>> ctx = DiffieHellman.generateContext();
>> long DHTime2 = System.currentTimeMillis();
>> if((DHTime2 - DHTime1) > 1000)
>> - Logger.normal(this, "DHTime2 is more than a second after
>> DHTime1 ("+(DHTime2 - DHTime1)+") working on "+pn.getName());
>> + Logger.error(this, "DHTime2 is more than a second after
>> DHTime1 ("+(DHTime2 - DHTime1)+") working on "+pn.getName());
>> pn.setDHContext(ctx);
>> long DHTime3 = System.currentTimeMillis();
>> if((DHTime3 - DHTime2) > 1000)
>> - Logger.normal(this, "DHTime3 is more than a second after
>> DHTime2 ("+(DHTime3 - DHTime2)+") working on "+pn.getName());
>> + Logger.error(this, "DHTime3 is more than a second after
>> DHTime2 ("+(DHTime3 - DHTime2)+") working on "+pn.getName());
>> }
>> int sentCount = 0;
>> long loopTime1 = System.currentTimeMillis();
>>
>> Modified: trunk/freenet/src/freenet/node/PeerNode.java
>> ===================================================================
>> --- trunk/freenet/src/freenet/node/PeerNode.java 2006-06-18 16:36:39 UTC
>> (rev 9302)
>> +++ trunk/freenet/src/freenet/node/PeerNode.java 2006-06-18 17:35:22 UTC
>> (rev 9303)
>> @@ -556,7 +556,7 @@
>> */
>> public void maybeUpdateHandshakeIPs(boolean ignoreHostnames) {
>> long now = System.currentTimeMillis();
>> - if((now - lastAttemptedHandshakeIPUpdateTime) < (5*60*1000)) {
>> + if((now - lastAttemptedHandshakeIPUpdateTime) < (5*60*1000)) {
>> // 5 minutes
>> //Logger.minor(this, "Looked up recently (detectedPeer
>> = "+detectedPeer + " : "+((detectedPeer == null) ? "" :
>> detectedPeer.getAddress(false).toString()));
>> return; // 5 minutes FIXME
>> }
>> @@ -628,7 +628,7 @@
>> detectedPeer = detectedDuplicate;
>> }
>> }
>> - Logger.minor(this, "3: detectedPeer = "+detectedPeer+"
>> ("+detectedPeer.getAddress(false));
>> + Logger.minor(this, "3: detectedPeer = "+detectedPeer+"
>> ("+detectedPeer.getAddress(false)+")");
>> Logger.minor(this, "3: maybeUpdateHandshakeIPs got a result of:
>> "+handshakeIPsToString());
>> return;
>> }
>>
