Add timing metrics to ReceivedPackStatistics Instrument ReceivePack to collect timeNegotiating, timeReceiving, timeCheckingConnectivity, and timeProcessingCommands. Prior to this change, ReceivedPackStatistics was fully generated in the PackParser class, which is invoked in the "timeReceiving" phase. Rather than modify the public PackParser interface to return a builder, this change creates a new builder instance from the stats retrieved from PackParser and populates the new timing info in the top-level service() method. * timeNegotiating: Tracks the entire start window up through recvCommands(), including info-refs * timeReceiving: Wraps receivePack() * timeCheckingConnectivity: Wraps checkSubmodules() and checkConnectivity() * timeProcessingCommands: Captures command validation, hook execution, and reference updating Change-Id: I0686749017d2ef66da2a3a227a1c2ed4f1f1e206
diff --git a/org.eclipse.jgit/src/org/eclipse/jgit/transport/ReceivePack.java b/org.eclipse.jgit/src/org/eclipse/jgit/transport/ReceivePack.java index 3d9c81c..0ee0ad5 100644 --- a/org.eclipse.jgit/src/org/eclipse/jgit/transport/ReceivePack.java +++ b/org.eclipse.jgit/src/org/eclipse/jgit/transport/ReceivePack.java
@@ -34,6 +34,8 @@ import java.io.OutputStream; import java.io.UncheckedIOException; import java.text.MessageFormat; +import java.time.Duration; +import java.time.Instant; import java.util.ArrayList; import java.util.Collections; import java.util.HashMap; @@ -236,6 +238,8 @@ public class ReceivePack { private PushCertificate pushCert; private ReceivedPackStatistics stats; + private long timeReceiving; + private long timeCheckingConnectivity; /** * Connectivity checker to use. @@ -1202,11 +1206,16 @@ private Map<String, Ref> getAdvertisedOrDefaultRefs() throws IOException { */ protected void receivePackAndCheckConnectivity() throws IOException, LargeObjectException, SubmoduleValidationException { + Instant start = Instant.now(); receivePack(); + timeReceiving = Duration.between(start, Instant.now()).toMillis(); + if (needCheckConnectivity()) { checkSubmodules(); checkConnectivity(); } + timeCheckingConnectivity = Duration.between(start, Instant.now()) + .toMillis() - timeReceiving; parser = null; } @@ -2226,6 +2235,7 @@ public void receiveWithExceptionPropagation(InputStream input, } private void service() throws IOException { + Instant startNegotiating = Instant.now(); if (isBiDirectionalPipe()) { sendAdvertisedRefs(new PacketLineOutRefAdvertiser(pckOut)); pckOut.flush(); @@ -2235,6 +2245,8 @@ private void service() throws IOException { return; recvCommands(); + long timeNegotiating = Duration.between(startNegotiating, Instant.now()) + .toMillis(); if (hasCommands()) { try (PostReceiveExecutor e = new PostReceiveExecutor()) { @@ -2249,6 +2261,7 @@ private void service() throws IOException { } } + Instant startProcessing = Instant.now(); try { setAtomic(isCapabilityEnabled(CAPABILITY_ATOMIC)); @@ -2266,6 +2279,17 @@ private void service() throws IOException { } finally { unlockPack(); } + long timeProcessingCommands = Duration + .between(startProcessing, Instant.now()).toMillis(); + + ReceivedPackStatistics.Builder statsBuilder = stats != null + ? ReceivedPackStatistics.Builder.toBuilder(stats) + : new ReceivedPackStatistics.Builder(); + stats = statsBuilder.setTimeNegotiating(timeNegotiating) + .setTimeReceiving(timeReceiving) + .setTimeCheckingConnectivity(timeCheckingConnectivity) + .setTimeProcessingCommands(timeProcessingCommands) + .build(); sendStatusReport(null); }
diff --git a/org.eclipse.jgit/src/org/eclipse/jgit/transport/ReceivedPackStatistics.java b/org.eclipse.jgit/src/org/eclipse/jgit/transport/ReceivedPackStatistics.java index 8887e26..f804c31 100644 --- a/org.eclipse.jgit/src/org/eclipse/jgit/transport/ReceivedPackStatistics.java +++ b/org.eclipse.jgit/src/org/eclipse/jgit/transport/ReceivedPackStatistics.java
@@ -34,6 +34,11 @@ public class ReceivedPackStatistics { private long numDeltaBlob; private long numDeltaTag; + private long timeNegotiating; + private long timeReceiving; + private long timeCheckingConnectivity; + private long timeProcessingCommands; + /** * Get number of bytes read from the input stream * @@ -155,6 +160,49 @@ public long getNumDeltaTag() { return numDeltaTag; } + /** + * Get time in milliseconds spent in the negotiation phase + * + * @return time in milliseconds spent in the negotiation phase + * @since 7.7 + */ + public long getTimeNegotiating() { + return timeNegotiating; + } + + /** + * Get time in milliseconds spent receiving the pack + * + * @return time in milliseconds spent receiving the pack + * @since 7.7 + */ + public long getTimeReceiving() { + return timeReceiving; + } + + /** + * Get time in milliseconds spent checking the connectivity of the received + * pack + * + * @return time in milliseconds spent checking the connectivity of the + * received pack + * @since 7.7 + */ + public long getTimeCheckingConnectivity() { + return timeCheckingConnectivity; + } + + /** + * Get time in milliseconds spent processing commands (validation, hooks, + * and ref updates) + * + * @return time in milliseconds spent processing commands + * @since 7.7 + */ + public long getTimeProcessingCommands() { + return timeProcessingCommands; + } + /** A builder for {@link ReceivedPackStatistics}. */ public static class Builder { private long numBytesRead; @@ -173,6 +221,39 @@ public static class Builder { private long numDeltaBlob; private long numDeltaTag; + private long timeNegotiating; + private long timeReceiving; + private long timeCheckingConnectivity; + private long timeProcessingCommands; + + /** + * Initialize from an existing ReceivedPackStatistics. + * + * @param s + * existing ReceivedPackStatistics object + * @return new Builder instance + * @since 7.7 + */ + public static Builder toBuilder(ReceivedPackStatistics s) { + Builder b = new Builder(); + b.numBytesRead = s.getNumBytesRead(); + b.numWholeCommit = s.getNumWholeCommit(); + b.numWholeTree = s.getNumWholeTree(); + b.numWholeBlob = s.getNumWholeBlob(); + b.numWholeTag = s.getNumWholeTag(); + b.numOfsDelta = s.getNumOfsDelta(); + b.numRefDelta = s.getNumRefDelta(); + b.numDeltaCommit = s.getNumDeltaCommit(); + b.numDeltaTree = s.getNumDeltaTree(); + b.numDeltaBlob = s.getNumDeltaBlob(); + b.numDeltaTag = s.getNumDeltaTag(); + b.timeNegotiating = s.getTimeNegotiating(); + b.timeReceiving = s.getTimeReceiving(); + b.timeCheckingConnectivity = s.getTimeCheckingConnectivity(); + b.timeProcessingCommands = s.getTimeProcessingCommands(); + return b; + } + /** * Set number of bytes read from the input stream * @@ -226,6 +307,52 @@ public Builder addWholeObject(int type) { } /** + * @param timeNegotiating + * time in milliseconds spent in the negotiation phase + * @return this + * @since 7.7 + */ + public Builder setTimeNegotiating(long timeNegotiating) { + this.timeNegotiating = timeNegotiating; + return this; + } + + /** + * @param timeReceiving + * time in milliseconds spent receiving the pack + * @return this + * @since 7.7 + */ + public Builder setTimeReceiving(long timeReceiving) { + this.timeReceiving = timeReceiving; + return this; + } + + /** + * @param timeCheckingConnectivity + * time in milliseconds spent checking the connectivity of + * the received pack + * @return this + * @since 7.7 + */ + public Builder setTimeCheckingConnectivity( + long timeCheckingConnectivity) { + this.timeCheckingConnectivity = timeCheckingConnectivity; + return this; + } + + /** + * @param timeProcessingCommands + * time in milliseconds spent processing commands + * @return this + * @since 7.7 + */ + public Builder setTimeProcessingCommands(long timeProcessingCommands) { + this.timeProcessingCommands = timeProcessingCommands; + return this; + } + + /** * Increment offset delta * * @return this @@ -299,6 +426,10 @@ ReceivedPackStatistics build() { s.numDeltaBlob = numDeltaBlob; s.numDeltaTag = numDeltaTag; s.numObjectsDuplicated = numObjectsDuplicated; + s.timeNegotiating = timeNegotiating; + s.timeReceiving = timeReceiving; + s.timeCheckingConnectivity = timeCheckingConnectivity; + s.timeProcessingCommands = timeProcessingCommands; return s; } }