Log time spent queueing and executing crypto and DB tasks.

bramble-core/src/main/java/org/briarproject/bramble/TimeLoggingExecutor.java

+package org.briarproject.bramble;
+
+import java.util.concurrent.BlockingQueue;
+import java.util.concurrent.RejectedExecutionHandler;
+import java.util.concurrent.ThreadPoolExecutor;
+import java.util.concurrent.TimeUnit;
+import java.util.logging.Level;
+import java.util.logging.Logger;
+
+import static java.util.logging.Level.FINE;
+
+public class TimeLoggingExecutor extends ThreadPoolExecutor {
+
+	private static final Level LOG_LEVEL = FINE;
+
+	private final Logger log;
+
+	public TimeLoggingExecutor(String tag, int corePoolSize, int maxPoolSize,
+			long keepAliveTime, TimeUnit unit,
+			BlockingQueue<Runnable> workQueue,
+			RejectedExecutionHandler handler) {
+		super(corePoolSize, maxPoolSize, keepAliveTime, unit, workQueue,
+				handler);
+		log = Logger.getLogger(tag);
+	}
+
+	@Override
+	public void execute(final Runnable r) {
+		final long submitted = System.currentTimeMillis();
+		super.execute(new Runnable() {
+			@Override
+			public void run() {
+				long started = System.currentTimeMillis();
+				if (log.isLoggable(LOG_LEVEL)) {
+					long duration = started - submitted;
+					log.log(LOG_LEVEL, "Queue time " + duration + " ms");
+				}
+				r.run();
+				long finished = System.currentTimeMillis();
+				if (log.isLoggable(LOG_LEVEL)) {
+					long duration = finished - started;
+					log.log(LOG_LEVEL, "Execution time " + duration + " ms");
+				}
+			}
+		});
+	}
+}

bramble-core/src/main/java/org/briarproject/bramble/crypto/CryptoModule.java

 package org.briarproject.bramble.crypto;
 
+import org.briarproject.bramble.TimeLoggingExecutor;
 import org.briarproject.bramble.api.crypto.CryptoComponent;
 import org.briarproject.bramble.api.crypto.CryptoExecutor;
 import org.briarproject.bramble.api.crypto.PasswordStrengthEstimator;
@@ -49,8 +50,8 @@ public class CryptoModule {
 		RejectedExecutionHandler policy =
 				new ThreadPoolExecutor.DiscardPolicy();
 		// Create a limited # of threads and keep them in the pool for 60 secs
-		cryptoExecutor = new ThreadPoolExecutor(0, MAX_EXECUTOR_THREADS,
-				60, SECONDS, queue, policy);
+		cryptoExecutor = new TimeLoggingExecutor("CryptoExecutor", 0,
+				MAX_EXECUTOR_THREADS, 60, SECONDS, queue, policy);
 	}
 
 	@Provides

bramble-core/src/main/java/org/briarproject/bramble/db/DatabaseComponentImpl.java

@@ -67,6 +67,7 @@ import javax.annotation.Nullable;
 import javax.annotation.concurrent.ThreadSafe;
 import javax.inject.Inject;
 
+import static java.util.logging.Level.FINE;
 import static java.util.logging.Level.WARNING;
 import static org.briarproject.bramble.api.sync.Group.Visibility.INVISIBLE;
 import static org.briarproject.bramble.api.sync.Group.Visibility.SHARED;
@@ -130,8 +131,14 @@ 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();
 		if (readOnly) lock.readLock().lock();
 		else lock.writeLock().lock();
+		if (LOG.isLoggable(FINE)) {
+			long duration = System.currentTimeMillis() - start;
+			if (readOnly) LOG.fine("Waited " + duration + " ms for read lock");
+			else LOG.fine("Waited " + duration + " ms for write lock");
+		}
 		try {
 			return new Transaction(db.startTransaction(), readOnly);
 		} catch (DbException e) {

bramble-core/src/main/java/org/briarproject/bramble/db/DatabaseExecutorModule.java

 package org.briarproject.bramble.db;
 
+import org.briarproject.bramble.TimeLoggingExecutor;
 import org.briarproject.bramble.api.db.DatabaseExecutor;
 import org.briarproject.bramble.api.lifecycle.LifecycleManager;
 
@@ -36,8 +37,8 @@ public class DatabaseExecutorModule {
 		RejectedExecutionHandler policy =
 				new ThreadPoolExecutor.DiscardPolicy();
 		// Use a single thread and keep it in the pool for 60 secs
-		databaseExecutor = new ThreadPoolExecutor(0, 1, 60, SECONDS, queue,
-				policy);
+		databaseExecutor = new TimeLoggingExecutor("DatabaseExecutor", 0, 1,
+				60, SECONDS, queue, policy);
 	}
 
 	@Provides