From 4123f4a5ce9ad8441991b218c09152ce43bf2317 Mon Sep 17 00:00:00 2001
From: akwizgran <akwizgran@users.sourceforge.net>
Date: Thu, 12 Jan 2017 12:16:13 +0000
Subject: [PATCH] Log time spent queueing and executing crypto and DB tasks.
---
.../bramble/TimeLoggingExecutor.java | 47 +++++++++++++++++++
.../bramble/crypto/CryptoModule.java | 5 +-
.../bramble/db/DatabaseComponentImpl.java | 7 +++
.../bramble/db/DatabaseExecutorModule.java | 5 +-
4 files changed, 60 insertions(+), 4 deletions(-)
create mode 100644 bramble-core/src/main/java/org/briarproject/bramble/TimeLoggingExecutor.java
diff --git a/bramble-core/src/main/java/org/briarproject/bramble/TimeLoggingExecutor.java b/bramble-core/src/main/java/org/briarproject/bramble/TimeLoggingExecutor.java
new file mode 100644
index 0000000000..77823e5d09
--- /dev/null
+++ b/bramble-core/src/main/java/org/briarproject/bramble/TimeLoggingExecutor.java
@@ -0,0 +1,47 @@
+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");
+ }
+ }
+ });
+ }
+}
diff --git a/bramble-core/src/main/java/org/briarproject/bramble/crypto/CryptoModule.java b/bramble-core/src/main/java/org/briarproject/bramble/crypto/CryptoModule.java
index 6b3ea5295b..1ac3cc29cf 100644
--- a/bramble-core/src/main/java/org/briarproject/bramble/crypto/CryptoModule.java
+++ b/bramble-core/src/main/java/org/briarproject/bramble/crypto/CryptoModule.java
@@ -1,5 +1,6 @@
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
diff --git a/bramble-core/src/main/java/org/briarproject/bramble/db/DatabaseComponentImpl.java b/bramble-core/src/main/java/org/briarproject/bramble/db/DatabaseComponentImpl.java
index 8d9be17094..dd8dea976d 100644
--- a/bramble-core/src/main/java/org/briarproject/bramble/db/DatabaseComponentImpl.java
+++ b/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) {
diff --git a/bramble-core/src/main/java/org/briarproject/bramble/db/DatabaseExecutorModule.java b/bramble-core/src/main/java/org/briarproject/bramble/db/DatabaseExecutorModule.java
index 7865faf364..4c11098ffb 100644
--- a/bramble-core/src/main/java/org/briarproject/bramble/db/DatabaseExecutorModule.java
+++ b/bramble-core/src/main/java/org/briarproject/bramble/db/DatabaseExecutorModule.java
@@ -1,5 +1,6 @@
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
--
GitLab