chore: add performance measurement infrastructure

.github/workflows/library_rust_tests.yml

@@ -202,9 +202,9 @@ jobs:
           unzip valid-Net-4.0.0.zip -d valid-Net-4.0.0
 
       - name: Test Rust
-        working-directory: ${{ matrix.library }}
+        working-directory: ${{ matrix.library }}/runtimes/rust
         shell: bash
         run: |
           # Without this, running test vectors fails due to `fatal runtime error: stack overflow`
           export RUST_MIN_STACK=104857600
-          make test_rust
+          cargo test --release -- --test-threads 1 --nocapture

TestVectors/dafny/TestVectors/src/EsdkManifestOptions.dfy

@@ -7,18 +7,37 @@ module {:options "-functionSyntax:4"} EsdkManifestOptions {
   import opened Wrappers
   import Types = AwsCryptographyEncryptionSdkTypes
 
+  datatype PerfReport =
+    | ReportNone
+    | ReportIndividual
+    | ReportFinal
+    | ReportAll
+    | ReportLoop(count : nat)
+
+  predicate DoReportFinal(r : PerfReport)
+  {
+    r.ReportFinal? || r.ReportAll?
+  }
+
+  predicate DoReportIndividual(r : PerfReport)
+  {
+    r.ReportIndividual? || r.ReportAll?
+  }
+
   datatype ManifestOptions =
     | Decrypt(
         nameonly manifestPath: string,
         nameonly manifestFileName: string,
         nameonly retryPolicy: Types.NetV4_0_0_RetryPolicy,
-        nameonly testName: Option<string> := None
+        nameonly testName: Option<string> := None,
+        nameonly report: PerfReport := ReportNone
       )
     | Encrypt(
         nameonly manifestPath: string,
         nameonly manifest: string,
         nameonly decryptManifestOutput: string,
         nameonly testName: Option<string> := None,
+        nameonly report: PerfReport := ReportNone,
         nameonly legacyOutput: int := 5
       )
     | DecryptSingle(

TestVectors/dafny/TestVectors/src/EsdkTestManifests.dfy

@@ -28,6 +28,7 @@ module {:options "-functionSyntax:4"} EsdkTestManifests {
   import EsdkManifestOptions
   import opened EsdkTestVectors
   import WriteVectors
+  import Time
 
   method StartDecryptVectors(
     op: EsdkManifestOptions.ManifestOptions
@@ -49,7 +50,7 @@ module {:options "-functionSyntax:4"} EsdkTestManifests {
       decryptManifest.jsonTests
     );
 
-    output := TestDecrypts(decryptManifest.keys, decryptVectors);
+    output := TestDecrypts(decryptManifest.keys, decryptVectors, op.report);
   }
 
   predicate TestDecryptVector?(v: EsdkDecryptTestVector)
@@ -59,7 +60,8 @@ module {:options "-functionSyntax:4"} EsdkTestManifests {
 
   method TestDecrypts(
     keys: KeyVectors.KeyVectorsClient,
-    vectors: seq<EsdkDecryptTestVector>
+    vectors: seq<EsdkDecryptTestVector>,
+    report: EsdkManifestOptions.PerfReport
   )
     returns (manifest: Result<seq<BoundedInts.byte>, string>)
     requires keys.ValidState()
@@ -70,21 +72,31 @@ module {:options "-functionSyntax:4"} EsdkTestManifests {
 
     var hasFailure := false;
     var skipped := 0;
+    var time := Time.GetAbsoluteTime();
 
     for i := 0 to |vectors|
     {
       var vector := vectors[i];
       if TestDecryptVector?(vector) {
-        var pass := EsdkTestVectors.TestDecrypt(keys, vector);
+        var itime := Time.GetAbsoluteTime();
+        var pass := EsdkTestVectors.TestDecrypt(keys, vector, report);
+        if EsdkManifestOptions.DoReportIndividual(report) {
+          var elapsed := Time.TimeSince(itime);
+          Time.PrintTimeLong(elapsed, "Decrypt " + vector.id, Some(LogFileName()));
+        }
         if !pass {
           hasFailure := true;
         }
       } else {
         skipped := skipped + 1;
         print "\nSKIP===> ", vector.id, "\n";
       }
-
     }
+    if EsdkManifestOptions.DoReportFinal(report) {
+      var elapsed := Time.TimeSince(time);
+      Time.PrintTimeLong(elapsed, "TestDecrypts ESDK", Some(LogFileName()));
+    }
+
     print "\n=================== Completed ", |vectors|, " Decrypt Tests =================== \n\n";
 
     if 0 < skipped {
@@ -94,6 +106,15 @@ module {:options "-functionSyntax:4"} EsdkTestManifests {
     manifest := if !hasFailure then Success([]) else Failure("Test Vectors failed, see errors above.\n");
   }
 
+  method GetRandom(n : mplTypes.PositiveInteger) returns (out : seq<uint8>)
+  {
+    var p :- expect AtomicPrimitives.AtomicPrimitives();
+    out :- expect p.GenerateRandomBytes(
+      AtomicPrimitives.Types.GenerateRandomBytesInput(
+        length := n
+      ));
+  }
+
   method {:vcs_split_on_every_assert} StartEncryptVectors(
     op: EsdkManifestOptions.ManifestOptions
   )
@@ -111,15 +132,11 @@ module {:options "-functionSyntax:4"} EsdkTestManifests {
       encryptManifest.jsonTests
     );
 
-    var p :- expect AtomicPrimitives.AtomicPrimitives();
     var plaintext := map[];
     for i := 0 to |encryptManifest.plaintext|
     {
       var (name, length) := encryptManifest.plaintext[i];
-      var data :- expect p.GenerateRandomBytes(
-        AtomicPrimitives.Types.GenerateRandomBytesInput(
-          length := length
-        ));
+      var data := GetRandom(length);
       // Write the plaintext to disk.
       print op.decryptManifestOutput + plaintextPathRoot + name, "\n\n";
       var _ :- WriteVectorsFile(op.decryptManifestOutput + plaintextPathRoot + name, data);
@@ -128,7 +145,7 @@ module {:options "-functionSyntax:4"} EsdkTestManifests {
 
     var encryptTests? := ToEncryptTests(encryptManifest.keys, encryptVectors);
     var encryptTests :- encryptTests?.MapFailure((e: KeyVectorsTypes.Error) => var _ := MplVectorPrintErr(e); "Cmm failure");
-    var decryptVectors :- TestEncrypts(plaintext, encryptManifest.keys, encryptTests);
+    var decryptVectors :- TestEncrypts(plaintext, encryptManifest.keys, encryptTests, op.report);
 
     var _ :- WriteVectors.WriteDecryptManifest(op, encryptManifest.keys, decryptVectors);
 
@@ -167,7 +184,8 @@ module {:options "-functionSyntax:4"} EsdkTestManifests {
   method TestEncrypts(
     plaintexts: map<string, seq<uint8>>,
     keys: KeyVectors.KeyVectorsClient,
-    tests: seq<EsdkTestVectors.EncryptTest>
+    tests: seq<EsdkTestVectors.EncryptTest>,
+    report: EsdkManifestOptions.PerfReport
   )
     returns (manifest: Result<seq<EsdkDecryptTestVector>, string>)
     requires keys.ValidState()
@@ -183,6 +201,7 @@ module {:options "-functionSyntax:4"} EsdkTestManifests {
     var hasFailure := false;
     var decryptVectors := [];
     var skipped := [];
+    var time := Time.GetAbsoluteTime();
 
     for i := 0 to |tests|
       invariant forall t <- tests ::
@@ -199,7 +218,13 @@ module {:options "-functionSyntax:4"} EsdkTestManifests {
           && test.vector.algorithmSuiteId.value.id.ESDK?,
           "Vector is using an algorithm suite other than ESDK"
         );
-        var pass :- EsdkTestVectors.TestEncrypt(plaintexts, keys, test);
+        var itime := Time.GetAbsoluteTime();
+        var pass :- EsdkTestVectors.TestEncrypt(plaintexts, keys, test, report);
+        if EsdkManifestOptions.DoReportIndividual(report) {
+          var elapsed := Time.TimeSince(itime);
+          Time.PrintTimeLong(elapsed, "Encrypt " + test.vector.id.UnwrapOr("unknown"), Some(LogFileName()));
+        }
+
         if !pass.output {
           hasFailure := true;
         } else if pass.vector.Some? {
@@ -210,6 +235,10 @@ module {:options "-functionSyntax:4"} EsdkTestManifests {
         print "\nSKIP===> ", test.vector.id.value, "\n";
       }
     }
+    if EsdkManifestOptions.DoReportFinal(report) {
+      var elapsed := Time.TimeSince(time);
+      Time.PrintTimeLong(elapsed, "TestEncrypts ESDK", Some(LogFileName()));
+    }
     print "\n=================== Completed ", |tests|, " Encrypt Tests =================== \n\n";
 
     expect !hasFailure;

TestVectors/dafny/TestVectors/src/EsdkTestVectors.dfy

@@ -20,6 +20,18 @@ module {:options "-functionSyntax:4"} EsdkTestVectors {
   import KeyVectorsTypes = AwsCryptographyMaterialProvidersTestVectorKeysTypes
   import TestVectors
   import AllAlgorithmSuites
+  import EsdkManifestOptions
+  import Time
+  import OsLang
+  import StandardLibrary.String
+
+  function LogFileName() : string
+  {
+    if OsLang.GetLanguageShort() == "Dotnet" then
+      "PerfLog.txt"
+    else
+      "../../PerfLog.txt"
+  }
 
   datatype EncryptTest = EncryptTest(
     cmm: mplTypes.ICryptographicMaterialsManager,
@@ -192,27 +204,27 @@ module {:options "-functionSyntax:4"} EsdkTestVectors {
 
   method {:vcs_split_on_every_assert} TestDecrypt(
     keys: KeyVectors.KeyVectorsClient,
-    vector: EsdkDecryptTestVector
+    vector: EsdkDecryptTestVector,
+    report: EsdkManifestOptions.PerfReport
   )
     returns (output: bool)
     requires keys.ValidState()
     modifies keys.Modifies
     ensures keys.ValidState()
   {
-    if vector.algorithmSuiteId.Some? {
-      var id := AllAlgorithmSuites.ToHex(vector.algorithmSuiteId.value);
-      print "\nTEST-DECRYPT===> ", vector.id, "\n", id, " ", vector.description, "\n";
-    } else {
-      print "\nTEST-DECRYPT===> ", vector.id, "\n", vector.description, "\n";
-    }
-
     // The decrypt test vectors also test initialization
     // This is because they were developed when the MPL
     // was still part of the ESDK
     var test? := DecryptVectorToDecryptTest(keys, vector);
 
     if test?.Failure? {
       print test?.error, "\n", "\nFAILED! <-----------\n";
+      if vector.algorithmSuiteId.Some? {
+        var id := AllAlgorithmSuites.ToHex(vector.algorithmSuiteId.value);
+        print "\nTEST-DECRYPT===> ", vector.id, "\n", id, " ", vector.description, "\n\n";
+      } else {
+        print "\nTEST-DECRYPT===> ", vector.id, "\n", vector.description, "\n\n";
+      }
       return false;
     }
 
@@ -234,6 +246,26 @@ module {:options "-functionSyntax:4"} EsdkTestVectors {
       keyring := None
     );
 
+    if report.ReportLoop? {
+      var pos := test.vector.PositiveDecryptTestVector? || test.vector.PositiveV1OrV2DecryptTestVector? || test.vector.PositiveV4DecryptTestVector?;
+      var time := Time.GetAbsoluteTime();
+      var total := report.count;
+      for i := 0 to report.count {
+        var result := test.client.Decrypt(input);
+        if pos && result.Failure? {
+          print "Aborting ReportLoop for ", test.vector.id, " because it was a positive test and it failed with ", result.error, "\n";
+          total := i;
+          break;
+        } else if !pos && result.Success? {
+          print "Aborting ReportLoop for ", test.vector.id, " because it was a negative test and it succeeded\n";
+          total := i;
+          break;
+        }
+      }
+      var elapsed := Time.TimeSince(time);
+      Time.PrintTimeLong(elapsed, "Decrypt(" + String.Base10Int2String(total) + ") " + test.vector.id, Some(LogFileName()));
+    }
+
     var result := test.client.Decrypt(input);
 
     output := match test.vector
@@ -331,7 +363,8 @@ module {:options "-functionSyntax:4"} EsdkTestVectors {
   method {:vcs_split_on_every_assert} TestEncrypt(
     plaintexts: map<string, seq<uint8>>,
     keys: KeyVectors.KeyVectorsClient,
-    test: EncryptTest
+    test: EncryptTest,
+    report: EsdkManifestOptions.PerfReport
   )
     returns (output: Result<EncryptTestOutput, string>)
     requires keys.ValidState() && test.ValidState()
@@ -344,9 +377,6 @@ module {:options "-functionSyntax:4"} EsdkTestVectors {
     requires test.vector.algorithmSuiteId.Some? && test.vector.algorithmSuiteId.value.id.ESDK?
     requires test.vector.id.Some?
   {
-    var id := AllAlgorithmSuites.ToHex(test.vector.algorithmSuiteId.value);
-    print "\nTEST-ENCRYPT===> ", test.vector.id.value, "\n", id, " ", test.vector.description, "\n";
-
     // The encrypt test vectors also test initialization
     // This is because they were developed when the MPL
     // was still part of the ESDK
@@ -364,6 +394,26 @@ module {:options "-functionSyntax:4"} EsdkTestVectors {
       frameLength := frameLength,
       algorithmSuiteId := Some(test.vector.algorithmSuiteId.value.id.ESDK)
     );
+
+    if report.ReportLoop? {
+      var pos := test.vector.PositiveEncryptTestVector? || test.vector.PositiveEncryptNegativeDecryptTestVector?;
+      var time := Time.GetAbsoluteTime();
+      var total := report.count;
+      for i := 0 to report.count {
+        var result := test.client.Encrypt(input);
+        if pos && result.Failure? {
+          print "Aborting ReportLoop for ", test.vector.id.UnwrapOr("unknown"), " because it was a positive test and it failed with ", result.error, "\n";
+          total := i;
+          break;
+        } else if !pos && result.Success? {
+          print "Aborting ReportLoop for ", test.vector.id.UnwrapOr("unknown"), " because it was a negative test and it succeeded\n";
+          total := i;
+          break;
+        }
+      }
+      var elapsed := Time.TimeSince(time);
+      Time.PrintTimeLong(elapsed, "Encrypt(" + String.Base10Int2String(total) + ") " + test.vector.id.UnwrapOr("unknown"), Some(LogFileName()));
+    }
     var result := test.client.Encrypt(input);
 
     if
@@ -386,6 +436,8 @@ module {:options "-functionSyntax:4"} EsdkTestVectors {
         print result.error;
       }
       print "\nFAILED! <-----------\n";
+      var id := AllAlgorithmSuites.ToHex(test.vector.algorithmSuiteId.value);
+      print "\nTEST-ENCRYPT===> ", test.vector.id.value, "\n", id, " ", test.vector.description, "\n\n";
     }
   }
 

TestVectors/dafny/TestVectors/src/Index.dfy

@@ -54,13 +54,13 @@ module {:options "-functionSyntax:4"} WrappedESDKMain {
       if op?.Success? {
         var op := op?.value;
         match op
-        case Decrypt(_, _, _, _) =>
+        case Decrypt(_, _, _, _, _) =>
           var result := EsdkTestManifests.StartDecryptVectors(op);
           if result.Failure? {
             print result.error;
           }
           expect result.Success?;
-        case Encrypt(_, _, _, _, _) =>
+        case Encrypt(_, _, _, _, _, _) =>
           var result := EsdkTestManifests.StartEncryptVectors(op);
           if result.Failure? {
             print result.error;

TestVectors/dafny/TestVectors/src/ParseEsdkJsonManifest.dfy

@@ -216,10 +216,16 @@ module {:options "-functionSyntax:4"} ParseEsdkJsonManifest {
 
     var encryptionContextStrings :- SmallObjectToStringStringMap(encryptionContextJsonKey, scenario);
     var encryptionContext :- utf8EncodeMap(encryptionContextStrings);
-    var reproducedEncryptionContextString :- SmallObjectToStringStringMap(reproducedEncryptionContextJsonKey, scenario);
-    var reproducedEncryptionContext :- utf8EncodeMap(reproducedEncryptionContextString);
+    var reproducedEncryptionContextString := SmallObjectToStringStringMap(reproducedEncryptionContextJsonKey, scenario);
     var description :- GetString("description", scenario);
 
+    // If no reproducedEncryptionContext, default to regular encryptionContext
+    var reproducedEncryptionContext :-
+      if reproducedEncryptionContextString.Success? then
+        utf8EncodeMap(reproducedEncryptionContextString.value)
+      else
+        Success(encryptionContext);
+
     match typ
     case "positive-esdk" =>
       var encryptKeyDescription :- ParseJsonManifests.GetKeyDescription(keys, encryptKeyDescription, scenario);