Log the timing of startup tasks so we can find bottlenecks.

briar-android/src/org/briarproject/android/SetupActivity.java

@@ -9,12 +9,14 @@ import static android.view.Gravity.CENTER_HORIZONTAL;
 import static android.view.View.GONE;
 import static android.view.View.VISIBLE;
 import static android.widget.LinearLayout.VERTICAL;
+import static java.util.logging.Level.INFO;
 import static org.briarproject.android.util.CommonLayoutParams.MATCH_MATCH;
 import static org.briarproject.android.util.CommonLayoutParams.WRAP_WRAP;
 import static org.briarproject.api.crypto.PasswordStrengthEstimator.WEAK;
 
 import java.util.Arrays;
 import java.util.concurrent.Executor;
+import java.util.logging.Logger;
 
 import javax.inject.Inject;
 
@@ -48,6 +50,9 @@ import android.widget.TextView;
 
 public class SetupActivity extends RoboActivity implements OnClickListener {
 
+	private static final Logger LOG =
+			Logger.getLogger(SetupActivity.class.getName());
+
 	@Inject @CryptoExecutor private Executor cryptoExecutor;
 	@Inject private PasswordStrengthEstimator strengthEstimator;
 	private EditText nicknameEntry = null;
@@ -66,6 +71,7 @@ public class SetupActivity extends RoboActivity implements OnClickListener {
 	@Override
 	public void onCreate(Bundle state) {
 		super.onCreate(state);
+
 		LinearLayout layout = new LinearLayout(this);
 		layout.setLayoutParams(MATCH_MATCH);
 		layout.setOrientation(VERTICAL);
@@ -217,16 +223,13 @@ public class SetupActivity extends RoboActivity implements OnClickListener {
 		cryptoExecutor.execute(new Runnable() {
 			public void run() {
 				byte[] key = crypto.generateSecretKey().getEncoded();
-				byte[] encrypted = crypto.encryptWithPassword(key, password);
-				storeEncryptedDatabaseKey(encrypted);
 				databaseConfig.setEncryptionKey(key);
-				KeyPair keyPair = crypto.generateSignatureKeyPair();
+				byte[] encrypted = encryptDatabaseKey(key, password);
-				final byte[] publicKey = keyPair.getPublic().getEncoded();
+				for(int i = 0; i < password.length; i++) password[i] = 0;
-				final byte[] privateKey = keyPair.getPrivate().getEncoded();
+				storeEncryptedDatabaseKey(encrypted);
-				LocalAuthor a = authorFactory.createLocalAuthor(nickname,
+				LocalAuthor localAuthor = createLocalAuthor(nickname);
-						publicKey, privateKey);
+				showHomeScreen(referenceManager.putReference(localAuthor,
-				showHomeScreen(referenceManager.putReference(a,
+						LocalAuthor.class));
-						LocalAuthor.class));				
 			}
 		});
 	}
@@ -235,11 +238,37 @@ public class SetupActivity extends RoboActivity implements OnClickListener {
 		e.delete(0, e.length());
 	}
 
-	private void storeEncryptedDatabaseKey(byte[] encrypted) {
+	private void storeEncryptedDatabaseKey(final byte[] encrypted) {
+		long start = System.currentTimeMillis();
 		SharedPreferences prefs = getSharedPreferences("db", MODE_PRIVATE);
 		Editor editor = prefs.edit();
 		editor.putString("key", StringUtils.toHexString(encrypted));
 		editor.commit();
+		long duration = System.currentTimeMillis() - start;
+		if(LOG.isLoggable(INFO))
+			LOG.info("Key storage took " + duration + " ms");
+	}
+
+	private byte[] encryptDatabaseKey(byte[] key, char[] password) {
+		long start = System.currentTimeMillis();
+		byte[] encrypted = crypto.encryptWithPassword(key, password);
+		long duration = System.currentTimeMillis() - start;
+		if(LOG.isLoggable(INFO))
+			LOG.info("Key derivation took " + duration + " ms");
+		return encrypted;
+	}
+
+	private LocalAuthor createLocalAuthor(String nickname) {
+		long start = System.currentTimeMillis();
+		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() - start;
+		if(LOG.isLoggable(INFO))
+			LOG.info("Identity creation took " + duration + " ms");
+		return localAuthor;
 	}
 
 	private void showHomeScreen(final long handle) {

briar-core/src/org/briarproject/lifecycle/LifecycleManagerImpl.java

@@ -16,12 +16,14 @@ import org.briarproject.api.db.DatabaseComponent;
 import org.briarproject.api.db.DbException;
 import org.briarproject.api.lifecycle.LifecycleManager;
 import org.briarproject.api.lifecycle.Service;
+import org.briarproject.api.system.Clock;
 
 class LifecycleManagerImpl implements LifecycleManager {
 
 	private static final Logger LOG =
 			Logger.getLogger(LifecycleManagerImpl.class.getName());
 
+	private final Clock clock;
 	private final DatabaseComponent db;
 	private final Collection<Service> services;
 	private final Collection<ExecutorService> executors;
@@ -30,7 +32,8 @@ class LifecycleManagerImpl implements LifecycleManager {
 	private final CountDownLatch shutdownLatch = new CountDownLatch(1);
 
 	@Inject
-	LifecycleManagerImpl(DatabaseComponent db) {
+	LifecycleManagerImpl(Clock clock, DatabaseComponent db) {
+		this.clock = clock;
 		this.db = db;
 		services = new CopyOnWriteArrayList<Service>();
 		executors = new CopyOnWriteArrayList<ExecutorService>();
@@ -51,20 +54,30 @@ class LifecycleManagerImpl implements LifecycleManager {
 	public boolean startServices() {
 		try {
 			if(LOG.isLoggable(INFO)) LOG.info("Starting");
+			long start = clock.currentTimeMillis();
 			boolean reopened = db.open();
+			long duration = clock.currentTimeMillis() - start;
 			if(LOG.isLoggable(INFO)) {
-				if(reopened) LOG.info("Database reopened");
+				if(reopened)
-				else LOG.info("Database created");
+					LOG.info("Reopening database took " + duration + " ms");
+				else LOG.info("Creating database took " + duration + " ms");
 			}
 			dbLatch.countDown();
 			for(Service s : services) {
+				start = clock.currentTimeMillis();
 				boolean started = s.start();
+				duration = clock.currentTimeMillis() - start;
+				if(!started) {
+					if(LOG.isLoggable(WARNING)) {
+						String name = s.getClass().getName();
+						LOG.warning(name + " did not start");
+					}
+					return false;
+				}
 				if(LOG.isLoggable(INFO)) {
 					String name = s.getClass().getName();
-					if(started) LOG.info("Service started: " + name);
+					LOG.info("Starting " + name + " took " + duration + " ms");
-					else LOG.info("Service failed to start: " + name);
 				}
-				if(!started) return false;
 			}
 			startupLatch.countDown();
 			return true;

briar-core/src/org/briarproject/plugins/PluginManagerImpl.java

@@ -37,6 +37,7 @@ import org.briarproject.api.plugins.simplex.SimplexPluginConfig;
 import org.briarproject.api.plugins.simplex.SimplexPluginFactory;
 import org.briarproject.api.plugins.simplex.SimplexTransportReader;
 import org.briarproject.api.plugins.simplex.SimplexTransportWriter;
+import org.briarproject.api.system.Clock;
 import org.briarproject.api.transport.ConnectionDispatcher;
 import org.briarproject.api.ui.UiCallback;
 
@@ -50,6 +51,7 @@ class PluginManagerImpl implements PluginManager {
 	private final Executor pluginExecutor;
 	private final SimplexPluginConfig simplexPluginConfig;
 	private final DuplexPluginConfig duplexPluginConfig;
+	private final Clock clock;
 	private final DatabaseComponent db;
 	private final Poller poller;
 	private final ConnectionDispatcher dispatcher;
@@ -60,12 +62,13 @@ class PluginManagerImpl implements PluginManager {
 	@Inject
 	PluginManagerImpl(@PluginExecutor Executor pluginExecutor,
 			SimplexPluginConfig simplexPluginConfig, 
-			DuplexPluginConfig duplexPluginConfig, DatabaseComponent db,
+			DuplexPluginConfig duplexPluginConfig, Clock clock,
-			Poller poller, ConnectionDispatcher dispatcher,
+			DatabaseComponent db, Poller poller,
-			UiCallback uiCallback) {
+			ConnectionDispatcher dispatcher, UiCallback uiCallback) {
 		this.pluginExecutor = pluginExecutor;
 		this.simplexPluginConfig = simplexPluginConfig;
 		this.duplexPluginConfig = duplexPluginConfig;
+		this.clock = clock;
 		this.db = db;
 		this.poller = poller;
 		this.dispatcher = dispatcher;
@@ -167,19 +170,31 @@ class PluginManagerImpl implements PluginManager {
 					return;
 				}
 				try {
+					long start = clock.currentTimeMillis();
 					db.addTransport(id, plugin.getMaxLatency());
+					long duration = clock.currentTimeMillis() - start;
+					if(LOG.isLoggable(INFO))
+						LOG.info("Adding transport took " + duration + " ms");
 				} catch(DbException e) {
 					if(LOG.isLoggable(WARNING))
 						LOG.log(WARNING, e.toString(), e);
 					return;
 				}
 				try {
-					if(plugin.start()) {
+					long start = clock.currentTimeMillis();
+					boolean started = plugin.start();
+					long duration = clock.currentTimeMillis() - start;
+					if(started) {
 						simplexPlugins.add(plugin);
-					} else {
 						if(LOG.isLoggable(INFO)) {
 							String name = plugin.getClass().getSimpleName();
-							LOG.info(name + " did not start");
+							LOG.info("Starting " + name + " took " +
+									duration + " ms");
+						}
+					} else {
+						if(LOG.isLoggable(WARNING)) {
+							String name = plugin.getClass().getSimpleName();
+							LOG.warning(name + " did not start");
 						}
 					}
 				} catch(IOException e) {
@@ -216,19 +231,31 @@ class PluginManagerImpl implements PluginManager {
 					return;
 				}
 				try {
+					long start = clock.currentTimeMillis();
 					db.addTransport(id, plugin.getMaxLatency());
+					long duration = clock.currentTimeMillis() - start;
+					if(LOG.isLoggable(INFO))
+						LOG.info("Adding transport took " + duration + " ms");
 				} catch(DbException e) {
 					if(LOG.isLoggable(WARNING))
 						LOG.log(WARNING, e.toString(), e);
 					return;
 				}
 				try {
-					if(plugin.start()) {
+					long start = clock.currentTimeMillis();
+					boolean started = plugin.start();
+					long duration = clock.currentTimeMillis() - start;
+					if(started) {
 						duplexPlugins.add(plugin);
-					} else {
 						if(LOG.isLoggable(INFO)) {
 							String name = plugin.getClass().getSimpleName();
-							LOG.info(name + " did not start");
+							LOG.info("Starting " + name + " took " +
+									duration + " ms");
+						}
+					} else {
+						if(LOG.isLoggable(WARNING)) {
+							String name = plugin.getClass().getSimpleName();
+							LOG.warning(name + " did not start");
 						}
 					}
 				} catch(IOException e) {
@@ -253,7 +280,13 @@ class PluginManagerImpl implements PluginManager {
 
 		public void run() {
 			try {
+				long start = clock.currentTimeMillis();
 				plugin.stop();
+				long duration = clock.currentTimeMillis() - start;
+				if(LOG.isLoggable(INFO)) {
+					String name = plugin.getClass().getSimpleName();
+					LOG.info("Stopping " + name + " took " + duration + " ms");
+				}
 			} catch(IOException e) {
 				if(LOG.isLoggable(WARNING)) LOG.log(WARNING, e.toString(), e);
 			} finally {

briar-tests/src/org/briarproject/plugins/PluginManagerImplTest.java

@@ -16,9 +16,10 @@ import org.briarproject.api.plugins.simplex.SimplexPlugin;
 import org.briarproject.api.plugins.simplex.SimplexPluginCallback;
 import org.briarproject.api.plugins.simplex.SimplexPluginConfig;
 import org.briarproject.api.plugins.simplex.SimplexPluginFactory;
+import org.briarproject.api.system.Clock;
+import org.briarproject.api.system.SystemClock;
 import org.briarproject.api.transport.ConnectionDispatcher;
 import org.briarproject.api.ui.UiCallback;
-
 import org.jmock.Expectations;
 import org.jmock.Mockery;
 import org.junit.Test;
@@ -27,6 +28,7 @@ public class PluginManagerImplTest extends BriarTestCase {
 
 	@Test
 	public void testStartAndStop() throws Exception {
+		Clock clock = new SystemClock();
 		Mockery context = new Mockery();
 		final Executor pluginExecutor = Executors.newCachedThreadPool();
 		final SimplexPluginConfig simplexPluginConfig =
@@ -118,7 +120,7 @@ public class PluginManagerImplTest extends BriarTestCase {
 			oneOf(duplexPlugin).stop();
 		}});
 		PluginManagerImpl p = new PluginManagerImpl(pluginExecutor,
-				simplexPluginConfig, duplexPluginConfig, db, poller,
+				simplexPluginConfig, duplexPluginConfig, clock, db, poller,
 				dispatcher, uiCallback);
 		// Two plugins should be started and stopped
 		assertTrue(p.start());