diff --git a/core/src/main/java/org/bitcoinj/base/internal/Stopwatch.java b/core/src/main/java/org/bitcoinj/base/internal/Stopwatch.java new file mode 100644 index 000000000..fdda3c11d --- /dev/null +++ b/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 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"; + } +} diff --git a/core/src/main/java/org/bitcoinj/base/internal/TimeUtils.java b/core/src/main/java/org/bitcoinj/base/internal/TimeUtils.java index 731e36b62..9d6edbe67 100644 --- a/core/src/main/java/org/bitcoinj/base/internal/TimeUtils.java +++ b/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. + *

+ * 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()); diff --git a/core/src/main/java/org/bitcoinj/core/PeerGroup.java b/core/src/main/java/org/bitcoinj/core/PeerGroup.java index 0a61a30ff..477a55e4a 100644 --- a/core/src/main/java/org/bitcoinj/core/PeerGroup.java +++ b/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 addressList = new LinkedList<>(); for (PeerDiscovery peerDiscovery : peerDiscoverers /* COW */) { List 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", - TimeUtils.elapsedTime(start).toMillis(), addressList.size(), peerDiscoverers.size()); + log.info("Peer discovery took {} and returned {} items from {} discoverers", + watch, addressList.size(), peerDiscoverers.size()); return addressList.size(); } @@ -1181,7 +1182,7 @@ public class PeerGroup implements TransactionBroadcaster { CompletableFuture 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); } diff --git a/core/src/main/java/org/bitcoinj/crypto/KeyCrypterScrypt.java b/core/src/main/java/org/bitcoinj/crypto/KeyCrypterScrypt.java index e5899bd16..250e75972 100644 --- a/core/src/main/java/org/bitcoinj/crypto/KeyCrypterScrypt.java +++ b/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); diff --git a/core/src/main/java/org/bitcoinj/crypto/MnemonicCode.java b/core/src/main/java/org/bitcoinj/crypto/MnemonicCode.java index 7425ae0b3..e1a34855c 100644 --- a/core/src/main/java/org/bitcoinj/crypto/MnemonicCode.java +++ b/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; } diff --git a/core/src/main/java/org/bitcoinj/params/BitcoinNetworkParams.java b/core/src/main/java/org/bitcoinj/params/BitcoinNetworkParams.java index 722ec51ce..3f760afc1 100644 --- a/core/src/main/java/org/bitcoinj/params/BitcoinNetworkParams.java +++ b/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); - if (elapsed.toMillis() > 50) - log.info("Difficulty transition traversal took {} ms", elapsed.toMillis()); + watch.stop(); + if (watch.elapsed().toMillis() > 50) + log.info("Difficulty transition traversal took {}", watch); Block blockIntervalAgo = cursor.getHeader(); int timespan = (int) (prev.getTimeSeconds() - blockIntervalAgo.getTimeSeconds()); diff --git a/core/src/main/java/org/bitcoinj/wallet/DeterministicKeyChain.java b/core/src/main/java/org/bitcoinj/wallet/DeterministicKeyChain.java index abe323617..483647d4a 100644 --- a/core/src/main/java/org/bitcoinj/wallet/DeterministicKeyChain.java +++ b/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 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; } diff --git a/core/src/main/java/org/bitcoinj/wallet/WalletFiles.java b/core/src/main/java/org/bitcoinj/wallet/WalletFiles.java index e0d6d191c..085c56891 100644 --- a/core/src/main/java/org/bitcoinj/wallet/WalletFiles.java +++ b/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. */ diff --git a/core/src/test/java/org/bitcoinj/base/internal/StopwatchTest.java b/core/src/test/java/org/bitcoinj/base/internal/StopwatchTest.java new file mode 100644 index 000000000..12189b677 --- /dev/null +++ b/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); + } +} diff --git a/core/src/test/java/org/bitcoinj/store/SPVBlockStoreTest.java b/core/src/test/java/org/bitcoinj/store/SPVBlockStoreTest.java index d00cc268d..1e65c386a 100644 --- a/core/src/test/java/org/bitcoinj/store/SPVBlockStoreTest.java +++ b/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); - assertTrue("took " + elapsed.toMillis() + " ms for " + ITERATIONS + " iterations", - elapsed.compareTo(THRESHOLD) < 0); + watch.stop(); + assertTrue("took " + watch + " for " + ITERATIONS + " iterations", + watch.elapsed().compareTo(THRESHOLD) < 0); store.close(); } diff --git a/integration-test/src/test/java/org/bitcoinj/core/PeerGroupTest.java b/integration-test/src/test/java/org/bitcoinj/core/PeerGroupTest.java index 99a7042b3..e44e681a1 100644 --- a/integration-test/src/test/java/org/bitcoinj/core/PeerGroupTest.java +++ b/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); - assertTrue(elapsed.toMillis() + " ms",elapsed.compareTo(timeout) >= 0); // should not disconnect before timeout + watch.stop(); + assertTrue(watch.toString(), watch.elapsed().compareTo(timeout) >= 0); // should not disconnect before timeout assertTrue(peerDisconnectedFuture.isDone()); // but should disconnect eventually }