[api] Add individual step timing to api tester (#9502)

This commit builds individual step timing on top of the consistent API testing introduced here. See proposal for more high level information.

This addition allows us to dive deeper on what the issue is should we detect any flow is consistently slower.

Changes:

Add timer macro in macros.rs.
Add helpers for emitting metrics and refactor process_result.
Put publish_module in its own thread by creating a tokio runtime.
Add sleeps between persistent checks.
Reduce API client sleep time to 100ms from 500ms.
Make test setups persistent.

crates/aptos-api-tester/src/consts.rs

@@ -0,0 +1,55 @@
+// Copyright © Aptos Foundation
+
+use once_cell::sync::Lazy;
+use std::{env, time::Duration};
+use url::Url;
+
+// faucet constants
+
+pub static DEVNET_NODE_URL: Lazy<Url> =
+    Lazy::new(|| Url::parse("https://fullnode.devnet.aptoslabs.com").unwrap());
+
+pub static DEVNET_FAUCET_URL: Lazy<Url> =
+    Lazy::new(|| Url::parse("https://faucet.devnet.aptoslabs.com").unwrap());
+
+pub static TESTNET_NODE_URL: Lazy<Url> =
+    Lazy::new(|| Url::parse("https://fullnode.testnet.aptoslabs.com").unwrap());
+
+pub static TESTNET_FAUCET_URL: Lazy<Url> =
+    Lazy::new(|| Url::parse("https://faucet.testnet.aptoslabs.com").unwrap());
+
+pub const FUND_AMOUNT: u64 = 100_000_000;
+
+// persistency check constants
+
+pub static PERSISTENCY_TIMEOUT: Lazy<Duration> = Lazy::new(|| {
+    env::var("PERSISTENCY_TIMEOUT")
+        .ok()
+        .and_then(|s| s.parse().ok())
+        .map(Duration::from_secs)
+        .unwrap_or(Duration::from_secs(30))
+});
+
+pub static SLEEP_PER_CYCLE: Lazy<Duration> = Lazy::new(|| {
+    env::var("SLEEP_PER_CYCLE")
+        .ok()
+        .and_then(|s| s.parse().ok())
+        .map(Duration::from_millis)
+        .unwrap_or(Duration::from_millis(100))
+});
+
+// runtime constants
+
+pub static NUM_THREADS: Lazy<usize> = Lazy::new(|| {
+    env::var("NUM_THREADS")
+        .ok()
+        .and_then(|s| s.parse().ok())
+        .unwrap_or(4)
+});
+
+pub static STACK_SIZE: Lazy<usize> = Lazy::new(|| {
+    env::var("STACK_SIZE")
+        .ok()
+        .and_then(|s| s.parse().ok())
+        .unwrap_or(4 * 1024 * 1024)
+});

crates/aptos-api-tester/src/counters.rs

@@ -54,3 +54,22 @@ pub static API_TEST_LATENCY: Lazy<HistogramVec> = Lazy::new(|| {
 pub fn test_latency(test_name: &str, network_name: &str, run_id: &str, result: &str) -> Histogram {
     API_TEST_LATENCY.with_label_values(&[test_name, network_name, run_id, result])
 }
+
+pub static API_TEST_STEP_LATENCY: Lazy<HistogramVec> = Lazy::new(|| {
+    register_histogram_vec!(
+        "api_test_step_latency",
+        "Time it takes to complete a user flow step",
+        &["test_name", "step_name", "network_name", "run_id", "result"],
+    )
+    .unwrap()
+});
+
+pub fn test_step_latency(
+    test_name: &str,
+    step_name: &str,
+    network_name: &str,
+    run_id: &str,
+    result: &str,
+) -> Histogram {
+    API_TEST_STEP_LATENCY.with_label_values(&[test_name, step_name, network_name, run_id, result])
+}

crates/aptos-api-tester/src/fail_message.rs

@@ -1,27 +1,27 @@
 // Copyright © Aptos Foundation
 
-pub static FAIL_WRONG_ACCOUNT_DATA: &str = "wrong account data";
-pub static FAIL_WRONG_BALANCE: &str = "wrong balance";
-pub static FAIL_WRONG_BALANCE_AT_VERSION: &str = "wrong balance at version";
-pub static FAIL_WRONG_COLLECTION_DATA: &str = "wrong collection data";
-pub static FAIL_WRONG_MESSAGE: &str = "wrong message";
-pub static FAIL_WRONG_MODULE: &str = "wrong module";
-pub static FAIL_WRONG_TOKEN_BALANCE: &str = "wrong token balance";
-pub static FAIL_WRONG_TOKEN_DATA: &str = "wrong token data";
-pub static ERROR_COULD_NOT_BUILD_PACKAGE: &str = "failed to build package";
-pub static ERROR_COULD_NOT_CHECK: &str = "persistency check never started";
-pub static ERROR_COULD_NOT_CREATE_ACCOUNT: &str = "failed to create account";
-pub static ERROR_COULD_NOT_CREATE_TRANSACTION: &str = "failed to create transaction";
-pub static ERROR_COULD_NOT_FINISH_TRANSACTION: &str = "failed to finish transaction";
-pub static ERROR_COULD_NOT_FUND_ACCOUNT: &str = "failed to fund account";
-pub static ERROR_COULD_NOT_SERIALIZE: &str = "failed to serialize";
-pub static ERROR_NO_ACCOUNT_DATA: &str = "can't find account data";
-pub static ERROR_NO_BALANCE: &str = "can't find account balance";
-pub static ERROR_NO_BYTECODE: &str = "can't find bytecode";
-pub static ERROR_NO_COLLECTION_DATA: &str = "can't find collection data";
-pub static ERROR_NO_MESSAGE: &str = "can't find message";
-pub static ERROR_NO_METADATA: &str = "can't find metadata";
-pub static ERROR_NO_MODULE: &str = "can't find module";
-pub static ERROR_NO_TOKEN_BALANCE: &str = "can't find token balance";
-pub static ERROR_NO_TOKEN_DATA: &str = "can't find token data";
-pub static ERROR_NO_VERSION: &str = "can't find transaction version";
+pub const FAIL_WRONG_ACCOUNT_DATA: &str = "wrong account data";
+pub const FAIL_WRONG_BALANCE: &str = "wrong balance";
+pub const FAIL_WRONG_BALANCE_AT_VERSION: &str = "wrong balance at version";
+pub const FAIL_WRONG_COLLECTION_DATA: &str = "wrong collection data";
+pub const FAIL_WRONG_MESSAGE: &str = "wrong message";
+pub const FAIL_WRONG_MODULE: &str = "wrong module";
+pub const FAIL_WRONG_TOKEN_BALANCE: &str = "wrong token balance";
+pub const FAIL_WRONG_TOKEN_DATA: &str = "wrong token data";
+pub const ERROR_COULD_NOT_BUILD_PACKAGE: &str = "failed to build package";
+pub const ERROR_COULD_NOT_CHECK: &str = "persistency check never started";
+pub const ERROR_COULD_NOT_CREATE_ACCOUNT: &str = "failed to create account";
+pub const ERROR_COULD_NOT_CREATE_TRANSACTION: &str = "failed to create transaction";
+pub const ERROR_COULD_NOT_FINISH_TRANSACTION: &str = "failed to finish transaction";
+pub const ERROR_COULD_NOT_FUND_ACCOUNT: &str = "failed to fund account";
+pub const ERROR_COULD_NOT_SERIALIZE: &str = "failed to serialize";
+pub const ERROR_NO_ACCOUNT_DATA: &str = "can't find account data";
+pub const ERROR_NO_BALANCE: &str = "can't find account balance";
+pub const ERROR_NO_BYTECODE: &str = "can't find bytecode";
+pub const ERROR_NO_COLLECTION_DATA: &str = "can't find collection data";
+pub const ERROR_NO_MESSAGE: &str = "can't find message";
+pub const ERROR_NO_METADATA: &str = "can't find metadata";
+pub const ERROR_NO_MODULE: &str = "can't find module";
+pub const ERROR_NO_TOKEN_BALANCE: &str = "can't find token balance";
+pub const ERROR_NO_TOKEN_DATA: &str = "can't find token data";
+pub const ERROR_NO_VERSION: &str = "can't find transaction version";

crates/aptos-api-tester/src/macros.rs

@@ -0,0 +1,18 @@
+// Copyright © Aptos Foundation
+
+#[macro_export]
+macro_rules! time_fn {
+    ($func:expr, $($arg:expr), *) => {{
+        // start timer
+        let start = tokio::time::Instant::now();
+
+        // call the flow
+        let result = $func($($arg),+).await;
+
+        // end timer
+        let time = (tokio::time::Instant::now() - start).as_micros() as f64;
+
+        // return
+        (result, time)
+    }};
+}

crates/aptos-api-tester/src/main.rs

@@ -3,135 +3,86 @@
 
 #![forbid(unsafe_code)]
 
+mod consts;
 mod counters;
 mod fail_message;
 mod persistent_check;
 mod tests;
 mod utils;
+#[macro_use]
+mod macros;
 
-use crate::{
-    tests::{coin_transfer, new_account, nft_transfer, publish_module},
-    utils::{set_metrics, NetworkName, TestFailure, TestName, TestResult},
-};
+use crate::utils::{NetworkName, TestName};
 use anyhow::Result;
 use aptos_logger::{info, Level, Logger};
 use aptos_push_metrics::MetricsPusher;
+use consts::{NUM_THREADS, STACK_SIZE};
 use futures::future::join_all;
-use std::{
-    future::Future,
-    time::{Instant, SystemTime, UNIX_EPOCH},
-};
+use std::time::{SystemTime, UNIX_EPOCH};
+use tokio::runtime::{Builder, Runtime};
 
-// Processes a test result.
-async fn process_result<Fut: Future<Output = Result<(), TestFailure>>>(
-    test_name: TestName,
-    network_name: NetworkName,
-    run_id: &str,
-    fut: Fut,
-) {
-    // start timer
-    let start = Instant::now();
-
-    // call the flow
-    let result = fut.await;
-
-    // end timer
-    let time = (Instant::now() - start).as_micros() as f64;
-
-    // process the result
-    let output = match result {
-        Ok(_) => TestResult::Success,
-        Err(failure) => TestResult::from(failure),
-    };
-
-    // set metrics and log
-    set_metrics(
-        &output,
-        &test_name.to_string(),
-        &network_name.to_string(),
-        run_id,
-        time,
-    );
-    info!(
-        "{} {} result:{:?} in time:{:?}",
-        network_name.to_string(),
-        test_name.to_string(),
-        output,
-        time,
-    );
-}
-
-async fn test_flows(network_name: NetworkName) -> Result<()> {
+async fn test_flows(runtime: &Runtime, network_name: NetworkName) -> Result<()> {
     let run_id = SystemTime::now()
         .duration_since(UNIX_EPOCH)?
         .as_secs()
         .to_string();
-    info!("testing {} at {}", network_name.to_string(), run_id);
+    info!(
+        "----- STARTING TESTS FOR {} WITH RUN ID {} -----",
+        network_name.to_string(),
+        run_id
+    );
 
-    // Test new account creation and funding
+    // Flow 1: New account
     let test_time = run_id.clone();
-    let handle_newaccount = tokio::spawn(async move {
-        process_result(
-            TestName::NewAccount,
-            network_name,
-            &test_time,
-            new_account::test(network_name),
-        )
-        .await;
+    let handle_newaccount = runtime.spawn(async move {
+        TestName::NewAccount.run(network_name, &test_time).await;
     });
 
-    // Flow 1: Coin transfer
+    // Flow 2: Coin transfer
     let test_time = run_id.clone();
-    let handle_cointransfer = tokio::spawn(async move {
-        process_result(
-            TestName::CoinTransfer,
-            network_name,
-            &test_time,
-            coin_transfer::test(network_name),
-        )
-        .await;
+    let handle_cointransfer = runtime.spawn(async move {
+        TestName::CoinTransfer.run(network_name, &test_time).await;
     });
 
-    // Flow 2: NFT transfer
+    // Flow 3: NFT transfer
     let test_time = run_id.clone();
-    let handle_nfttransfer = tokio::spawn(async move {
-        process_result(
-            TestName::NftTransfer,
-            network_name,
-            &test_time,
-            nft_transfer::test(network_name),
-        )
-        .await;
+    let handle_nfttransfer = runtime.spawn(async move {
+        TestName::NftTransfer.run(network_name, &test_time).await;
     });
 
-    // Flow 3: Publishing module
+    // Flow 4: Publishing module
     let test_time = run_id.clone();
-    process_result(
-        TestName::PublishModule,
-        network_name,
-        &test_time,
-        publish_module::test(network_name),
-    )
-    .await;
+    let handle_publishmodule = runtime.spawn(async move {
+        TestName::PublishModule.run(network_name, &test_time).await;
+    });
 
     join_all(vec![
         handle_newaccount,
         handle_cointransfer,
         handle_nfttransfer,
+        handle_publishmodule,
     ])
     .await;
     Ok(())
 }
 
-#[tokio::main]
-async fn main() -> Result<()> {
+fn main() -> Result<()> {
+    // create runtime
+    let runtime = Builder::new_multi_thread()
+        .worker_threads(*NUM_THREADS)
+        .enable_all()
+        .thread_stack_size(*STACK_SIZE)
+        .build()?;
+
     // log metrics
     Logger::builder().level(Level::Info).build();
     let _mp = MetricsPusher::start_for_local_run("api-tester");
 
-    // test flows
-    let _ = test_flows(NetworkName::Testnet).await;
-    let _ = test_flows(NetworkName::Devnet).await;
+    // run tests
+    runtime.block_on(async {
+        let _ = test_flows(&runtime, NetworkName::Testnet).await;
+        let _ = test_flows(&runtime, NetworkName::Devnet).await;
+    });
 
     Ok(())
 }