Stopwatch: introduce tool for measuring time mainly for log messages

The helpers from `TimeUtils` are affected by the mock clock, which
is not desired for debug output.

core/src/main/java/org/bitcoinj/base/internal/Stopwatch.java

@@ -0,0 +1,104 @@
+package org.bitcoinj.base.internal;
+
+/*
+ * Copyright by the original author or authors.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *    http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+import java.time.Duration;
+import java.time.Instant;
+import java.time.temporal.ChronoUnit;
+import java.time.temporal.Temporal;
+import java.time.temporal.TemporalAmount;
+import java.time.temporal.TemporalUnit;
+import java.util.Arrays;
+import java.util.List;
+
+import static org.bitcoinj.base.internal.Preconditions.checkArgument;
+
+/**
+ * A tool for measuring time, mainly for log messages. Note this class isn't affected by the mock clock of
+ * {@link TimeUtils}.
+ */
+public class Stopwatch implements TemporalAmount {
+    private final Instant startTime;
+    private Instant stopTime = null;
+
+    /**
+     * Start a newly created stopwatch.
+     *
+     * @return the stopwatch that was just started
+     */
+    public static Stopwatch start() {
+        return new Stopwatch();
+    }
+
+    private Stopwatch() {
+        this.startTime = Instant.now();
+    }
+
+    /**
+     * Stops the stopwatch, if it is running.
+     *
+     * @return the stopwatch that is stopped
+     */
+    public Stopwatch stop() {
+        if (isRunning()) stopTime = Instant.now();
+        return this;
+    }
+
+    /**
+     * Returns true if the stopwatch is running.
+     *
+     * @return true if the stopwatch is running, false otherwise
+     */
+    public boolean isRunning() {
+        return stopTime == null;
+    }
+
+    /**
+     * Gets the elapsed time on the watch. This doesn't stop the watch.
+     *
+     * @return elapsed time
+     */
+    public Duration elapsed() {
+        return Duration.between(startTime, isRunning() ? Instant.now() : stopTime);
+    }
+
+    @Override
+    public long get(TemporalUnit temporalUnit) {
+        checkArgument(temporalUnit.equals(ChronoUnit.MILLIS), () -> "unsupported temporal unit: " + temporalUnit);
+        return elapsed().toMillis();
+    }
+
+    @Override
+    public List<TemporalUnit> getUnits() {
+        return Arrays.asList(ChronoUnit.MILLIS);
+    }
+
+    @Override
+    public Temporal addTo(Temporal temporal) {
+        return temporal.plus(elapsed());
+    }
+
+    @Override
+    public Temporal subtractFrom(Temporal temporal) {
+        return temporal.minus(elapsed());
+    }
+
+    @Override
+    public String toString() {
+        return elapsed().toMillis() + " ms";
+    }
+}

core/src/main/java/org/bitcoinj/base/internal/TimeUtils.java

