[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.

.dockerignore

@@ -19,10 +19,10 @@
 !**/*.mrb
 !**/*.errmap
 !config/src/config/test_data
-!aptos-move/
 !aptos-move/aptos-release-builder/data/release.yaml
 !aptos-move/aptos-release-builder/data/proposals/*
 !aptos-move/framework/
+!aptos-move/move-examples/hello_blockchain/
 !crates/aptos/src/move_tool/*.bpl
 !crates/aptos-faucet/doc/
 !api/doc/

crates/aptos-api-tester/Cargo.toml

@@ -28,5 +28,7 @@ move-core-types = { workspace = true }
 once_cell = { workspace = true }
 prometheus = { workspace = true }
 rand = { workspace = true }
+serde = { workspace = true }
+serde_json = { workspace = true }
 tokio = { workspace = true }
 url = { workspace = true }

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

@@ -0,0 +1,59 @@
+// Copyright © Aptos Foundation
+
+use once_cell::sync::Lazy;
+use std::{env, time::Duration};
+use url::Url;
+
+// Node and 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
+
+// How long a persistent check runs for.
+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))
+});
+
+// Wait time between tries during a persistent check.
+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
+
+// The number of threads to use for running tests.
+pub static NUM_THREADS: Lazy<usize> = Lazy::new(|| {
+    env::var("NUM_THREADS")
+        .ok()
+        .and_then(|s| s.parse().ok())
+        .unwrap_or(4)
+});
+
+// The size of the stack for each thread.
+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/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,90 @@
 
 #![forbid(unsafe_code)]
 
+mod consts;
 mod counters;
-mod fail_message;
 mod persistent_check;
+mod strings;
 mod tests;
+mod tokenv1_client;
 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::TokenV1Transfer
+            .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
+    // TODO: separate the running of the two networks
+    runtime.block_on(async {
+        let _ = test_flows(&runtime, NetworkName::Testnet).await;
+        let _ = test_flows(&runtime, NetworkName::Devnet).await;
+    });
 
     Ok(())
 }