bench: simple working benchmark

OpenKeychain/src/main/java/org/sufficientlysecure/keychain/operations/BenchmarkOperation.java

@@ -27,6 +27,7 @@ import android.support.annotation.NonNull;
 
 import org.sufficientlysecure.keychain.operations.results.BenchmarkResult;
 import org.sufficientlysecure.keychain.operations.results.DecryptVerifyResult;
+import org.sufficientlysecure.keychain.operations.results.OperationResult.LogType;
 import org.sufficientlysecure.keychain.operations.results.OperationResult.OperationLog;
 import org.sufficientlysecure.keychain.operations.results.SignEncryptResult;
 import org.sufficientlysecure.keychain.pgp.PgpDecryptVerifyInputParcel;
@@ -54,9 +55,10 @@ public class BenchmarkOperation extends BaseOperation<BenchmarkInputParcel> {
     public BenchmarkResult execute(BenchmarkInputParcel consolidateInputParcel,
                                      CryptoInputParcel cryptoInputParcel) {
         OperationLog log = new OperationLog();
+        log.add(LogType.MSG_BENCH, 0);
 
         // random data
-        byte[] buf = new byte[1024];
+        byte[] buf = new byte[1024*1024*5];
         new Random().nextBytes(buf);
 
         Passphrase passphrase = new Passphrase("a");
@@ -66,24 +68,30 @@ public class BenchmarkOperation extends BaseOperation<BenchmarkInputParcel> {
         {
             SignEncryptOperation op =
                     new SignEncryptOperation(mContext, mProviderHelper,
-                            new ProgressScaler(mProgressable, 0, 10, 100), mCancelled);
+                            new ProgressScaler(mProgressable, 0, 50, 100), mCancelled);
             SignEncryptParcel input = new SignEncryptParcel();
             input.setSymmetricPassphrase(passphrase);
             input.setBytes(buf);
             encryptResult = op.execute(input, new CryptoInputParcel());
         }
+        log.add(encryptResult, 1);
+        log.add(LogType.MSG_BENCH_ENC_TIME, 1,
+                String.format("%.2f", encryptResult.getResults().get(0).mOperationTime / 1000.0));
 
         // decrypt
         DecryptVerifyResult decryptResult;
         {
             PgpDecryptVerifyOperation op =
                     new PgpDecryptVerifyOperation(mContext, mProviderHelper,
-                            new ProgressScaler(mProgressable, 0, 10, 100));
+                            new ProgressScaler(mProgressable, 50, 100, 100));
             PgpDecryptVerifyInputParcel input = new PgpDecryptVerifyInputParcel(encryptResult.getResultBytes());
             input.setAllowSymmetricDecryption(true);
             decryptResult = op.execute(input, new CryptoInputParcel(passphrase));
         }
+        log.add(decryptResult, 1);
+        log.add(LogType.MSG_BENCH_DEC_TIME, 1, String.format("%.2f", decryptResult.mOperationTime / 1000.0));
 
+        log.add(LogType.MSG_BENCH_SUCCESS, 0);
         return new BenchmarkResult(BenchmarkResult.RESULT_OK, log);
     }
 

OpenKeychain/src/main/java/org/sufficientlysecure/keychain/operations/results/DecryptVerifyResult.java

