Added timing and measurements to all methods, TODO printout tests

src/tests.rs

@@ -91,23 +91,78 @@ impl TestHarness {
         );
     }
 
-    fn trust_promotion(&mut self, cred: &cred::Lox) -> cred::Migration {
+    fn trust_promotion(&mut self, cred: &cred::Lox) -> (PerfStat, cred::Migration) {
+        let req_start = Instant::now();
         let (promreq, promstate) =
             trust_promotion::request(&cred, &self.ba.lox_pub, self.ba.today()).unwrap();
-        let promresp = self.ba.handle_trust_promotion(promreq).unwrap();
-        trust_promotion::handle_response(promstate, promresp).unwrap()
+        let encoded: Vec<u8> = bincode::serialize(&promreq).unwrap();
+        let req_t = req_start.elapsed();
+        let req_len = encoded.len();
+
+        let resp_start = Instant::now();
+        let decoded = bincode::deserialize(&encoded[..]).unwrap();
+        let promresp = self.ba.handle_trust_promotion(decoded).unwrap();
+        let encoded_resp: Vec<u8> = bincode::serialize(&promresp).unwrap();
+        let resp_t = resp_start.elapsed();
+        let resp_len = encoded_resp.len();
+
+        let resp_handle_start = Instant::now();
+        let decode_resp = bincode::deserialize(&encoded_resp[..]).unwrap();
+        let migcred = trust_promotion::handle_response(promstate, decode_resp).unwrap();
+        let resp_handle_t = resp_handle_start.elapsed();
+
+        return (
+            PerfStat {
+                req_len,
+                resp_len,
+                req_t,
+                resp_t,
+                resp_handle_t,
+            },
+            migcred,
+        );
     }
 
-    fn level0_migration(&mut self, loxcred: &cred::Lox, migcred: &cred::Migration) -> cred::Lox {
+    fn level0_migration(
+        &mut self,
+        loxcred: &cred::Lox,
+        migcred: &cred::Migration,
+    ) -> (PerfStat, cred::Lox) {
+        let req_start = Instant::now();
         let (migreq, migstate) =
             migration::request(loxcred, migcred, &self.ba.lox_pub, &self.ba.migration_pub).unwrap();
-        let migresp = self.ba.handle_migration(migreq).unwrap();
-        migration::handle_response(migstate, migresp, &self.ba.lox_pub).unwrap()
+        let encoded: Vec<u8> = bincode::serialize(&migreq).unwrap();
+        let req_t = req_start.elapsed();
+        let req_len = encoded.len();
+
+        let resp_start = Instant::now();
+        let decoded = bincode::deserialize(&encoded[..]).unwrap();
+        let migresp = self.ba.handle_migration(decoded).unwrap();
+        let encoded_resp: Vec<u8> = bincode::serialize(&migresp).unwrap();
+        let resp_t = resp_start.elapsed();
+        let resp_len = encoded_resp.len();
+
+        let resp_handle_start = Instant::now();
+        let decode_resp: migration::Response = bincode::deserialize(&encoded_resp[..]).unwrap();
+        let cred = migration::handle_response(migstate, decode_resp, &self.ba.lox_pub).unwrap();
+        let resp_handle_t = resp_handle_start.elapsed();
+
+        return (
+            PerfStat {
+                req_len,
+                resp_len,
+                req_t,
+                resp_t,
+                resp_handle_t,
+            },
+            cred,
+        );
     }
 
-    fn level_up(&mut self, cred: &cred::Lox) -> cred::Lox {
+    fn level_up(&mut self, cred: &cred::Lox) -> (PerfStat, cred::Lox) {
         // Read the bucket in the credential to get today's Bucket
         // Reachability credential
+
         let (id, key) = bridge_table::from_scalar(cred.bucket).unwrap();
         let encbuckets = self.ba.enc_bridge_table();
         let bucket =
@@ -116,6 +171,7 @@ impl TestHarness {
 
         // Use the Bucket Reachability credential to advance to the next
         // level
+        let req_start = Instant::now();
         let (req, state) = level_up::request(
             &cred,
             &reachcred,
@@ -124,11 +180,35 @@ impl TestHarness {
             self.ba.today(),
         )
         .unwrap();
-        let resp = self.ba.handle_level_up(req).unwrap();
-        level_up::handle_response(state, resp, &self.ba.lox_pub).unwrap()
+        let encoded: Vec<u8> = bincode::serialize(&req).unwrap();
+        let req_t = req_start.elapsed();
+        let req_len = encoded.len();
+
+        let resp_start = Instant::now();
+        let decoded = bincode::deserialize(&encoded[..]).unwrap();
+        let resp = self.ba.handle_level_up(decoded).unwrap();
+        let encoded_resp: Vec<u8> = bincode::serialize(&resp).unwrap();
+        let resp_t = resp_start.elapsed();
+        let resp_len = encoded_resp.len();
+
+        let resp_handle_start = Instant::now();
+        let decode_resp = bincode::deserialize(&encoded_resp[..]).unwrap();
+        let cred = level_up::handle_response(state, decode_resp, &self.ba.lox_pub).unwrap();
+        let resp_handle_t = resp_handle_start.elapsed();
+
+        return (
+            PerfStat {
+                req_len,
+                resp_len,
+                req_t,
+                resp_t,
+                resp_handle_t,
+            },
+            cred,
+        );
     }
 
-    fn issue_invite(&mut self, cred: &cred::Lox) -> (cred::Lox, cred::Invitation) {
+    fn issue_invite(&mut self, cred: &cred::Lox) -> (PerfStat, (cred::Lox, cred::Invitation)) {
         // Read the bucket in the credential to get today's Bucket
         // Reachability credential
         let (id, key) = bridge_table::from_scalar(cred.bucket).unwrap();
@@ -137,6 +217,7 @@ impl TestHarness {
             bridge_table::BridgeTable::decrypt_bucket(id, &key, &encbuckets[id as usize]).unwrap();
         let reachcred = bucket.1.unwrap();
 
+        let req_start = Instant::now();
         let (req, state) = issue_invite::request(
             &cred,
             &reachcred,
@@ -145,30 +226,140 @@ impl TestHarness {
             self.ba.today(),
         )
         .unwrap();
-        let resp = self.ba.handle_issue_invite(req).unwrap();
-        issue_invite::handle_response(state, resp, &self.ba.lox_pub, &self.ba.invitation_pub)
-            .unwrap()
+        let encoded: Vec<u8> = bincode::serialize(&req).unwrap();
+        let req_t = req_start.elapsed();
+        let req_len = encoded.len();
+
+        let resp_start = Instant::now();
+        let decoded = bincode::deserialize(&encoded[..]).unwrap();
+        let resp = self.ba.handle_issue_invite(decoded).unwrap();
+        let encoded_resp: Vec<u8> = bincode::serialize(&resp).unwrap();
+        let resp_t = resp_start.elapsed();
+        let resp_len = encoded_resp.len();
+
+        let resp_handle_start = Instant::now();
+        let decode_resp = bincode::deserialize(&encoded_resp[..]).unwrap();
+        let (cred, invite) = issue_invite::handle_response(
+            state,
+            decode_resp,
+            &self.ba.lox_pub,
+            &self.ba.invitation_pub,
+        )
+        .unwrap();
+        let resp_handle_t = resp_handle_start.elapsed();
+
+        return (
+            PerfStat {
+                req_len,
+                resp_len,
+                req_t,
+                resp_t,
+                resp_handle_t,
+            },
+            (cred, invite),
+        );
     }
 
-    fn redeem_invite(&mut self, inv: &cred::Invitation) -> cred::Lox {
+    fn redeem_invite(&mut self, inv: &cred::Invitation) -> (PerfStat, cred::Lox) {
+        let req_start = Instant::now();
         let (req, state) =
             redeem_invite::request(&inv, &self.ba.invitation_pub, self.ba.today()).unwrap();
-        let resp = self.ba.handle_redeem_invite(req).unwrap();
-        redeem_invite::handle_response(state, resp, &self.ba.lox_pub).unwrap()
+        let encoded: Vec<u8> = bincode::serialize(&req).unwrap();
+        let req_t = req_start.elapsed();
+        let req_len = encoded.len();
+
+        let resp_start = Instant::now();
+        let decoded = bincode::deserialize(&encoded[..]).unwrap();
+        let resp = self.ba.handle_redeem_invite(decoded).unwrap();
+        let encoded_resp: Vec<u8> = bincode::serialize(&resp).unwrap();
+        let resp_t = resp_start.elapsed();
+        let resp_len = encoded_resp.len();
+
+        let resp_handle_start = Instant::now();
+        let decode_resp = bincode::deserialize(&encoded_resp[..]).unwrap();
+        let cred = redeem_invite::handle_response(state, decode_resp, &self.ba.lox_pub).unwrap();
+        let resp_handle_t = resp_handle_start.elapsed();
+
+        return (
+            PerfStat {
+                req_len,
+                resp_len,
+                req_t,
+                resp_t,
+                resp_handle_t,
+            },
+            cred,
+        );
     }
 
-    fn check_blockage(&mut self, cred: &cred::Lox) -> cred::Migration {
+    fn check_blockage(&mut self, cred: &cred::Lox) -> (PerfStat, cred::Migration) {
+        let req_start = Instant::now();
         let (req, state) = check_blockage::request(&cred, &self.ba.lox_pub).unwrap();
-        let resp = self.ba.handle_check_blockage(req).unwrap();
-        check_blockage::handle_response(state, resp).unwrap()
+        let encoded: Vec<u8> = bincode::serialize(&req).unwrap();
+        let req_t = req_start.elapsed();
+        let req_len = encoded.len();
+
+        let resp_start = Instant::now();
+        let decoded = bincode::deserialize(&encoded[..]).unwrap();
+        let resp = self.ba.handle_check_blockage(decoded).unwrap();
+        let encoded_resp: Vec<u8> = bincode::serialize(&resp).unwrap();
+        let resp_t = resp_start.elapsed();
+        let resp_len = encoded_resp.len();
+
+        let resp_handle_start = Instant::now();
+        let decode_resp = bincode::deserialize(&encoded_resp[..]).unwrap();
+        let migcred = check_blockage::handle_response(state, decode_resp).unwrap();
+        let resp_handle_t = resp_handle_start.elapsed();
+
+        return (
+            PerfStat {
+                req_len,
+                resp_len,
+                req_t,
+                resp_t,
+                resp_handle_t,
+            },
+            migcred,
+        );
     }
 
-    fn blockage_migration(&mut self, cred: &cred::Lox, mig: &cred::Migration) -> cred::Lox {
+    fn blockage_migration(
+        &mut self,
+        cred: &cred::Lox,
+        mig: &cred::Migration,
+    ) -> (PerfStat, cred::Lox) {
+        let req_start = Instant::now();
         let (req, state) =
             blockage_migration::request(&cred, &mig, &self.ba.lox_pub, &self.ba.migration_pub)
                 .unwrap();
-        let resp = self.ba.handle_blockage_migration(req).unwrap();
-        blockage_migration::handle_response(state, resp, &self.ba.lox_pub).unwrap()
+        let encoded: Vec<u8> = bincode::serialize(&req).unwrap();
+        let req_t = req_start.elapsed();
+        let req_len = encoded.len();
+
+        let resp_start = Instant::now();
+        let decoded = bincode::deserialize(&encoded[..]).unwrap();
+        let resp = self.ba.handle_blockage_migration(decoded).unwrap();
+        let encoded_resp: Vec<u8> = bincode::serialize(&resp).unwrap();
+        let resp_t = resp_start.elapsed();
+        let resp_len = encoded_resp.len();
+
+        let resp_handle_start = Instant::now();
+        let decode_resp: blockage_migration::Response =
+            bincode::deserialize(&encoded_resp[..]).unwrap();
+        let cred =
+            blockage_migration::handle_response(state, decode_resp, &self.ba.lox_pub).unwrap();
+        let resp_handle_t = resp_handle_start.elapsed();
+
+        return (
+            PerfStat {
+                req_len,
+                resp_len,
+                req_t,
+                resp_t,
+                resp_handle_t,
+            },
+            cred,
+        );
     }
 }
 
@@ -207,7 +398,7 @@ fn test_trust_promotion() {
     // Time passes
     th.advance_days(47);
 
-    let migcred = th.trust_promotion(&cred);
+    let (perf_stat, migcred) = th.trust_promotion(&cred);
     assert!(th.ba.verify_migration(&migcred));
 
     // Check that we can use the to_bucket in the Migration credenital
@@ -216,6 +407,11 @@ fn test_trust_promotion() {
     let encbuckets = th.ba.enc_bridge_table();
     let bucket =
         bridge_table::BridgeTable::decrypt_bucket(id, &key, &encbuckets[id as usize]).unwrap();
+    println!("Request size = {:?}", perf_stat.req_len);
+    println!("Request time = {:?}", perf_stat.req_t);
+    println!("Response size = {:?}", perf_stat.resp_len);
+    println!("Response time = {:?}", perf_stat.resp_t);
+    println!("Response handle time = {:?}", perf_stat.resp_handle_t);
     println!("bucket = {:?}", bucket);
     assert!(th.ba.verify_reachability(&bucket.1.unwrap()));
 }
@@ -230,10 +426,39 @@ fn test_level0_migration() {
     // Time passes
     th.advance_days(47);
 
-    let migcred = th.trust_promotion(&cred);
+    let (perf_stat, migcred) = th.trust_promotion(&cred);
     assert!(th.ba.verify_migration(&migcred));
-
-    let newloxcred = th.level0_migration(&cred, &migcred);
+    println!(
+        "Trust Promotion to 1 Request size = {:?}",
+        perf_stat.req_len
+    );
+    println!("Trust Promotion to 1 Request time = {:?}", perf_stat.req_t);
+    println!(
+        "Trust Promotion to 1 Response size = {:?}",
+        perf_stat.resp_len
+    );
+    println!(
+        "Trust Promotion to 1 Response time = {:?}",
+        perf_stat.resp_t
+    );
+    println!(
+        "Trust Promotion to 1 Response handle time = {:?}",
+        perf_stat.resp_handle_t
+    );
+
+    let (mperf_stat, newloxcred) = th.level0_migration(&cred, &migcred);
+
+    println!("Level 0 migration Request size = {:?}", mperf_stat.req_len);
+    println!("Level 0 migration Request time = {:?}", mperf_stat.req_t);
+    println!(
+        "Level 0 migration Response size = {:?}",
+        mperf_stat.resp_len
+    );
+    println!("Level 0 migration Response time = {:?}", mperf_stat.resp_t);
+    println!(
+        "Level 0 migration Response handle time = {:?}",
+        perf_stat.resp_handle_t
+    );
 
     assert!(th.ba.verify_lox(&newloxcred));
     println!("newloxcred = {:?}", newloxcred);
@@ -257,32 +482,132 @@ fn test_level_up() {
     th.advance_days(47);
 
     // Go up to level 1
-    let migcred = th.trust_promotion(&cred);
-    let cred1 = th.level0_migration(&cred, &migcred);
+    let (perf_stat, migcred) = th.trust_promotion(&cred);
+    println!(
+        "Trust Promotion to 1 Request size = {:?}",
+        perf_stat.req_len
+    );
+    println!("Trust Promotion to 1 Request time = {:?}", perf_stat.req_t);
+    println!(
+        "Trust Promotion to 1 Response size = {:?}",
+        perf_stat.resp_len
+    );
+    println!(
+        "Trust Promotion to 1 Response time = {:?}",
+        perf_stat.resp_t
+    );
+    println!(
+        "Trust Promotion to 1 Response handle time = {:?}",
+        perf_stat.resp_handle_t
+    );
+
+    let (mperf_stat, cred1) = th.level0_migration(&cred, &migcred);
+
+    println!(
+        "New Level 1 credential Request size = {:?}",
+        mperf_stat.req_len
+    );
+    println!(
+        "New Level 1 credential Request time = {:?}",
+        mperf_stat.req_t
+    );
+    println!(
+        "New Level 1 credential Response size = {:?}",
+        mperf_stat.resp_len
+    );
+    println!(
+        "New Level 1 credential Response time = {:?}",
+        mperf_stat.resp_t
+    );
+    println!(
+        "New Level 1 credential Response handle time = {:?}",
+        perf_stat.resp_handle_t
+    );
+
     assert!(scalar_u32(&cred1.trust_level).unwrap() == 1);
 
     // Time passes
     th.advance_days(20);
 
-    let cred2 = th.level_up(&cred1);
+    let (two_perf_stat, cred2) = th.level_up(&cred1);
     assert!(scalar_u32(&cred2.trust_level).unwrap() == 2);
     println!("cred2 = {:?}", cred2);
+    println!(
+        "Trust Promotion to 2 Request size = {:?}",
+        two_perf_stat.req_len
+    );
+    println!(
+        "Trust Promotion to 2 Request time = {:?}",
+        two_perf_stat.req_t
+    );
+    println!(
+        "Trust Promotion to 2 Response size = {:?}",
+        two_perf_stat.resp_len
+    );
+    println!(
+        "Trust Promotion to 2 Response time = {:?}",
+        two_perf_stat.resp_t
+    );
+    println!(
+        "Trust Promotion to 2 Response handle time = {:?}",
+        two_perf_stat.resp_handle_t
+    );
     assert!(th.ba.verify_lox(&cred2));
 
     // Time passes
     th.advance_days(30);
 
-    let cred3 = th.level_up(&cred2);
+    let (three_perf_stat, cred3) = th.level_up(&cred2);
     assert!(scalar_u32(&cred3.trust_level).unwrap() == 3);
     println!("cred3 = {:?}", cred3);
+    println!(
+        "Trust Promotion to 3 Request size = {:?}",
+        three_perf_stat.req_len
+    );
+    println!(
+        "Trust Promotion to 3 Request time = {:?}",
+        three_perf_stat.req_t
+    );
+    println!(
+        "Trust Promotion to 3 Response size = {:?}",
+        three_perf_stat.resp_len
+    );
+    println!(
+        "Trust Promotion to 3 Response time = {:?}",
+        three_perf_stat.resp_t
+    );
+    println!(
+        "Trust Promotion to 3 Response handle time = {:?}",
+        three_perf_stat.resp_handle_t
+    );
     assert!(th.ba.verify_lox(&cred3));
 
     // Time passes
     th.advance_days(60);
 
-    let cred4 = th.level_up(&cred3);
+    let (four_perf_stat, cred4) = th.level_up(&cred3);
     assert!(scalar_u32(&cred3.trust_level).unwrap() == 3);
     println!("cred4 = {:?}", cred4);
+    println!(
+        "Trust Promotion to 4 Request size = {:?}",
+        four_perf_stat.req_len
+    );
+    println!(
+        "Trust Promotion to 4 Request time = {:?}",
+        four_perf_stat.req_t
+    );
+    println!(
+        "Trust Promotion to 4 Response size = {:?}",
+        four_perf_stat.resp_len
+    );
+    println!(
+        "Trust Promotion to 4 Response time = {:?}",
+        four_perf_stat.resp_t
+    );
+    println!(
+        "Trust Promotion to 4 Response handle time = {:?}",
+        four_perf_stat.resp_handle_t
+    );
     assert!(th.ba.verify_lox(&cred4));
 }
 
@@ -297,21 +622,21 @@ fn test_issue_invite() {
     th.advance_days(47);
 
     // Go up to level 1
-    let migcred = th.trust_promotion(&cred);
-    let cred1 = th.level0_migration(&cred, &migcred);
+    let (perf_stat, migcred) = th.trust_promotion(&cred);
+    let (mperf_stat, cred1) = th.level0_migration(&cred, &migcred);
     assert!(scalar_u32(&cred1.trust_level).unwrap() == 1);
 
     // Time passes
     th.advance_days(20);
 
     // Go up to level 2
-    let cred2 = th.level_up(&cred1);
+    let (two_perf_stat, cred2) = th.level_up(&cred1);
     assert!(scalar_u32(&cred2.trust_level).unwrap() == 2);
     println!("cred2 = {:?}", cred2);
     assert!(th.ba.verify_lox(&cred2));
 
     // Issue an invitation
-    let (cred2a, invite) = th.issue_invite(&cred2);
+    let (invite_perf_stat, (cred2a, invite)) = th.issue_invite(&cred2);
     assert!(th.ba.verify_lox(&cred2a));
     assert!(th.ba.verify_invitation(&invite));
     println!("cred2a = {:?}", cred2a);
@@ -329,21 +654,21 @@ fn test_redeem_invite() {
     th.advance_days(47);
 
     // Go up to level 1
-    let migcred = th.trust_promotion(&cred);
-    let cred1 = th.level0_migration(&cred, &migcred);
+    let (perf_stat, migcred) = th.trust_promotion(&cred);
+    let (one_perf_stat, cred1) = th.level0_migration(&cred, &migcred);
     assert!(scalar_u32(&cred1.trust_level).unwrap() == 1);
 
     // Time passes
     th.advance_days(20);
 
     // Go up to level 2
-    let cred2 = th.level_up(&cred1);
+    let (two_perf_stat, cred2) = th.level_up(&cred1);
     assert!(scalar_u32(&cred2.trust_level).unwrap() == 2);
     println!("cred2 = {:?}", cred2);
     assert!(th.ba.verify_lox(&cred2));
 
     // Issue an invitation to Bob
-    let (cred2a, bob_invite) = th.issue_invite(&cred2);
+    let (invite_perf_stat, (cred2a, bob_invite)) = th.issue_invite(&cred2);
     assert!(th.ba.verify_lox(&cred2a));
     assert!(th.ba.verify_invitation(&bob_invite));
     println!("cred2a = {:?}", cred2a);
@@ -353,7 +678,7 @@ fn test_redeem_invite() {
     th.advance_days(12);
 
     // Bob joins the system
-    let bob_cred = th.redeem_invite(&bob_invite);
+    let (bob_perf_stat, bob_cred) = th.redeem_invite(&bob_invite);
     assert!(th.ba.verify_lox(&bob_cred));
     println!("bob_cred = {:?}", bob_cred);
 }
@@ -419,15 +744,15 @@ fn test_blockage_migration() {
     th.advance_days(47);
 
     // Go up to level 1
-    let migcred = th.trust_promotion(&cred);
-    let cred1 = th.level0_migration(&cred, &migcred);
+    let (mperf_stat, migcred) = th.trust_promotion(&cred);
+    let (perf_stat, cred1) = th.level0_migration(&cred, &migcred);
     assert!(scalar_u32(&cred1.trust_level).unwrap() == 1);
 
     // Time passes
     th.advance_days(20);
 
     // Go up to level 2
-    let cred2 = th.level_up(&cred1);
+    let (two_perf_stat, cred2) = th.level_up(&cred1);
     assert!(scalar_u32(&cred2.trust_level).unwrap() == 2);
     println!("cred2 = {:?}", cred2);
     assert!(th.ba.verify_lox(&cred2));
@@ -436,7 +761,7 @@ fn test_blockage_migration() {
     th.advance_days(29);
 
     // Go up to level 3
-    let cred3 = th.level_up(&cred2);
+    let (three_perf_stat, cred3) = th.level_up(&cred2);
     assert!(scalar_u32(&cred3.trust_level).unwrap() == 3);
     println!("cred3 = {:?}", cred3);
     assert!(th.ba.verify_lox(&cred3));
@@ -468,12 +793,12 @@ fn test_blockage_migration() {
     assert!(bucket2.1.is_none());
 
     // See about getting a Migration credential for the blockage
-    let migration = th.check_blockage(&cred3);
+    let (block_perf_stat, migration) = th.check_blockage(&cred3);
 
     println!("migration = {:?}", migration);
 
     // Migrate
-    let cred4 = th.blockage_migration(&cred3, &migration);
+    let (four_perf_stat, cred4) = th.blockage_migration(&cred3, &migration);
 
     println!("cred4 = {:?}", cred4);
     assert!(th.ba.verify_lox(&cred4));