UploadPack: Expose PackWriter activity to a logger

The UploadPackLogger interface allows applications that embed
GitServlet or otherwise use UploadPack to service clients to
track and log how PackWriter was used, and what it sent.  This
provides more granularity into the request activity than might
be available from the HTTP server logs, helping administrators
to better understand utilization and Git server performance.

Change-Id: I1d36b060eb3385339d5f986e68192789ef70fc4e
Signed-off-by: Shawn O. Pearce <spearce@spearce.org>

org.eclipse.jgit/src/org/eclipse/jgit/storage/pack/PackWriter.java

@@ -575,14 +575,26 @@ public class PackWriter {
 		stats.totalObjects = objCnt;
 
 		writeMonitor.beginTask(JGitText.get().writingObjects, (int) objCnt);
+		long writeStart = System.currentTimeMillis();
+
+		long headerStart = out.length();
 		out.writeFileHeader(PACK_VERSION_GENERATED, objCnt);
 		out.flush();
+		long headerEnd = out.length();
+
 		writeObjects(out);
+		if (!edgeObjects.isEmpty() || !cachedPacks.isEmpty())
+			stats.thinPackBytes = out.length() - (headerEnd - headerStart);
+
 		for (CachedPack pack : cachedPacks) {
 			stats.reusedObjects += pack.getObjectCount();
 			reuseSupport.copyPackAsIs(out, pack);
 		}
 		writeChecksum(out);
+		out.flush();
+		stats.timeWriting = System.currentTimeMillis() - writeStart;
+		stats.totalBytes = out.length();
+		stats.reusedPacks = Collections.unmodifiableList(cachedPacks);
 
 		reader.release();
 		writeMonitor.endTask();
@@ -739,9 +751,16 @@ public class PackWriter {
 		if (cnt == 0)
 			return;
 
+		final long searchStart = System.currentTimeMillis();
 		monitor.beginTask(JGitText.get().compressingObjects, nonEdgeCnt);
 		searchForDeltas(monitor, list, cnt);
 		monitor.endTask();
+		stats.deltaSearchNonEdgeObjects = nonEdgeCnt;
+		stats.timeCompressing = System.currentTimeMillis() - searchStart;
+
+		for (int i = 0; i < cnt; i++)
+			if (!list[i].isEdge() && list[i].isDeltaRepresentation())
+				stats.deltasFound++;
 	}
 
 	private int findObjectsNeedingDelta(ObjectToPack[] list, int cnt, int type) {
@@ -1079,12 +1098,16 @@ public class PackWriter {
 			Collection<? extends ObjectId> have)
 			throws MissingObjectException, IOException,
 			IncorrectObjectTypeException {
+		final long countingStart = System.currentTimeMillis();
 		countingMonitor.beginTask(JGitText.get().countingObjects,
 				ProgressMonitor.UNKNOWN);
 
 		if (have == null)
 			have = Collections.emptySet();
 
+		stats.interestingObjects = Collections.unmodifiableSet(new HashSet(want));
+		stats.uninterestingObjects = Collections.unmodifiableSet(new HashSet(have));
+
 		List<ObjectId> all = new ArrayList<ObjectId>(want.size() + have.size());
 		all.addAll(want);
 		all.addAll(have);
@@ -1227,6 +1250,7 @@ public class PackWriter {
 		for (CachedPack pack : cachedPacks)
 			countingMonitor.update((int) pack.getObjectCount());
 		countingMonitor.endTask();
+		stats.timeCounting = System.currentTimeMillis() - countingStart;
 	}
 
 	private void pruneObjectList(int typesToPrune, int typeCode) {
@@ -1380,6 +1404,16 @@ public class PackWriter {
 
 	/** Summary of how PackWriter created the pack. */
 	public static class Statistics {
+		Set<ObjectId> interestingObjects;
+
+		Set<ObjectId> uninterestingObjects;
+
+		Collection<CachedPack> reusedPacks;
+
+		int deltaSearchNonEdgeObjects;
+
+		int deltasFound;
+
 		long totalObjects;
 
 		long totalDeltas;
@@ -1388,6 +1422,150 @@ public class PackWriter {
 
 		long reusedDeltas;
 
+		long totalBytes;
+
+		long thinPackBytes;
+
+		long timeCounting;
+
+		long timeCompressing;
+
+		long timeWriting;
+
+		/**
+		 * @return unmodifiable collection of objects to be included in the
+		 *         pack. May be null if the pack was hand-crafted in a unit
+		 *         test.
+		 */
+		public Set<ObjectId> getInterestingObjects() {
+			return interestingObjects;
+		}
+
+		/**
+		 * @return unmodifiable collection of objects that should be excluded
+		 *         from the pack, as the peer that will receive the pack already
+		 *         has these objects.
+		 */
+		public Set<ObjectId> getUninterestingObjects() {
+			return uninterestingObjects;
+		}
+
+		/**
+		 * @return unmodifiable collection of the cached packs that were reused
+		 *         in the output, if any were selected for reuse.
+		 */
+		public Collection<CachedPack> getReusedPacks() {
+			return reusedPacks;
+		}
+
+		/**
+		 * @return number of objects in the output pack that went through the
+		 *         delta search process in order to find a potential delta base.
+		 */
+		public int getDeltaSearchNonEdgeObjects() {
+			return deltaSearchNonEdgeObjects;
+		}
+
+		/**
+		 * @return number of objects in the output pack that went through delta
+		 *         base search and found a suitable base. This is a subset of
+		 *         {@link #getDeltaSearchNonEdgeObjects()}.
+		 */
+		public int getDeltasFound() {
+			return deltasFound;
+		}
+
+		/**
+		 * @return total number of objects output. This total includes the value
+		 *         of {@link #getTotalDeltas()}.
+		 */
+		public long getTotalObjects() {
+			return totalObjects;
+		}
+
+		/**
+		 * @return total number of deltas output. This may be lower than the
+		 *         actual number of deltas if a cached pack was reused.
+		 */
+		public long getTotalDeltas() {
+			return totalDeltas;
+		}
+
+		/**
+		 * @return number of objects whose existing representation was reused in
+		 *         the output. This count includes {@link #getReusedDeltas()}.
+		 */
+		public long getReusedObjects() {
+			return reusedObjects;
+		}
+
+		/**
+		 * @return number of deltas whose existing representation was reused in
+		 *         the output, as their base object was also output or was
+		 *         assumed present for a thin pack. This may be lower than the
+		 *         actual number of reused deltas if a cached pack was reused.
+		 */
+		public long getReusedDeltas() {
+			return reusedDeltas;
+		}
+
+		/**
+		 * @return total number of bytes written. This size includes the pack
+		 *         header, trailer, thin pack, and reused cached pack(s).
+		 */
+		public long getTotalBytes() {
+			return totalBytes;
+		}
+
+		/**
+		 * @return size of the thin pack in bytes, if a thin pack was generated.
+		 *         A thin pack is created when the client already has objects
+		 *         and some deltas are created against those objects, or if a
+		 *         cached pack is being used and some deltas will reference
+		 *         objects in the cached pack. This size does not include the
+		 *         pack header or trailer.
+		 */
+		public long getThinPackBytes() {
+			return thinPackBytes;
+		}
+
+		/**
+		 * @return time in milliseconds spent enumerating the objects that need
+		 *         to be included in the output. This time includes any restarts
+		 *         that occur when a cached pack is selected for reuse.
+		 */
+		public long getTimeCounting() {
+			return timeCounting;
+		}
+
+		/**
+		 * @return time in milliseconds spent on delta compression. This is
+		 *         observed wall-clock time and does not accurately track CPU
+		 *         time used when multiple threads were used to perform the
+		 *         delta compression.
+		 */
+		public long getTimeCompressing() {
+			return timeCompressing;
+		}
+
+		/**
+		 * @return time in milliseconds spent writing the pack output, from
+		 *         start of header until end of trailer. The transfer speed can
+		 *         be approximated by dividing {@link #getTotalBytes()} by this
+		 *         value.
+		 */
+		public long getTimeWriting() {
+			return timeWriting;
+		}
+
+		/**
+		 * @return get the average output speed in terms of bytes-per-second.
+		 *         {@code getTotalBytes() / (getTimeWriting() / 1000.0)}.
+		 */
+		public double getTransferRate() {
+			return getTotalBytes() / (getTimeWriting() / 1000.0);
+		}
+
 		/** @return formatted message string for display to clients. */
 		public String getMessage() {
 			return MessageFormat.format(JGitText.get().packWriterStatistics, //

org.eclipse.jgit/src/org/eclipse/jgit/transport/BasePackPushConnection.java

@@ -246,7 +246,6 @@ public abstract class BasePackPushConnection extends BasePackConnection implemen
 		List<ObjectId> remoteObjects = new ArrayList<ObjectId>(getRefs().size());
 		List<ObjectId> newObjects = new ArrayList<ObjectId>(refUpdates.size());
 
-		final long start;
 		final PackWriter writer = new PackWriter(transport.getPackConfig(),
 				local.newObjectReader());
 		try {
@@ -263,13 +262,11 @@ public abstract class BasePackPushConnection extends BasePackConnection implemen
 			writer.setThin(thinPack);
 			writer.setDeltaBaseAsOffset(capableOfsDelta);
 			writer.preparePack(monitor, newObjects, remoteObjects);
-			start = System.currentTimeMillis();
 			writer.writePack(monitor, monitor, out);
 		} finally {
 			writer.release();
 		}
-		out.flush();
-		packTransferTime = System.currentTimeMillis() - start;
+		packTransferTime = writer.getStatistics().getTimeWriting();
 	}
 
 	private void readStatusReport(final Map<String, RemoteRefUpdate> refUpdates)

org.eclipse.jgit/src/org/eclipse/jgit/transport/UploadPack.java

@@ -179,6 +179,10 @@ public class UploadPack {
 
 	private MultiAck multiAck = MultiAck.OFF;
 
+	private PackWriter.Statistics statistics;
+
+	private UploadPackLogger logger;
+
 	/**
 	 * Create a new pack upload for an open repository.
 	 *
@@ -283,6 +287,16 @@ public class UploadPack {
 		this.packConfig = pc;
 	}
 
+	/**
+	 * Set the logger.
+	 *
+	 * @param logger
+	 *            the logger instance. If null, no logging occurs.
+	 */
+	public void setLogger(UploadPackLogger logger) {
+		this.logger = logger;
+	}
+
 	/**
 	 * Execute the upload task on the socket.
 	 *
@@ -332,6 +346,17 @@ public class UploadPack {
 		}
 	}
 
+	/**
+	 * Get the PackWriter's statistics if a pack was sent to the client.
+	 *
+	 * @return statistics about pack output, if a pack was sent. Null if no pack
+	 *         was sent, such as during the negotation phase of a smart HTTP
+	 *         connection, or if the client was already up-to-date.
+	 */
+	public PackWriter.Statistics getPackStatistics() {
+		return statistics;
+	}
+
 	private void service() throws IOException {
 		if (biDirectionalPipe)
 			sendAdvertisedRefs(new PacketLineOutRefAdvertiser(pckOut));
@@ -704,7 +729,7 @@ public class UploadPack {
 			}
 
 			pw.writePack(pm, NullProgressMonitor.INSTANCE, packOut);
-			packOut.flush();
+			statistics = pw.getStatistics();
 
 			if (msgOut != null) {
 				String msg = pw.getStatistics().getMessage() + '\n';
@@ -718,5 +743,8 @@ public class UploadPack {
 
 		if (sideband)
 			pckOut.end();
+
+		if (logger != null && statistics != null)
+			logger.onPackStatistics(statistics);
 	}
 }

org.eclipse.jgit/src/org/eclipse/jgit/transport/UploadPackLogger.java

@@ -0,0 +1,64 @@
+/*
+ * Copyright (C) 2011, Google Inc.
+ * and other copyright owners as documented in the project's IP log.
+ *
+ * This program and the accompanying materials are made available
+ * under the terms of the Eclipse Distribution License v1.0 which
+ * accompanies this distribution, is reproduced below, and is
+ * available at http://www.eclipse.org/org/documents/edl-v10.php
+ *
+ * All rights reserved.
+ *
+ * Redistribution and use in source and binary forms, with or
+ * without modification, are permitted provided that the following
+ * conditions are met:
+ *
+ * - Redistributions of source code must retain the above copyright
+ *   notice, this list of conditions and the following disclaimer.
+ *
+ * - Redistributions in binary form must reproduce the above
+ *   copyright notice, this list of conditions and the following
+ *   disclaimer in the documentation and/or other materials provided
+ *   with the distribution.
+ *
+ * - Neither the name of the Eclipse Foundation, Inc. nor the
+ *   names of its contributors may be used to endorse or promote
+ *   products derived from this software without specific prior
+ *   written permission.
+ *
+ * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND
+ * CONTRIBUTORS "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES,
+ * INCLUDING, BUT NOT LIMITED TO, THE IMPLIED WARRANTIES
+ * OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
+ * ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT OWNER OR
+ * CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
+ * SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT
+ * NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES;
+ * LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER
+ * CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT,
+ * STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE)
+ * ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF
+ * ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
+ */
+
+package org.eclipse.jgit.transport;
+
+import org.eclipse.jgit.storage.pack.PackWriter;
+
+/**
+ * Logs activity that occurred within {@link UploadPack}.
+ * <p>
+ * Implementors of the interface are responsible for associating the current
+ * thread to a particular connection, if they need to also include connection
+ * information. One method is to use a {@link java.lang.ThreadLocal} to remember
+ * the connection information before invoking UploadPack.
+ */
+public interface UploadPackLogger {
+	/**
+	 * Notice to the logger after a pack has been sent.
+	 *
+	 * @param stats
+	 *            the statistics after sending a pack to the client.
+	 */
+	public void onPackStatistics(PackWriter.Statistics stats);
+}