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...
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;
> }
>
> _______________________________________________
> cvs mailing list
> cvs at freenetproject.org
> http://emu.freenetproject.org/cgi-bin/mailman/listinfo/cvs
>
--
Matthew J Toseland - toad at amphibian.dyndns.org
Freenet Project Official Codemonkey - http://freenetproject.org/
ICTHUS - Nothing is impossible. Our Boss says so.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 189 bytes
Desc: Digital signature
URL:
<https://emu.freenetproject.org/pipermail/cvs/attachments/20060620/4b33e00f/attachment.pgp>
