Measure time taken for reachability checks

Reason why this change is needed:
Getting this metric will help estimate how much time will be saved once
the reachability checks get optimized

What this patch does:
Measure time spent by requestValidator.checkWants() in parseWants() and save
it in an instance of PackStatistics.Accumulator.

Signed-off-by: Alexa Panfil <alexapizza@google.com>
Change-Id: Id7fe4016f96549d9511a2c24052dad93cfbb31a4

2 files changed, 53 insertions, 8 deletions

diff --git a/org.eclipse.jgit/src/org/eclipse/jgit/storage/pack/PackStatistics.java b/org.eclipse.jgit/src/org/eclipse/jgit/storage/pack/PackStatistics.java
index 645da0a068..e5ed080618 100644
--- a/org.eclipse.jgit/src/org/eclipse/jgit/storage/pack/PackStatistics.java
+++ b/org.eclipse.jgit/src/org/eclipse/jgit/storage/pack/PackStatistics.java
@@ -188,6 +188,13 @@ public class PackStatistics {
 		public long haves;
 
 		/**
+		 * The count of wants that were not advertised by the server.
+		 *
+		 * @since 5.10
+		 */
+		public long notAdvertisedWants;
+
+		/**
 		 * Time in ms spent in the negotiation phase. For non-bidirectional
 		 * transports (e.g., HTTP), this is only for the final request that
 		 * sends back the pack file.
@@ -266,6 +273,11 @@ public class PackStatistics {
 		/** Time in ms spent writing the pack. */
 		public long timeWriting;
 
+		/** Time in ms spent checking reachability.
+		 * @since 5.10
+		 */
+		public long reachabilityCheckDuration;
+
 		/** Number of trees traversed in the walk when writing the pack.
 		 * @since 5.4*/
 		public long treesTraversed;
@@ -349,6 +361,16 @@ public class PackStatistics {
 	}
 
 	/**
+	 * Get the count of client wants that were not advertised by the server.
+	 *
+	 * @return count of client wants that were not advertised by the server.
+	 * @since 5.10
+	 */
+	public long getNotAdvertisedWants() {
+		return statistics.notAdvertisedWants;
+	}
+
+	/**
 	 * Time in ms spent in the negotiation phase. For non-bidirectional
 	 * transports (e.g., HTTP), this is only for the final request that sends
 	 * back the pack file.
@@ -604,6 +626,18 @@ public class PackStatistics {
 	}
 
 	/**
+	 * Get time in milliseconds spent checking if the client has access to the
+	 * commits they are requesting.
+	 *
+	 * @return time in milliseconds spent checking if the client has access to the
+	 * commits they are requesting.
+	 * @since 5.10
+	 */
+	public long getReachabilityCheckDuration() {
+		return statistics.reachabilityCheckDuration;
+	}
+
+	/**
 	 * @return number of trees traversed in the walk when writing the pack.
 	 * @since 5.4
 	 */
diff --git a/org.eclipse.jgit/src/org/eclipse/jgit/transport/UploadPack.java b/org.eclipse.jgit/src/org/eclipse/jgit/transport/UploadPack.java
index 8c243d439b..26c7ab7531 100644
--- a/org.eclipse.jgit/src/org/eclipse/jgit/transport/UploadPack.java
+++ b/org.eclipse.jgit/src/org/eclipse/jgit/transport/UploadPack.java
@@ -1189,7 +1189,8 @@ public class UploadPack {
 
 		if (req.wasDoneReceived()) {
 			processHaveLines(req.getPeerHas(), ObjectId.zeroId(),
-					new PacketLineOut(NullOutputStream.INSTANCE));
+					new PacketLineOut(NullOutputStream.INSTANCE),
+					accumulator);
 		} else {
 			pckOut.writeString("acknowledgments\n"); //$NON-NLS-1$
 			for (ObjectId id : req.getPeerHas()) {
@@ -1198,7 +1199,8 @@ public class UploadPack {
 				}
 			}
 			processHaveLines(req.getPeerHas(), ObjectId.zeroId(),
-					new PacketLineOut(NullOutputStream.INSTANCE));
+					new PacketLineOut(NullOutputStream.INSTANCE),
+					accumulator);
 			if (okToGiveUp()) {
 				pckOut.writeString("ready\n"); //$NON-NLS-1$
 			} else if (commonBase.isEmpty()) {
@@ -1648,7 +1650,7 @@ public class UploadPack {
 			}
 
 			if (PacketLineIn.isEnd(line)) {
-				last = processHaveLines(peerHas, last, pckOut);
+				last = processHaveLines(peerHas, last, pckOut, accumulator);
 				if (commonBase.isEmpty() || multiAck != MultiAck.OFF)
 					pckOut.writeString("NAK\n"); //$NON-NLS-1$
 				if (noDone && sentReady) {
@@ -1663,7 +1665,7 @@ public class UploadPack {
 				peerHas.add(ObjectId.fromString(line.substring(5)));
 				accumulator.haves++;
 			} else if (line.equals("done")) { //$NON-NLS-1$
-				last = processHaveLines(peerHas, last, pckOut);
+				last = processHaveLines(peerHas, last, pckOut, accumulator);
 
 				if (commonBase.isEmpty())
 					pckOut.writeString("NAK\n"); //$NON-NLS-1$
@@ -1679,11 +1681,12 @@ public class UploadPack {
 		}
 	}
 
-	private ObjectId processHaveLines(List<ObjectId> peerHas, ObjectId last, PacketLineOut out)
+	private ObjectId processHaveLines(List<ObjectId> peerHas, ObjectId last,
+			PacketLineOut out, PackStatistics.Accumulator accumulator)
 			throws IOException {
 		preUploadHook.onBeginNegotiateRound(this, wantIds, peerHas.size());
 		if (wantAll.isEmpty() && !wantIds.isEmpty())
-			parseWants();
+			parseWants(accumulator);
 		if (peerHas.isEmpty())
 			return last;
 
@@ -1780,7 +1783,7 @@ public class UploadPack {
 		return last;
 	}
 
-	private void parseWants() throws IOException {
+	private void parseWants(PackStatistics.Accumulator accumulator) throws IOException {
 		List<ObjectId> notAdvertisedWants = null;
 		for (ObjectId obj : wantIds) {
 			if (!advertised.contains(obj)) {
@@ -1789,9 +1792,17 @@ public class UploadPack {
 				notAdvertisedWants.add(obj);
 			}
 		}
-		if (notAdvertisedWants != null)
+		if (notAdvertisedWants != null) {
+			accumulator.notAdvertisedWants = notAdvertisedWants.size();
+
+			long startReachabilityChecking = System.currentTimeMillis();
+
 			requestValidator.checkWants(this, notAdvertisedWants);
 
+			accumulator.reachabilityCheckDuration = System.currentTimeMillis() -
+					startReachabilityChecking;
+		}
+
 		AsyncRevObjectQueue q = walk.parseAny(wantIds, true);
 		try {
 			RevObject obj;