@@ -72,6 +72,8 @@ public class TimeUtils {
 
     /**
      * Returns elapsed time between given start and current time as a Duration.
+     * <p>
+     * Note that this method is affected by the mock clock. If you want to raise real debug data use {@link Stopwatch}.
      */
     public static Duration elapsedTime(Instant start) {
         return Duration.between(start, currentTime());

core/src/main/java/org/bitcoinj/core/PeerGroup.java

@@ -27,6 +27,7 @@ import com.google.common.util.concurrent.Uninterruptibles;
 import net.jcip.annotations.GuardedBy;
 import org.bitcoinj.base.Network;
 import org.bitcoinj.base.internal.PlatformUtils;
+import org.bitcoinj.base.internal.Stopwatch;
 import org.bitcoinj.base.internal.TimeUtils;
 import org.bitcoinj.core.listeners.AddressEventListener;
 import org.bitcoinj.core.listeners.BlockchainDownloadEventListener;
@@ -1074,7 +1075,7 @@ public class PeerGroup implements TransactionBroadcaster {
         checkState(!lock.isHeldByCurrentThread());
         int maxPeersToDiscoverCount = this.vMaxPeersToDiscoverCount;
         Duration peerDiscoveryTimeout = this.vPeerDiscoveryTimeout;
-        Instant start = TimeUtils.currentTime();
+        Stopwatch watch = Stopwatch.start();
         final List<PeerAddress> addressList = new LinkedList<>();
         for (PeerDiscovery peerDiscovery : peerDiscoverers /* COW */) {
             List<InetSocketAddress> addresses;
@@ -1096,8 +1097,8 @@ public class PeerGroup implements TransactionBroadcaster {
                 registration.executor.execute(() -> registration.listener.onPeersDiscovered(peersDiscoveredSet));
             }
         }
-        log.info("Peer discovery took {} ms and returned {} items from {} discoverers",
+        log.info("Peer discovery took {} and returned {} items from {} discoverers",
-                TimeUtils.elapsedTime(start).toMillis(), addressList.size(), peerDiscoverers.size());
+                watch, addressList.size(), peerDiscoverers.size());
         return addressList.size();
     }
 
@@ -1181,7 +1182,7 @@ public class PeerGroup implements TransactionBroadcaster {
         CompletableFuture<Void> future = CompletableFuture.runAsync(() -> {
             try {
                 log.info("Stopping ...");
-                Instant start = TimeUtils.currentTime();
+                Stopwatch watch = Stopwatch.start();
                 // The log output this creates can be useful.
                 setDownloadPeer(null);
                 // Blocking close of all sockets.
@@ -1191,7 +1192,7 @@ public class PeerGroup implements TransactionBroadcaster {
                     peerDiscovery.shutdown();
                 }
                 vRunning = false;
-                log.info("Stopped, took {} ms.", TimeUtils.elapsedTime(start).toMillis());
+                log.info("Stopped, took {}.", watch);
             } catch (Throwable e) {
                 log.error("Exception when shutting down", e);  // The executor swallows exceptions :(
             }
@@ -1203,11 +1204,11 @@ public class PeerGroup implements TransactionBroadcaster {
     /** Does a blocking stop */
     public void stop() {
         try {
-            Instant start = TimeUtils.currentTime();
+            Stopwatch watch = Stopwatch.start();
             stopAsync();
             log.info("Awaiting PeerGroup shutdown ...");
             executor.awaitTermination(Long.MAX_VALUE, TimeUnit.SECONDS);
-            log.info("... took {} ms", TimeUtils.elapsedTime(start).toMillis());
+            log.info("... took {}", watch);
         } catch (InterruptedException e) {
             throw new RuntimeException(e);
         }

core/src/main/java/org/bitcoinj/crypto/KeyCrypterScrypt.java

@@ -18,6 +18,7 @@
 package org.bitcoinj.crypto;
 
 import com.google.protobuf.ByteString;
+import org.bitcoinj.base.internal.Stopwatch;
 import org.bitcoinj.base.internal.TimeUtils;
 import org.bitcoinj.wallet.Protos;
 import org.bitcoinj.wallet.Protos.ScryptParameters;
@@ -150,9 +151,9 @@ public class KeyCrypterScrypt implements KeyCrypter {
                 log.warn("You are using a ScryptParameters with no salt. Your encryption may be vulnerable to a dictionary attack.");
             }
 
-            Instant start = TimeUtils.currentTime();
+            Stopwatch watch = Stopwatch.start();
             byte[] keyBytes = SCrypt.generate(passwordBytes, salt, (int) scryptParameters.getN(), scryptParameters.getR(), scryptParameters.getP(), KEY_LENGTH);
-            log.info("Deriving key took {} ms for {}.", TimeUtils.elapsedTime(start).toMillis(), scryptParametersString());
+            log.info("Deriving key took {} for {}.", watch, scryptParametersString());
             return new AesKey(keyBytes);
         } catch (Exception e) {
             throw new KeyCrypterException("Could not generate key from password and salt.", e);

core/src/main/java/org/bitcoinj/crypto/MnemonicCode.java

@@ -19,6 +19,7 @@ package org.bitcoinj.crypto;
 
 import org.bitcoinj.base.Sha256Hash;
 import org.bitcoinj.base.internal.PlatformUtils;
+import org.bitcoinj.base.internal.Stopwatch;
 import org.bitcoinj.base.internal.TimeUtils;
 import org.bitcoinj.base.internal.StreamUtils;
 import org.bitcoinj.base.internal.InternalUtils;
@@ -145,9 +146,9 @@ public class MnemonicCode {
         String pass = InternalUtils.SPACE_JOINER.join(words);
         String salt = "mnemonic" + passphrase;
 
-        Instant start = TimeUtils.currentTime();
+        Stopwatch watch = Stopwatch.start();
         byte[] seed = PBKDF2SHA512.derive(pass, salt, PBKDF2_ROUNDS, 64);
-        log.info("PBKDF2 took {} ms", TimeUtils.elapsedTime(start).toMillis());
+        log.info("PBKDF2 took {}", watch);
         return seed;
     }
 

core/src/main/java/org/bitcoinj/params/BitcoinNetworkParams.java

@@ -18,6 +18,7 @@
 package org.bitcoinj.params;
 
 import org.bitcoinj.base.BitcoinNetwork;
+import org.bitcoinj.base.internal.Stopwatch;
 import org.bitcoinj.base.internal.TimeUtils;
 import org.bitcoinj.base.internal.ByteUtils;
 import org.bitcoinj.core.BitcoinSerializer;
@@ -178,7 +179,7 @@ public abstract class BitcoinNetworkParams extends NetworkParameters {
 
         // We need to find a block far back in the chain. It's OK that this is expensive because it only occurs every
         // two weeks after the initial block chain download.
-        Instant start = TimeUtils.currentTime();
+        Stopwatch watch = Stopwatch.start();
         Sha256Hash hash = prev.getHash();
         StoredBlock cursor = null;
         final int interval = this.getInterval();
@@ -193,9 +194,9 @@ public abstract class BitcoinNetworkParams extends NetworkParameters {
         }
         checkState(cursor != null && isDifficultyTransitionPoint(cursor.getHeight() - 1), () ->
                 "didn't arrive at a transition point");
-        Duration elapsed = TimeUtils.elapsedTime(start);
+        watch.stop();
-        if (elapsed.toMillis() > 50)
+        if (watch.elapsed().toMillis() > 50)
-            log.info("Difficulty transition traversal took {} ms", elapsed.toMillis());
+            log.info("Difficulty transition traversal took {}", watch);
 
         Block blockIntervalAgo = cursor.getHeader();
         int timespan = (int) (prev.getTimeSeconds() - blockIntervalAgo.getTimeSeconds());

core/src/main/java/org/bitcoinj/wallet/DeterministicKeyChain.java

@@ -20,6 +20,7 @@ import com.google.common.base.MoreObjects;
 import com.google.protobuf.ByteString;
 import org.bitcoinj.base.Network;
 import org.bitcoinj.base.ScriptType;
+import org.bitcoinj.base.internal.Stopwatch;
 import org.bitcoinj.base.internal.TimeUtils;
 import org.bitcoinj.crypto.AesKey;
 import org.bitcoinj.base.internal.ByteUtils;
@@ -1272,12 +1273,12 @@ public class DeterministicKeyChain implements EncryptableKeyChain {
         log.info("{} keys needed for {} = {} issued + {} lookahead size + {} lookahead threshold - {} num children",
                 limit, parent.getPathAsString(), issued, lookaheadSize, lookaheadThreshold, numChildren);
 
-        Instant start = TimeUtils.currentTime();
+        Stopwatch watch = Stopwatch.start();
         List<DeterministicKey> result = HDKeyDerivation.generate(parent, numChildren)
                 .limit(limit)
                 .map(DeterministicKey::dropPrivateBytes)
                 .collect(StreamUtils.toUnmodifiableList());
-        log.info("Took {} ms", TimeUtils.elapsedTime(start).toMillis());
+        log.info("Took {}", watch);
         return result;
     }
 

core/src/main/java/org/bitcoinj/wallet/WalletFiles.java

@@ -17,6 +17,7 @@
 
 package org.bitcoinj.wallet;
 
+import org.bitcoinj.base.internal.Stopwatch;
 import org.bitcoinj.base.internal.TimeUtils;
 import org.bitcoinj.utils.ContextPropagatingThreadFactory;
 import org.slf4j.Logger;
@@ -137,7 +138,7 @@ public class WalletFiles {
     }
 
     private void saveNowInternal() throws IOException {
-        Instant start = TimeUtils.currentTime();
+        Stopwatch watch = Stopwatch.start();
         File directory = file.getAbsoluteFile().getParentFile();
         if (!directory.exists()) {
             throw new FileNotFoundException(directory.getPath() + " (wallet directory not found)");
@@ -149,7 +150,7 @@ public class WalletFiles {
         wallet.saveToFile(temp, file);
         if (listener != null)
             listener.onAfterAutoSave(file);
-        log.info("Save completed in {} ms", TimeUtils.elapsedTime(start).toMillis());
+        log.info("Save completed in {}", watch);
     }
 
     /** Queues up a save in the background. Useful for not very important wallet changes. */

core/src/test/java/org/bitcoinj/base/internal/StopwatchTest.java

@@ -0,0 +1,63 @@
+/*
+ * Copyright by the original author or authors.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *    http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package org.bitcoinj.base.internal;
+
+import org.junit.Before;
+import org.junit.Test;
+
+import java.time.Duration;
+import java.time.Instant;
+
+import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.assertNotEquals;
+import static org.junit.Assert.assertTrue;
+
+public class StopwatchTest {
+    private Stopwatch stopwatch;
+
+    @Before
+    public void setUp() {
+        stopwatch = Stopwatch.start();
+    }
+
+    @Test
+    public void toString_() {
+        stopwatch.toString();
+    }
+
+    @Test
+    public void stop() {
+        stopwatch.stop();
+    }
+
+    @Test
+    public void addSubstract() {
+        Instant i1 = Instant.now();
+        Instant i2 = i1.plus(stopwatch.stop());
+        Instant i3 = i2.minus(stopwatch);
+        assertEquals(i1, i3);
+        assertTrue(i2.compareTo(i1) >= 0);
+        assertTrue(i3.compareTo(i2) <= 0);
+    }
+
+    @Test
+    public void compareTo() {
+        Duration hour = Duration.ofHours(1);
+        assertTrue(stopwatch.elapsed().compareTo(hour) < 0);
+        assertTrue(hour.compareTo(stopwatch.elapsed()) > 0);
+    }
+}

core/src/test/java/org/bitcoinj/store/SPVBlockStoreTest.java

@@ -21,6 +21,7 @@ import org.bitcoinj.base.BitcoinNetwork;
 import org.bitcoinj.base.ScriptType;
 import org.bitcoinj.base.Address;
 import org.bitcoinj.base.internal.PlatformUtils;
+import org.bitcoinj.base.internal.Stopwatch;
 import org.bitcoinj.base.internal.TimeUtils;
 import org.bitcoinj.core.Block;
 import org.bitcoinj.core.Context;
@@ -146,7 +147,7 @@ public class SPVBlockStoreTest {
         final int ITERATIONS = 100000;
         final Duration THRESHOLD = Duration.ofSeconds(5);
         SPVBlockStore store = new SPVBlockStore(TESTNET, blockStoreFile);
-        Instant start = TimeUtils.currentTime();
+        Stopwatch watch = Stopwatch.start();
         for (int i = 0; i < ITERATIONS; i++) {
             // Using i as the nonce so that the block hashes are different.
             Block block = new Block(TESTNET, 0, Sha256Hash.ZERO_HASH, Sha256Hash.ZERO_HASH, 0, 0, i,
@@ -155,9 +156,9 @@ public class SPVBlockStoreTest {
             store.put(b);
             store.setChainHead(b);
         }
-        Duration elapsed = TimeUtils.elapsedTime(start);
+        watch.stop();
-        assertTrue("took " + elapsed.toMillis() + " ms for " + ITERATIONS + " iterations",
+        assertTrue("took " + watch + " for " + ITERATIONS + " iterations",
-                elapsed.compareTo(THRESHOLD) < 0);
+                watch.elapsed().compareTo(THRESHOLD) < 0);
         store.close();
     }
 

integration-test/src/test/java/org/bitcoinj/core/PeerGroupTest.java

@@ -22,6 +22,7 @@ import org.bitcoinj.base.Address;
 import org.bitcoinj.base.Coin;
 import org.bitcoinj.base.ScriptType;
 import org.bitcoinj.base.Sha256Hash;
+import org.bitcoinj.base.internal.Stopwatch;
 import org.bitcoinj.base.internal.TimeUtils;
 import org.bitcoinj.core.listeners.DownloadProgressTracker;
 import org.bitcoinj.core.listeners.PeerConnectedEventListener;
@@ -535,7 +536,7 @@ public class PeerGroupTest extends TestWithPeerGroup {
         peerGroup.addConnectedEventListener(Threading.SAME_THREAD, (peer, peerCount) -> peerConnectedFuture.complete(null));
         peerGroup.addDisconnectedEventListener(Threading.SAME_THREAD, (peer, peerCount) -> peerDisconnectedFuture.complete(null));
         // connect to peer but don't do handshake
-        Instant start = TimeUtils.currentTime(); // before connection so we don't get elapsed < timeout
+        Stopwatch watch = Stopwatch.start(); // before connection so we don't get elapsed < timeout
         connectPeerWithoutVersionExchange(0);
         // wait for disconnect (plus a bit more, in case test server is overloaded)
         try {
@@ -545,8 +546,8 @@ public class PeerGroupTest extends TestWithPeerGroup {
         }
         // check things after disconnect
         assertFalse(peerConnectedFuture.isDone()); // should never have connected
-        Duration elapsed = TimeUtils.elapsedTime(start);
+        watch.stop();
-        assertTrue(elapsed.toMillis() + " ms",elapsed.compareTo(timeout) >= 0); // should not disconnect before timeout
+        assertTrue(watch.toString(), watch.elapsed().compareTo(timeout) >= 0); // should not disconnect before timeout
         assertTrue(peerDisconnectedFuture.isDone()); // but should disconnect eventually
     }