Use System.nanoTime() for timing measurements.

This commit is contained in:
akwizgran
2018-06-15 12:04:12 +01:00
parent ccee1febbc
commit 08931e64cb
23 changed files with 136 additions and 102 deletions

View File

@@ -10,6 +10,7 @@ import java.util.logging.Logger;
import javax.annotation.concurrent.GuardedBy;
import static java.util.logging.Level.FINE;
import static org.briarproject.bramble.util.TimeUtils.now;
/**
* An {@link Executor} that delegates its tasks to another {@link Executor}
@@ -46,10 +47,10 @@ public class PoliteExecutor implements Executor {
@Override
public void execute(Runnable r) {
long submitted = System.currentTimeMillis();
long submitted = now();
Runnable wrapped = () -> {
if (log.isLoggable(FINE)) {
long queued = System.currentTimeMillis() - submitted;
long queued = now() - submitted;
log.fine("Queue time " + queued + " ms");
}
try {

View File

@@ -9,6 +9,7 @@ import java.util.concurrent.TimeUnit;
import java.util.logging.Logger;
import static java.util.logging.Level.FINE;
import static org.briarproject.bramble.util.TimeUtils.now;
@NotNullByDefault
public class TimeLoggingExecutor extends ThreadPoolExecutor {
@@ -27,13 +28,13 @@ public class TimeLoggingExecutor extends ThreadPoolExecutor {
@Override
public void execute(Runnable r) {
if (log.isLoggable(FINE)) {
long submitted = System.currentTimeMillis();
long submitted = now();
super.execute(() -> {
long started = System.currentTimeMillis();
long started = now();
long queued = started - submitted;
log.fine("Queue time " + queued + " ms");
r.run();
long executing = System.currentTimeMillis() - started;
long executing = now() - started;
log.fine("Execution time " + executing + " ms");
});
} else {

View File

@@ -33,6 +33,7 @@ import javax.inject.Inject;
import static java.util.logging.Level.FINE;
import static java.util.logging.Level.INFO;
import static org.briarproject.bramble.util.ByteUtils.INT_32_BYTES;
import static org.briarproject.bramble.util.TimeUtils.now;
@NotNullByDefault
class CryptoComponentImpl implements CryptoComponent {
@@ -128,14 +129,14 @@ class CryptoComponentImpl implements CryptoComponent {
throw new IllegalArgumentException();
if (!(pub instanceof Curve25519PublicKey))
throw new IllegalArgumentException();
long now = System.currentTimeMillis();
long start = now();
byte[] secret = curve25519.calculateAgreement(pub.getEncoded(),
priv.getEncoded());
// If the shared secret is all zeroes, the public key is invalid
byte allZero = 0;
for (byte b : secret) allZero |= b;
if (allZero == 0) throw new GeneralSecurityException();
long duration = System.currentTimeMillis() - now;
long duration = now() - start;
if (LOG.isLoggable(FINE))
LOG.fine("Deriving shared secret took " + duration + " ms");
return secret;

View File

@@ -11,6 +11,7 @@ import javax.inject.Inject;
import static java.util.logging.Level.FINE;
import static java.util.logging.Level.INFO;
import static org.briarproject.bramble.util.TimeUtils.now;
class ScryptKdf implements PasswordBasedKdf {
@@ -51,11 +52,11 @@ class ScryptKdf implements PasswordBasedKdf {
@Override
public SecretKey deriveKey(String password, byte[] salt, int cost) {
long start = System.currentTimeMillis();
long start = now();
byte[] passwordBytes = StringUtils.toUtf8(password);
SecretKey k = new SecretKey(SCrypt.generate(passwordBytes, salt, cost,
BLOCK_SIZE, PARALLELIZATION, SecretKey.LENGTH));
long duration = System.currentTimeMillis() - start;
long duration = now() - start;
if (LOG.isLoggable(FINE))
LOG.fine("Deriving key from password took " + duration + " ms");
return k;

View File

@@ -17,6 +17,7 @@ import java.util.logging.Logger;
import javax.annotation.concurrent.Immutable;
import static java.util.logging.Level.FINE;
import static org.briarproject.bramble.util.TimeUtils.now;
/**
* A key parser that uses the encoding defined in "SEC 1: Elliptic Curve
@@ -48,7 +49,7 @@ class Sec1KeyParser implements KeyParser {
throws GeneralSecurityException {
// The validation procedure comes from SEC 1, section 3.2.2.1. Note
// that SEC 1 parameter names are used below, not RFC 5639 names
long now = System.currentTimeMillis();
long start = now();
if (encodedKey.length != publicKeyBytes)
throw new GeneralSecurityException();
// The first byte must be 0x04
@@ -80,7 +81,7 @@ class Sec1KeyParser implements KeyParser {
// Construct a public key from the point (x, y) and the params
ECPublicKeyParameters k = new ECPublicKeyParameters(pub, params);
PublicKey p = new Sec1PublicKey(k);
long duration = System.currentTimeMillis() - now;
long duration = now() - start;
if (LOG.isLoggable(FINE))
LOG.fine("Parsing public key took " + duration + " ms");
return p;
@@ -89,7 +90,7 @@ class Sec1KeyParser implements KeyParser {
@Override
public PrivateKey parsePrivateKey(byte[] encodedKey)
throws GeneralSecurityException {
long now = System.currentTimeMillis();
long start = now();
if (encodedKey.length != privateKeyBytes)
throw new GeneralSecurityException();
BigInteger d = new BigInteger(1, encodedKey); // Positive signum
@@ -99,7 +100,7 @@ class Sec1KeyParser implements KeyParser {
// Construct a private key from the private value and the params
ECPrivateKeyParameters k = new ECPrivateKeyParameters(d, params);
PrivateKey p = new Sec1PrivateKey(k, keyBits);
long duration = System.currentTimeMillis() - now;
long duration = now() - start;
if (LOG.isLoggable(FINE))
LOG.fine("Parsing private key took " + duration + " ms");
return p;

View File

@@ -75,6 +75,7 @@ import static org.briarproject.bramble.api.sync.Group.Visibility.SHARED;
import static org.briarproject.bramble.api.sync.ValidationManager.State.DELIVERED;
import static org.briarproject.bramble.api.sync.ValidationManager.State.UNKNOWN;
import static org.briarproject.bramble.db.DatabaseConstants.MAX_OFFERED_MESSAGES;
import static org.briarproject.bramble.util.TimeUtils.now;
@ThreadSafe
@NotNullByDefault
@@ -125,11 +126,11 @@ class DatabaseComponentImpl<T> implements DatabaseComponent {
// Don't allow reentrant locking
if (lock.getReadHoldCount() > 0) throw new IllegalStateException();
if (lock.getWriteHoldCount() > 0) throw new IllegalStateException();
long start = System.currentTimeMillis();
long start = now();
if (readOnly) lock.readLock().lock();
else lock.writeLock().lock();
if (LOG.isLoggable(FINE)) {
long duration = System.currentTimeMillis() - start;
long duration = now() - start;
if (readOnly) LOG.fine("Waited " + duration + " ms for read lock");
else LOG.fine("Waited " + duration + " ms for write lock");
}

View File

@@ -44,6 +44,7 @@ import static org.briarproject.bramble.api.lifecycle.LifecycleManager.StartResul
import static org.briarproject.bramble.api.lifecycle.LifecycleManager.StartResult.DB_ERROR;
import static org.briarproject.bramble.api.lifecycle.LifecycleManager.StartResult.SERVICE_ERROR;
import static org.briarproject.bramble.api.lifecycle.LifecycleManager.StartResult.SUCCESS;
import static org.briarproject.bramble.util.TimeUtils.now;
@ThreadSafe
@NotNullByDefault
@@ -102,22 +103,22 @@ class LifecycleManagerImpl implements LifecycleManager, MigrationListener {
}
private LocalAuthor createLocalAuthor(String nickname) {
long now = System.currentTimeMillis();
long start = now();
KeyPair keyPair = crypto.generateSignatureKeyPair();
byte[] publicKey = keyPair.getPublic().getEncoded();
byte[] privateKey = keyPair.getPrivate().getEncoded();
LocalAuthor localAuthor = authorFactory
.createLocalAuthor(nickname, publicKey, privateKey);
long duration = System.currentTimeMillis() - now;
long duration = now() - start;
if (LOG.isLoggable(FINE))
LOG.fine("Creating local author took " + duration + " ms");
return localAuthor;
}
private void registerLocalAuthor(LocalAuthor author) throws DbException {
long now = System.currentTimeMillis();
long start = now();
identityManager.registerLocalAuthor(author);
long duration = System.currentTimeMillis() - now;
long duration = now() - start;
if (LOG.isLoggable(FINE))
LOG.fine("Registering local author took " + duration + " ms");
}
@@ -130,10 +131,10 @@ class LifecycleManagerImpl implements LifecycleManager, MigrationListener {
}
try {
LOG.info("Starting services");
long start = System.currentTimeMillis();
long start = now();
boolean reopened = db.open(this);
long duration = System.currentTimeMillis() - start;
long duration = now() - start;
if (LOG.isLoggable(FINE)) {
if (reopened)
LOG.fine("Reopening database took " + duration + " ms");
@@ -151,9 +152,9 @@ class LifecycleManagerImpl implements LifecycleManager, MigrationListener {
Transaction txn = db.startTransaction(false);
try {
for (Client c : clients) {
start = System.currentTimeMillis();
start = now();
c.createLocalState(txn);
duration = System.currentTimeMillis() - start;
duration = now() - start;
if (LOG.isLoggable(FINE)) {
LOG.fine("Starting client "
+ c.getClass().getSimpleName()
@@ -165,9 +166,9 @@ class LifecycleManagerImpl implements LifecycleManager, MigrationListener {
db.endTransaction(txn);
}
for (Service s : services) {
start = System.currentTimeMillis();
start = now();
s.startService();
duration = System.currentTimeMillis() - start;
duration = now() - start;
if (LOG.isLoggable(FINE)) {
LOG.fine("Starting service " + s.getClass().getSimpleName()
+ " took " + duration + " ms");
@@ -214,9 +215,9 @@ class LifecycleManagerImpl implements LifecycleManager, MigrationListener {
state = STOPPING;
eventBus.broadcast(new LifecycleEvent(STOPPING));
for (Service s : services) {
long start = System.currentTimeMillis();
long start = now();
s.stopService();
long duration = System.currentTimeMillis() - start;
long duration = now() - start;
if (LOG.isLoggable(FINE)) {
LOG.fine("Stopping service " + s.getClass().getSimpleName()
+ " took " + duration + " ms");
@@ -229,9 +230,9 @@ class LifecycleManagerImpl implements LifecycleManager, MigrationListener {
}
e.shutdownNow();
}
long start = System.currentTimeMillis();
long start = now();
db.close();
long duration = System.currentTimeMillis() - start;
long duration = now() - start;
if (LOG.isLoggable(FINE))
LOG.fine("Closing database took " + duration + " ms");
shutdownLatch.countDown();

View File

@@ -52,6 +52,7 @@ import javax.inject.Inject;
import static java.util.logging.Level.FINE;
import static java.util.logging.Level.INFO;
import static java.util.logging.Level.WARNING;
import static org.briarproject.bramble.util.TimeUtils.now;
@ThreadSafe
@NotNullByDefault
@@ -206,9 +207,9 @@ class PluginManagerImpl implements PluginManager, Service {
@Override
public void run() {
try {
long start = System.currentTimeMillis();
long start = now();
plugin.start();
long duration = System.currentTimeMillis() - start;
long duration = now() - start;
if (LOG.isLoggable(FINE)) {
LOG.fine("Starting plugin " + plugin.getId() + " took " +
duration + " ms");
@@ -244,9 +245,9 @@ class PluginManagerImpl implements PluginManager, Service {
// Wait for the plugin to finish starting
startLatch.await();
// Stop the plugin
long start = System.currentTimeMillis();
long start = now();
plugin.stop();
long duration = System.currentTimeMillis() - start;
long duration = now() - start;
if (LOG.isLoggable(FINE)) {
LOG.fine("Stopping plugin " + plugin.getId()
+ " took " + duration + " ms");