contract: Add some verification statistics to the integration tests.

src/contract/dao/tests/integration.rs

@@ -16,6 +16,8 @@
  * along with this program.  If not, see <https://www.gnu.org/licenses/>.
  */
 
+use std::time::{Duration, Instant};
+
 use darkfi::{tx::Transaction, Result};
 use darkfi_sdk::{
     crypto::{
@@ -57,6 +59,12 @@ use harness::{init_logger, DaoTestHarness};
 async fn integration_test() -> Result<()> {
     init_logger()?;
 
+    // Some benchmark averages
+    let mut mint_verify_times = vec![];
+    let mut propose_verify_times = vec![];
+    let mut vote_verify_times = vec![];
+    let mut exec_verify_times = vec![];
+
     let dao_th = DaoTestHarness::new().await?;
 
     // Money parameters
@@ -104,7 +112,9 @@ async fn integration_test() -> Result<()> {
     let sigs = tx.create_sigs(&mut OsRng, &[dao_th.dao_kp.secret])?;
     tx.signatures = vec![sigs];
 
+    let timer = Instant::now();
     dao_th.alice_state.read().await.verify_transactions(&[tx.clone()], true).await?;
+    mint_verify_times.push(timer.elapsed());
     // TODO: Witness and add to wallet merkle tree?
 
     let mut dao_tree = MerkleTree::new(100);
@@ -421,7 +431,9 @@ async fn integration_test() -> Result<()> {
     let sigs = tx.create_sigs(&mut OsRng, &vec![signature_secret])?;
     tx.signatures = vec![sigs];
 
+    let timer = Instant::now();
     dao_th.alice_state.read().await.verify_transactions(&[tx.clone()], true).await?;
+    propose_verify_times.push(timer.elapsed());
 
     //// Wallet
 
@@ -526,7 +538,9 @@ async fn integration_test() -> Result<()> {
     let sigs = tx.create_sigs(&mut OsRng, &vec![signature_secret])?;
     tx.signatures = vec![sigs];
 
+    let timer = Instant::now();
     dao_th.alice_state.read().await.verify_transactions(&[tx.clone()], true).await?;
+    vote_verify_times.push(timer.elapsed());
 
     // Secret vote info. Needs to be revealed at some point.
     // TODO: look into verifiable encryption for notes
@@ -594,7 +608,9 @@ async fn integration_test() -> Result<()> {
     let sigs = tx.create_sigs(&mut OsRng, &vec![signature_secret])?;
     tx.signatures = vec![sigs];
 
+    let timer = Instant::now();
     dao_th.alice_state.read().await.verify_transactions(&[tx.clone()], true).await?;
+    vote_verify_times.push(timer.elapsed());
 
     let vote_note_2 = {
         let enc_note = note::EncryptedNote2 {
@@ -659,7 +675,9 @@ async fn integration_test() -> Result<()> {
     let sigs = tx.create_sigs(&mut OsRng, &vec![signature_secret])?;
     tx.signatures = vec![sigs];
 
+    let timer = Instant::now();
     dao_th.alice_state.read().await.verify_transactions(&[tx.clone()], true).await?;
+    vote_verify_times.push(timer.elapsed());
 
     // Secret vote info. Needs to be revealed at some point.
     // TODO: look into verifiable encryption for notes
@@ -850,7 +868,26 @@ async fn integration_test() -> Result<()> {
     let exec_sigs = tx.create_sigs(&mut OsRng, &vec![exec_signature_secret])?;
     tx.signatures = vec![xfer_sigs, exec_sigs];
 
+    let timer = Instant::now();
     dao_th.alice_state.read().await.verify_transactions(&[tx.clone()], true).await?;
+    exec_verify_times.push(timer.elapsed());
+
+    // Statistics
+    let mint_avg = mint_verify_times.iter().sum::<Duration>();
+    let mint_avg = mint_avg / mint_verify_times.len() as u32;
+    println!("Average Mint verification time: {:?}", mint_avg);
+
+    let propose_avg = propose_verify_times.iter().sum::<Duration>();
+    let propose_avg = propose_avg / propose_verify_times.len() as u32;
+    println!("Average Propose verification time: {:?}", propose_avg);
+
+    let vote_avg = vote_verify_times.iter().sum::<Duration>();
+    let vote_avg = vote_avg / vote_verify_times.len() as u32;
+    println!("Average Vote verification time: {:?}", vote_avg);
+
+    let exec_avg = exec_verify_times.iter().sum::<Duration>();
+    let exec_avg = exec_avg / exec_verify_times.len() as u32;
+    println!("Average Exec verification time: {:?}", exec_avg);
 
     Ok(())
 }

src/contract/money/tests/mint_pay_swap.rs

@@ -27,6 +27,8 @@
 //!
 //! TODO: Malicious cases
 
+use std::time::{Duration, Instant};
+
 use darkfi::{tx::Transaction, Result};
 use darkfi_sdk::{
     crypto::{
@@ -53,6 +55,11 @@ use harness::{init_logger, MoneyTestHarness};
 async fn money_contract_transfer() -> Result<()> {
     init_logger();
 
+    // Some benchmark averages
+    let mut swap_verify_times = vec![];
+    let mut transfer_verify_times = vec![];
+    let mut mint_verify_times = vec![];
+
     // Some numbers we want to assert
     const ALICE_INITIAL: u64 = 100;
     const BOB_INITIAL: u64 = 200;
@@ -98,41 +105,53 @@ async fn money_contract_transfer() -> Result<()> {
     info!(target: "money", "[Faucet] =============================");
     info!(target: "money", "[Faucet] Executing Alice token mint tx");
     info!(target: "money", "[Faucet] =============================");
+    let timer = Instant::now();
     th.faucet.state.read().await.verify_transactions(&[alice_mint_tx.clone()], true).await?;
     th.faucet.merkle_tree.append(&MerkleNode::from(alice_params.output.coin.inner()));
+    mint_verify_times.push(timer.elapsed());
 
     info!(target: "money", "[Faucet] ===========================");
     info!(target: "money", "[Faucet] Executing Bob token mint tx");
     info!(target: "money", "[Faucet] ===========================");
+    let timer = Instant::now();
     th.faucet.state.read().await.verify_transactions(&[bob_mint_tx.clone()], true).await?;
     th.faucet.merkle_tree.append(&MerkleNode::from(bob_params.output.coin.inner()));
+    mint_verify_times.push(timer.elapsed());
 
     info!(target: "money", "[Alice] =============================");
     info!(target: "money", "[Alice] Executing Alice token mint tx");
     info!(target: "money", "[Alice] =============================");
+    let timer = Instant::now();
     th.alice.state.read().await.verify_transactions(&[alice_mint_tx.clone()], true).await?;
     th.alice.merkle_tree.append(&MerkleNode::from(alice_params.output.coin.inner()));
     // Alice has to witness this coin because it's hers.
     let alice_leaf_pos = th.alice.merkle_tree.witness().unwrap();
+    mint_verify_times.push(timer.elapsed());
 
     info!(target: "money", "[Alice] ===========================");
     info!(target: "money", "[Alice] Executing Bob token mint tx");
     info!(target: "money", "[Alice] ===========================");
+    let timer = Instant::now();
     th.alice.state.read().await.verify_transactions(&[bob_mint_tx.clone()], true).await?;
     th.alice.merkle_tree.append(&MerkleNode::from(bob_params.output.coin.inner()));
+    mint_verify_times.push(timer.elapsed());
 
     info!(target: "money", "[Bob] =============================");
     info!(target: "money", "[Bob] Executing Alice token mint tx");
     info!(target: "money", "[Bob] =============================");
+    let timer = Instant::now();
     th.bob.state.read().await.verify_transactions(&[alice_mint_tx.clone()], true).await?;
     th.bob.merkle_tree.append(&MerkleNode::from(alice_params.output.coin.inner()));
+    mint_verify_times.push(timer.elapsed());
 
     info!(target: "money", "[Bob] ===========================");
     info!(target: "money", "[Bob] Executing Bob token mint tx");
     info!(target: "money", "[Bob] ===========================");
+    let timer = Instant::now();
     th.bob.state.read().await.verify_transactions(&[bob_mint_tx.clone()], true).await?;
     th.bob.merkle_tree.append(&MerkleNode::from(bob_params.output.coin.inner()));
     let bob_leaf_pos = th.bob.merkle_tree.witness().unwrap();
+    mint_verify_times.push(timer.elapsed());
 
     assert!(th.alice.merkle_tree.root(0).unwrap() == th.bob.merkle_tree.root(0).unwrap());
     assert!(th.faucet.merkle_tree.root(0).unwrap() == th.bob.merkle_tree.root(0).unwrap());
@@ -212,25 +231,31 @@ async fn money_contract_transfer() -> Result<()> {
     info!(target: "money", "[Faucet] ==============================");
     info!(target: "money", "[Faucet] Executing Alice2Bob payment tx");
     info!(target: "money", "[Faucet] ==============================");
+    let timer = Instant::now();
     th.faucet.state.read().await.verify_transactions(&[alice2bob_tx.clone()], true).await?;
     th.faucet.merkle_tree.append(&MerkleNode::from(alice2bob_params.outputs[0].coin.inner()));
     th.faucet.merkle_tree.append(&MerkleNode::from(alice2bob_params.outputs[1].coin.inner()));
+    transfer_verify_times.push(timer.elapsed());
 
     info!(target: "money", "[Alice] ==============================");
     info!(target: "money", "[Alice] Executing Alice2Bob payment tx");
     info!(target: "money", "[Alice] ==============================");
+    let timer = Instant::now();
     th.alice.state.read().await.verify_transactions(&[alice2bob_tx.clone()], true).await?;
     th.alice.merkle_tree.append(&MerkleNode::from(alice2bob_params.outputs[0].coin.inner()));
     let alice_leaf_pos = th.alice.merkle_tree.witness().unwrap();
     th.alice.merkle_tree.append(&MerkleNode::from(alice2bob_params.outputs[1].coin.inner()));
+    transfer_verify_times.push(timer.elapsed());
 
     info!(target: "money", "[Bob] ==============================");
     info!(target: "money", "[Bob] Executing Alice2Bob payment tx");
     info!(target: "money", "[Bob] ==============================");
+    let timer = Instant::now();
     th.bob.state.read().await.verify_transactions(&[alice2bob_tx.clone()], true).await?;
     th.bob.merkle_tree.append(&MerkleNode::from(alice2bob_params.outputs[0].coin.inner()));
     th.bob.merkle_tree.append(&MerkleNode::from(alice2bob_params.outputs[1].coin.inner()));
     let bob_leaf_pos = th.bob.merkle_tree.witness().unwrap();
+    transfer_verify_times.push(timer.elapsed());
 
     assert!(th.alice.merkle_tree.root(0).unwrap() == th.bob.merkle_tree.root(0).unwrap());
     assert!(th.faucet.merkle_tree.root(0).unwrap() == th.bob.merkle_tree.root(0).unwrap());
@@ -313,25 +338,31 @@ async fn money_contract_transfer() -> Result<()> {
     info!(target: "money", "[Faucet] ==============================");
     info!(target: "money", "[Faucet] Executing Bob2Alice payment tx");
     info!(target: "money", "[Faucet] ==============================");
+    let timer = Instant::now();
     th.faucet.state.read().await.verify_transactions(&[bob2alice_tx.clone()], true).await?;
     th.faucet.merkle_tree.append(&MerkleNode::from(bob2alice_params.outputs[0].coin.inner()));
     th.faucet.merkle_tree.append(&MerkleNode::from(bob2alice_params.outputs[1].coin.inner()));
+    transfer_verify_times.push(timer.elapsed());
 
     info!(target: "money", "[Alice] ==============================");
     info!(target: "money", "[Alice] Executing Bob2Alice payment tx");
     info!(target: "money", "[Alice] ==============================");
+    let timer = Instant::now();
     th.alice.state.read().await.verify_transactions(&[bob2alice_tx.clone()], true).await?;
     th.alice.merkle_tree.append(&MerkleNode::from(bob2alice_params.outputs[0].coin.inner()));
     th.alice.merkle_tree.append(&MerkleNode::from(bob2alice_params.outputs[1].coin.inner()));
     let alice_leaf_pos = th.alice.merkle_tree.witness().unwrap();
+    transfer_verify_times.push(timer.elapsed());
 
     info!(target: "money", "[Bob] ==================+===========");
     info!(target: "money", "[Bob] Executing Bob2Alice payment tx");
     info!(target: "money", "[Bob] ==================+===========");
+    let timer = Instant::now();
     th.bob.state.read().await.verify_transactions(&[bob2alice_tx.clone()], true).await?;
     th.bob.merkle_tree.append(&MerkleNode::from(bob2alice_params.outputs[0].coin.inner()));
     let bob_leaf_pos = th.bob.merkle_tree.witness().unwrap();
     th.bob.merkle_tree.append(&MerkleNode::from(bob2alice_params.outputs[1].coin.inner()));
+    transfer_verify_times.push(timer.elapsed());
 
     // Alice should now have two OwnCoins
     let note: MoneyNote = bob2alice_params.outputs[1].note.decrypt(&th.alice.keypair.secret)?;
@@ -473,25 +504,31 @@ async fn money_contract_transfer() -> Result<()> {
     info!(target: "money", "[Faucet] ==========================");
     info!(target: "money", "[Faucet] Executing AliceBob swap tx");
     info!(target: "money", "[Faucet] ==========================");
+    let timer = Instant::now();
     th.faucet.state.read().await.verify_transactions(&[alicebob_swap_tx.clone()], true).await?;
     th.faucet.merkle_tree.append(&MerkleNode::from(swap_full_params.outputs[0].coin.inner()));
     th.faucet.merkle_tree.append(&MerkleNode::from(swap_full_params.outputs[1].coin.inner()));
+    swap_verify_times.push(timer.elapsed());
 
     info!(target: "money", "[Alice] ==========================");
     info!(target: "money", "[Alice] Executing AliceBob swap tx");
     info!(target: "money", "[Alice] ==========================");
+    let timer = Instant::now();
     th.alice.state.read().await.verify_transactions(&[alicebob_swap_tx.clone()], true).await?;
     th.alice.merkle_tree.append(&MerkleNode::from(swap_full_params.outputs[0].coin.inner()));
     let alice_leaf_pos = th.alice.merkle_tree.witness().unwrap();
     th.alice.merkle_tree.append(&MerkleNode::from(swap_full_params.outputs[1].coin.inner()));
+    swap_verify_times.push(timer.elapsed());
 
     info!(target: "money", "[Bob] ==========================");
     info!(target: "money", "[Bob] Executing AliceBob swap tx");
     info!(target: "money", "[Bob] ==========================");
+    let timer = Instant::now();
     th.bob.state.read().await.verify_transactions(&[alicebob_swap_tx.clone()], true).await?;
     th.bob.merkle_tree.append(&MerkleNode::from(swap_full_params.outputs[0].coin.inner()));
     th.bob.merkle_tree.append(&MerkleNode::from(swap_full_params.outputs[1].coin.inner()));
     let bob_leaf_pos = th.bob.merkle_tree.witness().unwrap();
+    swap_verify_times.push(timer.elapsed());
 
     assert!(th.alice.merkle_tree.root(0).unwrap() == th.bob.merkle_tree.root(0).unwrap());
     assert!(th.faucet.merkle_tree.root(0).unwrap() == th.bob.merkle_tree.root(0).unwrap());
@@ -578,21 +615,27 @@ async fn money_contract_transfer() -> Result<()> {
     info!(target: "money", "[Faucet] ================================");
     info!(target: "money", "[Faucet] Executing Alice2Alice payment tx");
     info!(target: "money", "[Faucet] ================================");
+    let timer = Instant::now();
     th.faucet.state.read().await.verify_transactions(&[alice2alice_tx.clone()], true).await?;
     th.faucet.merkle_tree.append(&MerkleNode::from(alice2alice_params.outputs[0].coin.inner()));
+    transfer_verify_times.push(timer.elapsed());
 
     info!(target: "money", "[Alice] ================================");
     info!(target: "money", "[Alice] Executing Alice2Alice payment tx");
     info!(target: "money", "[Alice] ================================");
+    let timer = Instant::now();
     th.alice.state.read().await.verify_transactions(&[alice2alice_tx.clone()], true).await?;
     th.alice.merkle_tree.append(&MerkleNode::from(alice2alice_params.outputs[0].coin.inner()));
     let alice_leaf_pos = th.alice.merkle_tree.witness().unwrap();
+    transfer_verify_times.push(timer.elapsed());
 
     info!(target: "money", "[Bob] ================================");
     info!(target: "money", "[Bob] Executing Alice2Alice payment tx");
     info!(target: "money", "[Bob] ================================");
+    let timer = Instant::now();
     th.bob.state.read().await.verify_transactions(&[alice2alice_tx.clone()], true).await?;
     th.bob.merkle_tree.append(&MerkleNode::from(alice2alice_params.outputs[0].coin.inner()));
+    transfer_verify_times.push(timer.elapsed());
 
     assert!(th.alice.merkle_tree.root(0).unwrap() == th.bob.merkle_tree.root(0).unwrap());
     assert!(th.faucet.merkle_tree.root(0).unwrap() == th.bob.merkle_tree.root(0).unwrap());
@@ -664,21 +707,27 @@ async fn money_contract_transfer() -> Result<()> {
     info!(target: "money", "[Faucet] ============================");
     info!(target: "money", "[Faucet] Executing Bob2Bob payment tx");
     info!(target: "money", "[Faucet] ============================");
+    let timer = Instant::now();
     th.faucet.state.read().await.verify_transactions(&[bob2bob_tx.clone()], true).await?;
     th.faucet.merkle_tree.append(&MerkleNode::from(bob2bob_params.outputs[0].coin.inner()));
+    transfer_verify_times.push(timer.elapsed());
 
     info!(target: "money", "[Alice] ============================");
     info!(target: "money", "[Alice] Executing Bob2Bob payment tx");
     info!(target: "money", "[Alice] ============================");
+    let timer = Instant::now();
     th.alice.state.read().await.verify_transactions(&[bob2bob_tx.clone()], true).await?;
     th.alice.merkle_tree.append(&MerkleNode::from(bob2bob_params.outputs[0].coin.inner()));
+    transfer_verify_times.push(timer.elapsed());
 
     info!(target: "money", "[Bob] ============================");
     info!(target: "money", "[Bob] Executing Bob2Bob payment tx");
     info!(target: "money", "[Bob] ============================");
+    let timer = Instant::now();
     th.bob.state.read().await.verify_transactions(&[bob2bob_tx.clone()], true).await?;
     th.bob.merkle_tree.append(&MerkleNode::from(bob2bob_params.outputs[0].coin.inner()));
     let bob_leaf_pos = th.bob.merkle_tree.witness().unwrap();
+    transfer_verify_times.push(timer.elapsed());
 
     assert!(th.alice.merkle_tree.root(0).unwrap() == th.bob.merkle_tree.root(0).unwrap());
     assert!(th.faucet.merkle_tree.root(0).unwrap() == th.bob.merkle_tree.root(0).unwrap());
@@ -798,25 +847,31 @@ async fn money_contract_transfer() -> Result<()> {
     info!(target: "money", "[Faucet] ==========================");
     info!(target: "money", "[Faucet] Executing AliceBob swap tx");
     info!(target: "money", "[Faucet] ==========================");
+    let timer = Instant::now();
     th.faucet.state.read().await.verify_transactions(&[alicebob_swap_tx.clone()], true).await?;
     th.faucet.merkle_tree.append(&MerkleNode::from(swap_full_params.outputs[0].coin.inner()));
     th.faucet.merkle_tree.append(&MerkleNode::from(swap_full_params.outputs[1].coin.inner()));
+    swap_verify_times.push(timer.elapsed());
 
     info!(target: "money", "[Alice] ==========================");
     info!(target: "money", "[Alice] Executing AliceBob swap tx");
     info!(target: "money", "[Alice] ==========================");
+    let timer = Instant::now();
     th.alice.state.read().await.verify_transactions(&[alicebob_swap_tx.clone()], true).await?;
     th.alice.merkle_tree.append(&MerkleNode::from(swap_full_params.outputs[0].coin.inner()));
     let alice_leaf_pos = th.alice.merkle_tree.witness().unwrap();
     th.alice.merkle_tree.append(&MerkleNode::from(swap_full_params.outputs[1].coin.inner()));
+    swap_verify_times.push(timer.elapsed());
 
     info!(target: "money", "[Bob] ==========================");
     info!(target: "money", "[Bob] Executing AliceBob swap tx");
     info!(target: "money", "[Bob] ==========================");
+    let timer = Instant::now();
     th.bob.state.read().await.verify_transactions(&[alicebob_swap_tx.clone()], true).await?;
     th.bob.merkle_tree.append(&MerkleNode::from(swap_full_params.outputs[0].coin.inner()));
     th.bob.merkle_tree.append(&MerkleNode::from(swap_full_params.outputs[1].coin.inner()));
     let bob_leaf_pos = th.bob.merkle_tree.witness().unwrap();
+    swap_verify_times.push(timer.elapsed());
 
     assert!(th.alice.merkle_tree.root(0).unwrap() == th.bob.merkle_tree.root(0).unwrap());
     assert!(th.faucet.merkle_tree.root(0).unwrap() == th.bob.merkle_tree.root(0).unwrap());
@@ -851,6 +906,19 @@ async fn money_contract_transfer() -> Result<()> {
     assert!(bob_owncoins[0].note.value == ALICE_INITIAL);
     assert!(bob_owncoins[0].note.token_id == alice_token_id);
 
+    // Statistics
+    let swap_avg = swap_verify_times.iter().sum::<Duration>();
+    let swap_avg = swap_avg / swap_verify_times.len() as u32;
+    println!("Average Swap verification time: {:?}", swap_avg);
+
+    let transfer_avg = transfer_verify_times.iter().sum::<Duration>();
+    let transfer_avg = transfer_avg / transfer_verify_times.len() as u32;
+    println!("Average Transfer verification time: {:?}", transfer_avg);
+
+    let mint_avg = mint_verify_times.iter().sum::<Duration>();
+    let mint_avg = mint_avg / mint_verify_times.len() as u32;
+    println!("Average Mint verification time: {:?}", mint_avg);
+
     // Thanks for reading
     Ok(())
 }