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

3 files changed, 175 insertions, 19 deletions

diff --git a/org.eclipse.jgit.test/tst/org/eclipse/jgit/transport/UploadPackTest.java b/org.eclipse.jgit.test/tst/org/eclipse/jgit/transport/UploadPackTest.java
index 945900f14b..55caa64d87 100644
--- a/org.eclipse.jgit.test/tst/org/eclipse/jgit/transport/UploadPackTest.java
+++ b/org.eclipse.jgit.test/tst/org/eclipse/jgit/transport/UploadPackTest.java
@@ -361,21 +361,21 @@ public class UploadPackTest {
 	}
 
 	/*
-	 * Invokes UploadPack with protocol v2 and sends it the given lines,
+	 * Invokes UploadPack with specified protocol version and sends it the given lines,
 	 * and returns UploadPack's output stream.
 	 */
-	private ByteArrayInputStream uploadPackV2Setup(
+	private ByteArrayInputStream uploadPackSetup(String version,
 			Consumer<UploadPack> postConstructionSetup, String... inputLines)
 			throws Exception {
 
 		ByteArrayInputStream send = linesAsInputStream(inputLines);
 
-		server.getConfig().setString("protocol", null, "version", "2");
+		server.getConfig().setString("protocol", null, "version", version);
 		UploadPack up = new UploadPack(server);
 		if (postConstructionSetup != null) {
 			postConstructionSetup.accept(up);
 		}
-		up.setExtraParameters(Sets.of("version=2"));
+		up.setExtraParameters(Sets.of("version=".concat(version)));
 
 		ByteArrayOutputStream recv = new ByteArrayOutputStream();
 		up.upload(send, recv, null);
@@ -403,6 +403,30 @@ public class UploadPackTest {
 	}
 
 	/*
+	 * Invokes UploadPack with protocol v1 and sends it the given lines.
+	 * Returns UploadPack's output stream, not including the capability
+	 * advertisement by the server.
+	 */
+	private ByteArrayInputStream uploadPackV1(
+			Consumer<UploadPack> postConstructionSetup,
+			String... inputLines)
+			throws Exception {
+		ByteArrayInputStream recvStream =
+				uploadPackSetup("1", postConstructionSetup, inputLines);
+		PacketLineIn pckIn = new PacketLineIn(recvStream);
+
+		// drain capabilities
+		while (!PacketLineIn.isEnd(pckIn.readString())) {
+			// do nothing
+		}
+		return recvStream;
+	}
+
+	private ByteArrayInputStream uploadPackV1(String... inputLines) throws Exception {
+		return uploadPackV1(null, inputLines);
+	}
+
+	/*
 	 * Invokes UploadPack with protocol v2 and sends it the given lines.
 	 * Returns UploadPack's output stream, not including the capability
 	 * advertisement by the server.
@@ -412,7 +436,7 @@ public class UploadPackTest {
 			String... inputLines)
 			throws Exception {
 		ByteArrayInputStream recvStream =
-				uploadPackV2Setup(postConstructionSetup, inputLines);
+				uploadPackSetup("2", postConstructionSetup, inputLines);
 		PacketLineIn pckIn = new PacketLineIn(recvStream);
 
 		// drain capabilities
@@ -452,7 +476,7 @@ public class UploadPackTest {
 	@Test
 	public void testV2Capabilities() throws Exception {
 		TestV2Hook hook = new TestV2Hook();
-		ByteArrayInputStream recvStream = uploadPackV2Setup(
+		ByteArrayInputStream recvStream = uploadPackSetup( "2",
 				(UploadPack up) -> {up.setProtocolV2Hook(hook);},
 				PacketLineIn.end());
 		PacketLineIn pckIn = new PacketLineIn(recvStream);
@@ -475,7 +499,7 @@ public class UploadPackTest {
 			String fetchCapability) throws Exception {
 		server.getConfig().setBoolean(configSection, null, configName, true);
 		ByteArrayInputStream recvStream =
-				uploadPackV2Setup(null, PacketLineIn.end());
+				uploadPackSetup("2", null, PacketLineIn.end());
 		PacketLineIn pckIn = new PacketLineIn(recvStream);
 
 		assertThat(pckIn.readString(), is("version 2"));
@@ -499,7 +523,7 @@ public class UploadPackTest {
 			String configName, String fetchCapability) throws Exception {
 		server.getConfig().setBoolean(configSection, null, configName, false);
 		ByteArrayInputStream recvStream =
-				uploadPackV2Setup(null, PacketLineIn.end());
+				uploadPackSetup("2", null, PacketLineIn.end());
 		PacketLineIn pckIn = new PacketLineIn(recvStream);
 
 		assertThat(pckIn.readString(), is("version 2"));
@@ -551,7 +575,7 @@ public class UploadPackTest {
 		server.getConfig().setBoolean("uploadpack", null, "allowrefinwant", true);
 		server.getConfig().setBoolean("uploadpack", null, "advertiserefinwant", false);
 		ByteArrayInputStream recvStream =
-				uploadPackV2Setup(null, PacketLineIn.end());
+				uploadPackSetup("2", null, PacketLineIn.end());
 		PacketLineIn pckIn = new PacketLineIn(recvStream);
 
 		assertThat(pckIn.readString(), is("version 2"));
@@ -715,7 +739,7 @@ public class UploadPackTest {
 				PacketLineIn.end() };
 
 		TestV2Hook testHook = new TestV2Hook();
-		uploadPackV2Setup((UploadPack up) -> {up.setProtocolV2Hook(testHook);}, lines);
+		uploadPackSetup("2", (UploadPack up) -> {up.setProtocolV2Hook(testHook);}, lines);
 
 		LsRefsV2Request req = testHook.lsRefsRequest;
 		assertEquals(2, req.getServerOptions().size());
@@ -1532,7 +1556,7 @@ public class UploadPackTest {
 				PacketLineIn.end() };
 
 		TestV2Hook testHook = new TestV2Hook();
-		uploadPackV2Setup((UploadPack up) -> {up.setProtocolV2Hook(testHook);}, lines);
+		uploadPackSetup("2", (UploadPack up) -> {up.setProtocolV2Hook(testHook);}, lines);
 
 		FetchV2Request req = testHook.fetchRequest;
 		assertNotNull(req);
@@ -2385,6 +2409,93 @@ public class UploadPackTest {
 		assertEquals(1, ((RefCallsCountingRepository)server).numRefCalls());
 	}
 
+	@Test
+	public void testNotAdvertisedWantsV1Fetch() throws Exception {
+		String commonInBlob = "abcdefghijklmnopqrstuvwxyz";
+
+		RevBlob parentBlob = remote.blob(commonInBlob + "a");
+		RevCommit parent = remote
+				.commit(remote.tree(remote.file("foo", parentBlob)));
+		RevBlob childBlob = remote.blob(commonInBlob + "b");
+		RevCommit child = remote
+				.commit(remote.tree(remote.file("foo", childBlob)), parent);
+		remote.update("branch1", child);
+
+		uploadPackV1("want " + child.toObjectId().getName() + "\n",
+				PacketLineIn.end(),
+				"have " + parent.toObjectId().getName() + "\n",
+				"done\n", PacketLineIn.end());
+
+		assertEquals(0, stats.getNotAdvertisedWants());
+	}
+
+	@Test
+	public void testNotAdvertisedWantsV1FetchRequestPolicyReachableCommit() throws Exception {
+		String commonInBlob = "abcdefghijklmnopqrstuvwxyz";
+
+		RevBlob parentBlob = remote.blob(commonInBlob + "a");
+		RevCommit parent = remote
+				.commit(remote.tree(remote.file("foo", parentBlob)));
+		RevBlob childBlob = remote.blob(commonInBlob + "b");
+		RevCommit child = remote
+				.commit(remote.tree(remote.file("foo", childBlob)), parent);
+
+		remote.update("branch1", child);
+
+		uploadPackV1((UploadPack up) -> {up.setRequestPolicy(RequestPolicy.REACHABLE_COMMIT);},
+				"want " + parent.toObjectId().getName() + "\n",
+				PacketLineIn.end(),
+				"done\n", PacketLineIn.end());
+
+		assertEquals(1, stats.getNotAdvertisedWants());
+	}
+
+	@Test
+	public void testNotAdvertisedWantsV2FetchThinPack() throws Exception {
+		String commonInBlob = "abcdefghijklmnopqrstuvwxyz";
+
+		RevBlob parentBlob = remote.blob(commonInBlob + "a");
+		RevCommit parent = remote
+				.commit(remote.tree(remote.file("foo", parentBlob)));
+		RevBlob childBlob = remote.blob(commonInBlob + "b");
+		RevCommit child = remote
+				.commit(remote.tree(remote.file("foo", childBlob)), parent);
+		remote.update("branch1", child);
+
+		ByteArrayInputStream recvStream = uploadPackV2("command=fetch\n",
+				PacketLineIn.delimiter(),
+				"want " + child.toObjectId().getName() + "\n",
+				"have " + parent.toObjectId().getName() + "\n", "thin-pack\n",
+				"done\n", PacketLineIn.end());
+		PacketLineIn pckIn = new PacketLineIn(recvStream);
+
+		assertThat(pckIn.readString(), is("packfile"));
+
+		assertEquals(0, stats.getNotAdvertisedWants());
+	}
+
+	@Test
+	public void testNotAdvertisedWantsV2FetchRequestPolicyReachableCommit() throws Exception {
+		String commonInBlob = "abcdefghijklmnopqrstuvwxyz";
+
+		RevBlob parentBlob = remote.blob(commonInBlob + "a");
+		RevCommit parent = remote
+				.commit(remote.tree(remote.file("foo", parentBlob)));
+		RevBlob childBlob = remote.blob(commonInBlob + "b");
+		RevCommit child = remote
+				.commit(remote.tree(remote.file("foo", childBlob)), parent);
+
+		remote.update("branch1", child);
+
+		uploadPackV2((UploadPack up) -> {up.setRequestPolicy(RequestPolicy.REACHABLE_COMMIT);},
+				"command=fetch\n",
+				PacketLineIn.delimiter(),
+				"want " + parent.toObjectId().getName() + "\n", "thin-pack\n",
+				"done\n", PacketLineIn.end());
+
+		assertEquals(1, stats.getNotAdvertisedWants());
+	}
+
 	private class RefCallsCountingRepository extends InMemoryRepository {
 		private final InMemoryRepository.MemRefDatabase refdb;
 		private int numRefCalls;
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;