@@ -39,7 +39,7 @@ public class DecryptVerifyResult extends InputPendingResult {
 
     byte[] mOutputBytes;
 
-    public long mTotalTime;
+    public long mOperationTime;
 
     public DecryptVerifyResult(int result, OperationLog log) {
         super(result, log);

OpenKeychain/src/main/java/org/sufficientlysecure/keychain/operations/results/OperationResult.java

@@ -874,6 +874,12 @@ public abstract class OperationResult implements Parcelable {
         MSG_LV_FETCH_ERROR_IO (LogLevel.ERROR, R.string.msg_lv_fetch_error_io),
         MSG_LV_FETCH_ERROR_FORMAT(LogLevel.ERROR, R.string.msg_lv_fetch_error_format),
         MSG_LV_FETCH_ERROR_NOTHING (LogLevel.ERROR, R.string.msg_lv_fetch_error_nothing),
+
+        MSG_BENCH (LogLevel.START, R.string.msg_bench),
+        MSG_BENCH_ENC_TIME (LogLevel.INFO, R.string.msg_bench_enc_time),
+        MSG_BENCH_DEC_TIME (LogLevel.INFO, R.string.msg_bench_dec_time),
+        MSG_BENCH_SUCCESS (LogLevel.OK, R.string.msg_bench_success),
+
         ;
 
         public final int mMsgId;

OpenKeychain/src/main/java/org/sufficientlysecure/keychain/operations/results/PgpSignEncryptResult.java

@@ -26,6 +26,7 @@ import org.sufficientlysecure.keychain.service.input.RequiredInputParcel;
 public class PgpSignEncryptResult extends InputPendingResult {
 
     byte[] mDetachedSignature;
+    public long mOperationTime;
 
     public void setDetachedSignature(byte[] detachedSignature) {
         mDetachedSignature = detachedSignature;

OpenKeychain/src/main/java/org/sufficientlysecure/keychain/operations/results/SignEncryptResult.java

@@ -56,6 +56,10 @@ public class SignEncryptResult extends InputPendingResult {
         return mResultBytes;
     }
 
+    public ArrayList<PgpSignEncryptResult> getResults() {
+        return mResults;
+    }
+
     public int describeContents() {
         return 0;
     }

OpenKeychain/src/main/java/org/sufficientlysecure/keychain/pgp/PgpDecryptVerifyOperation.java

@@ -124,8 +124,8 @@ public class PgpDecryptVerifyOperation extends BaseOperation<PgpDecryptVerifyInp
             result.setOutputBytes(outputData);
         }
 
-        result.mTotalTime = System.currentTimeMillis() - startTime;
+        result.mOperationTime = System.currentTimeMillis() - startTime;
-        Log.d(Constants.TAG, "total time taken: " + String.format("%.2f", result.mTotalTime / 1000.0) + "s");
+        Log.d(Constants.TAG, "total time taken: " + String.format("%.2f", result.mOperationTime / 1000.0) + "s");
         return result;
 
     }
@@ -429,7 +429,7 @@ public class PgpDecryptVerifyOperation extends BaseOperation<PgpDecryptVerifyInp
 
         InputStream dataIn = literalData.getInputStream();
 
-        long startDecryptTime = System.currentTimeMillis();
+        long opTime, startTime = System.currentTimeMillis();
 
         long alreadyWritten = 0;
         long wholeSize = 0; // TODO inputData.getSize() - inputData.getStreamPosition();
@@ -462,8 +462,19 @@ public class PgpDecryptVerifyOperation extends BaseOperation<PgpDecryptVerifyInp
             }
         }
 
-        Log.d(Constants.TAG, "decrypt time taken: " + String.format("%.2f",
+        if (signatureChecker.isInitialized()) {
-                (System.currentTimeMillis()-startDecryptTime) / 1000.0) + "s");
+
+            Object o = plainFact.nextObject();
+            boolean signatureCheckOk = signatureChecker.verifySignatureOnePass(o, log, indent + 1);
+
+            if (!signatureCheckOk) {
+                return new DecryptVerifyResult(DecryptVerifyResult.RESULT_ERROR, log);
+            }
+
+        }
+
+        opTime = System.currentTimeMillis()-startTime;
+        Log.d(Constants.TAG, "decrypt time taken: " + String.format("%.2f", opTime / 1000.0) + "s");
 
         // special treatment to detect pgp mime types
         if (matchesPrefix(firstBytes, "-----BEGIN PGP PUBLIC KEY BLOCK-----")
@@ -479,17 +490,6 @@ public class PgpDecryptVerifyOperation extends BaseOperation<PgpDecryptVerifyInp
         metadata = new OpenPgpMetadata(
                 originalFilename, mimeType, literalData.getModificationTime().getTime(), alreadyWritten, charset);
 
-        if (signatureChecker.isInitialized()) {
-
-            Object o = plainFact.nextObject();
-            boolean signatureCheckOk = signatureChecker.verifySignatureOnePass(o, log, indent + 1);
-
-            if (!signatureCheckOk) {
-                return new DecryptVerifyResult(DecryptVerifyResult.RESULT_ERROR, log);
-            }
-
-        }
-
         indent -= 1;
 
         if (esResult != null) {
@@ -522,6 +522,7 @@ public class PgpDecryptVerifyOperation extends BaseOperation<PgpDecryptVerifyInp
         result.setSignatureResult(signatureChecker.getSignatureResult());
         result.setDecryptionResult(decryptionResultBuilder.build());
         result.setDecryptionMetadata(metadata);
+        result.mOperationTime = opTime;
 
         return result;
 

OpenKeychain/src/main/java/org/sufficientlysecure/keychain/pgp/PgpSignEncryptOperation.java

@@ -321,6 +321,8 @@ public class PgpSignEncryptOperation extends BaseOperation {
         ArmoredOutputStream detachedArmorOut = null;
         BCPGOutputStream detachedBcpgOut = null;
 
+        long opTime, startTime = System.currentTimeMillis();
+
         try {
 
             if (enableEncryption) {
@@ -516,6 +518,10 @@ public class PgpSignEncryptOperation extends BaseOperation {
                 }
             }
 
+            opTime = System.currentTimeMillis() -startTime;
+            Log.d(Constants.TAG, "sign/encrypt time taken: " + String.format("%.2f",
+                    opTime / 1000.0) + "s");
+
             // closing outputs
             // NOTE: closing needs to be done in the correct order!
             if (encryptionOut != null) {
@@ -559,6 +565,7 @@ public class PgpSignEncryptOperation extends BaseOperation {
 
         log.add(LogType.MSG_PSE_OK, indent);
         PgpSignEncryptResult result = new PgpSignEncryptResult(PgpSignEncryptResult.RESULT_OK, log);
+        result.mOperationTime = opTime;
         if (detachedByteOut != null) {
             try {
                 detachedByteOut.flush();

OpenKeychain/src/main/res/values/strings.xml

@@ -1363,6 +1363,11 @@
     <string name="msg_lv_fetch_error_format">"Format error!"</string>
     <string name="msg_lv_fetch_error_nothing">"Resource not found!"</string>
 
+    <string name="msg_bench">"Benchmarking some operations…"</string>
+    <string name="msg_bench_enc_time">"Encryption time: %ss"</string>
+    <string name="msg_bench_dec_time">"Decryption time: %ss"</string>
+    <string name="msg_bench_success">"Benchmarking complete!"</string>
+
     <string name="msg_data">"Processing input data"</string>
     <string name="msg_data_openpgp">"Attempting to process OpenPGP data"</string>
     <string name="msg_data_detached">"Encountered detached signature"</string>