diff --git a/.gitignore b/.gitignore index 9b5d0361..52478627 100644 --- a/.gitignore +++ b/.gitignore @@ -1,5 +1,6 @@ debug/ target/ +**.pyc .env .envrc diff --git a/Cargo.lock b/Cargo.lock index 3ba4c3ac..724fa19c 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -655,7 +655,7 @@ dependencies = [ [[package]] name = "blockifier" version = "0.0.0" -source = "git+https://github.com/lambdaclass/sequencer.git?rev=bfc5b6b5475d359b8fc910516e026d972be5d02f#bfc5b6b5475d359b8fc910516e026d972be5d02f" +source = "git+https://github.com/lambdaclass/sequencer.git?rev=2ad9ecad71bd71304b80c36992f41568c82313ad#2ad9ecad71bd71304b80c36992f41568c82313ad" dependencies = [ "anyhow", "ark-ec", @@ -699,7 +699,7 @@ dependencies = [ [[package]] name = "blockifier_reexecution" version = "0.0.0" -source = "git+https://github.com/lambdaclass/sequencer.git?rev=bfc5b6b5475d359b8fc910516e026d972be5d02f#bfc5b6b5475d359b8fc910516e026d972be5d02f" +source = "git+https://github.com/lambdaclass/sequencer.git?rev=2ad9ecad71bd71304b80c36992f41568c82313ad#2ad9ecad71bd71304b80c36992f41568c82313ad" dependencies = [ "assert_matches", "blockifier", @@ -1574,9 +1574,9 @@ dependencies = [ [[package]] name = "clap" -version = "4.5.22" +version = "4.5.23" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "69371e34337c4c984bbe322360c2547210bf632eb2814bbe78a6e87a2935bd2b" +checksum = "3135e7ec2ef7b10c6ed8950f0f792ed96ee093fa088608f1c76e569722700c84" dependencies = [ "clap_builder", "clap_derive", @@ -1584,9 +1584,9 @@ dependencies = [ [[package]] name = "clap_builder" -version = "4.5.22" +version = "4.5.23" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "6e24c1b4099818523236a8ca881d2b45db98dadfb4625cf6608c12069fcbbde1" +checksum = "30582fc632330df2bd26877bde0c1f4470d57c582bbc070376afcd04d8cb4838" dependencies = [ "anstream", "anstyle", @@ -1608,9 +1608,9 @@ dependencies = [ [[package]] name = "clap_lex" -version = "0.7.3" +version = "0.7.4" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "afb84c814227b90d6895e01398aee0d8033c00e7466aca416fb6a8e0eb19d8a7" +checksum = "f46ad14479a25103f283c0f10005961cf086d8dc42205bb44c46ac563475dca6" [[package]] name = "coins-bip32" @@ -3770,7 +3770,7 @@ checksum = "b248f5224d1d606005e02c97f5aa4e88eeb230488bcc03bc9ca4d7991399f2b5" [[package]] name = "infra_utils" version = "0.0.0" -source = "git+https://github.com/lambdaclass/sequencer.git?rev=bfc5b6b5475d359b8fc910516e026d972be5d02f#bfc5b6b5475d359b8fc910516e026d972be5d02f" +source = "git+https://github.com/lambdaclass/sequencer.git?rev=2ad9ecad71bd71304b80c36992f41568c82313ad#2ad9ecad71bd71304b80c36992f41568c82313ad" dependencies = [ "tokio", ] @@ -4539,7 +4539,7 @@ dependencies = [ [[package]] name = "mempool_test_utils" version = "0.0.0" -source = "git+https://github.com/lambdaclass/sequencer.git?rev=bfc5b6b5475d359b8fc910516e026d972be5d02f#bfc5b6b5475d359b8fc910516e026d972be5d02f" +source = "git+https://github.com/lambdaclass/sequencer.git?rev=2ad9ecad71bd71304b80c36992f41568c82313ad#2ad9ecad71bd71304b80c36992f41568c82313ad" dependencies = [ "assert_matches", "blockifier", @@ -5003,7 +5003,7 @@ dependencies = [ [[package]] name = "papyrus_common" version = "0.0.0" -source = "git+https://github.com/lambdaclass/sequencer.git?rev=bfc5b6b5475d359b8fc910516e026d972be5d02f#bfc5b6b5475d359b8fc910516e026d972be5d02f" +source = "git+https://github.com/lambdaclass/sequencer.git?rev=2ad9ecad71bd71304b80c36992f41568c82313ad#2ad9ecad71bd71304b80c36992f41568c82313ad" dependencies = [ "base64 0.13.1", "cairo-lang-starknet-classes", @@ -5022,7 +5022,7 @@ dependencies = [ [[package]] name = "papyrus_config" version = "0.0.0" -source = "git+https://github.com/lambdaclass/sequencer.git?rev=bfc5b6b5475d359b8fc910516e026d972be5d02f#bfc5b6b5475d359b8fc910516e026d972be5d02f" +source = "git+https://github.com/lambdaclass/sequencer.git?rev=2ad9ecad71bd71304b80c36992f41568c82313ad#2ad9ecad71bd71304b80c36992f41568c82313ad" dependencies = [ "clap", "infra_utils", @@ -5037,7 +5037,7 @@ dependencies = [ [[package]] name = "papyrus_execution" version = "0.0.0" -source = "git+https://github.com/lambdaclass/sequencer.git?rev=bfc5b6b5475d359b8fc910516e026d972be5d02f#bfc5b6b5475d359b8fc910516e026d972be5d02f" +source = "git+https://github.com/lambdaclass/sequencer.git?rev=2ad9ecad71bd71304b80c36992f41568c82313ad#2ad9ecad71bd71304b80c36992f41568c82313ad" dependencies = [ "anyhow", "blockifier", @@ -5060,7 +5060,7 @@ dependencies = [ [[package]] name = "papyrus_network_types" version = "0.0.0" -source = "git+https://github.com/lambdaclass/sequencer.git?rev=bfc5b6b5475d359b8fc910516e026d972be5d02f#bfc5b6b5475d359b8fc910516e026d972be5d02f" +source = "git+https://github.com/lambdaclass/sequencer.git?rev=2ad9ecad71bd71304b80c36992f41568c82313ad#2ad9ecad71bd71304b80c36992f41568c82313ad" dependencies = [ "libp2p", "serde", @@ -5069,7 +5069,7 @@ dependencies = [ [[package]] name = "papyrus_proc_macros" version = "0.0.0" -source = "git+https://github.com/lambdaclass/sequencer.git?rev=bfc5b6b5475d359b8fc910516e026d972be5d02f#bfc5b6b5475d359b8fc910516e026d972be5d02f" +source = "git+https://github.com/lambdaclass/sequencer.git?rev=2ad9ecad71bd71304b80c36992f41568c82313ad#2ad9ecad71bd71304b80c36992f41568c82313ad" dependencies = [ "quote", "syn 2.0.90", @@ -5079,7 +5079,7 @@ dependencies = [ [[package]] name = "papyrus_rpc" version = "0.0.0" -source = "git+https://github.com/lambdaclass/sequencer.git?rev=bfc5b6b5475d359b8fc910516e026d972be5d02f#bfc5b6b5475d359b8fc910516e026d972be5d02f" +source = "git+https://github.com/lambdaclass/sequencer.git?rev=2ad9ecad71bd71304b80c36992f41568c82313ad#2ad9ecad71bd71304b80c36992f41568c82313ad" dependencies = [ "anyhow", "async-trait", @@ -5113,7 +5113,7 @@ dependencies = [ [[package]] name = "papyrus_storage" version = "0.0.0" -source = "git+https://github.com/lambdaclass/sequencer.git?rev=bfc5b6b5475d359b8fc910516e026d972be5d02f#bfc5b6b5475d359b8fc910516e026d972be5d02f" +source = "git+https://github.com/lambdaclass/sequencer.git?rev=2ad9ecad71bd71304b80c36992f41568c82313ad#2ad9ecad71bd71304b80c36992f41568c82313ad" dependencies = [ "byteorder", "cairo-lang-casm", @@ -6950,7 +6950,7 @@ dependencies = [ [[package]] name = "starknet_api" version = "0.0.0" -source = "git+https://github.com/lambdaclass/sequencer.git?rev=bfc5b6b5475d359b8fc910516e026d972be5d02f#bfc5b6b5475d359b8fc910516e026d972be5d02f" +source = "git+https://github.com/lambdaclass/sequencer.git?rev=2ad9ecad71bd71304b80c36992f41568c82313ad#2ad9ecad71bd71304b80c36992f41568c82313ad" dependencies = [ "bitvec", "cairo-lang-runner", @@ -6976,7 +6976,7 @@ dependencies = [ [[package]] name = "starknet_client" version = "0.0.0" -source = "git+https://github.com/lambdaclass/sequencer.git?rev=bfc5b6b5475d359b8fc910516e026d972be5d02f#bfc5b6b5475d359b8fc910516e026d972be5d02f" +source = "git+https://github.com/lambdaclass/sequencer.git?rev=2ad9ecad71bd71304b80c36992f41568c82313ad#2ad9ecad71bd71304b80c36992f41568c82313ad" dependencies = [ "async-trait", "cairo-lang-starknet-classes", @@ -7003,7 +7003,7 @@ dependencies = [ [[package]] name = "starknet_gateway" version = "0.0.0" -source = "git+https://github.com/lambdaclass/sequencer.git?rev=bfc5b6b5475d359b8fc910516e026d972be5d02f#bfc5b6b5475d359b8fc910516e026d972be5d02f" +source = "git+https://github.com/lambdaclass/sequencer.git?rev=2ad9ecad71bd71304b80c36992f41568c82313ad#2ad9ecad71bd71304b80c36992f41568c82313ad" dependencies = [ "async-trait", "axum", @@ -7031,7 +7031,7 @@ dependencies = [ [[package]] name = "starknet_gateway_types" version = "0.0.0" -source = "git+https://github.com/lambdaclass/sequencer.git?rev=bfc5b6b5475d359b8fc910516e026d972be5d02f#bfc5b6b5475d359b8fc910516e026d972be5d02f" +source = "git+https://github.com/lambdaclass/sequencer.git?rev=2ad9ecad71bd71304b80c36992f41568c82313ad#2ad9ecad71bd71304b80c36992f41568c82313ad" dependencies = [ "async-trait", "axum", @@ -7050,7 +7050,7 @@ dependencies = [ [[package]] name = "starknet_mempool_types" version = "0.0.0" -source = "git+https://github.com/lambdaclass/sequencer.git?rev=bfc5b6b5475d359b8fc910516e026d972be5d02f#bfc5b6b5475d359b8fc910516e026d972be5d02f" +source = "git+https://github.com/lambdaclass/sequencer.git?rev=2ad9ecad71bd71304b80c36992f41568c82313ad#2ad9ecad71bd71304b80c36992f41568c82313ad" dependencies = [ "async-trait", "papyrus_network_types", @@ -7064,7 +7064,7 @@ dependencies = [ [[package]] name = "starknet_sequencer_infra" version = "0.0.0" -source = "git+https://github.com/lambdaclass/sequencer.git?rev=bfc5b6b5475d359b8fc910516e026d972be5d02f#bfc5b6b5475d359b8fc910516e026d972be5d02f" +source = "git+https://github.com/lambdaclass/sequencer.git?rev=2ad9ecad71bd71304b80c36992f41568c82313ad#2ad9ecad71bd71304b80c36992f41568c82313ad" dependencies = [ "async-trait", "bincode 1.3.3", @@ -7082,7 +7082,7 @@ dependencies = [ [[package]] name = "starknet_sierra_compile" version = "0.0.0" -source = "git+https://github.com/lambdaclass/sequencer.git?rev=bfc5b6b5475d359b8fc910516e026d972be5d02f#bfc5b6b5475d359b8fc910516e026d972be5d02f" +source = "git+https://github.com/lambdaclass/sequencer.git?rev=2ad9ecad71bd71304b80c36992f41568c82313ad#2ad9ecad71bd71304b80c36992f41568c82313ad" dependencies = [ "cairo-lang-sierra", "cairo-lang-starknet-classes", @@ -7523,9 +7523,9 @@ dependencies = [ [[package]] name = "tokio-stream" -version = "0.1.16" +version = "0.1.17" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "4f4e6ce100d0eb49a2734f8c0812bcd324cf357d21810932c5df6b96ef2b86f1" +checksum = "eca58d7bba4a75707817a2c44174253f9236b2d5fbd055602e9d5c07c139a047" dependencies = [ "futures-core", "pin-project-lite", diff --git a/Cargo.toml b/Cargo.toml index a6f7403c..95485b76 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -14,7 +14,7 @@ serde_with = "3.11.0" serde = "1.0.197" cairo-native = "0.2.4" # Sequencer Dependencies -starknet_api = { git = "https://github.com/lambdaclass/sequencer.git", rev = "bfc5b6b5475d359b8fc910516e026d972be5d02f" } # replay -blockifier = { git = "https://github.com/lambdaclass/sequencer.git", rev = "bfc5b6b5475d359b8fc910516e026d972be5d02f", features = ["cairo_native"] } # replay -starknet_gateway = { git = "https://github.com/lambdaclass/sequencer.git", rev = "bfc5b6b5475d359b8fc910516e026d972be5d02f" } # replay -blockifier_reexecution = { git = "https://github.com/lambdaclass/sequencer.git", rev = "bfc5b6b5475d359b8fc910516e026d972be5d02f" } # replay +starknet_api = { git = "https://github.com/lambdaclass/sequencer.git", rev = "2ad9ecad71bd71304b80c36992f41568c82313ad" } # replay +blockifier = { git = "https://github.com/lambdaclass/sequencer.git", rev = "2ad9ecad71bd71304b80c36992f41568c82313ad", features = ["cairo_native"] } # replay +starknet_gateway = { git = "https://github.com/lambdaclass/sequencer.git", rev = "2ad9ecad71bd71304b80c36992f41568c82313ad" } # replay +blockifier_reexecution = { git = "https://github.com/lambdaclass/sequencer.git", rev = "2ad9ecad71bd71304b80c36992f41568c82313ad" } # replay diff --git a/README.md b/README.md index 6215aafa..32065b9d 100644 --- a/README.md +++ b/README.md @@ -126,17 +126,25 @@ In the `plotting` directory, you can find python scripts to plot relevant inform Make sure to erase the `compiled_programs` directory, then run: ```bash -cargo run --features benchmark,structured_logging bench-block-range 724000 724000 mainnet 1 | tee native-logs -cargo run --features benchmark,structured_logging,only_cairo_vm bench-block-range 724000 724000 mainnet 1 | tee vm-logs +./scripts/benchmark_tx.sh <tx> <net> <block> <laps> +``` + +This generates four files: +- `{native,vm}-data-$tx-$net.json`: Contains the execution time of each contract call +- `{native,vm}-logs-$tx-$net.json`: Contains the output of running the benchmark + +If you want to benchmark a full block, you could run: +```bash +./scripts/benchmark_block.sh <block-start> <block-end> <net> <laps> ``` Once you have done this, you can use the plotting scripts: +- `python ./plotting/plot_execution_time.py native-data vm-data`: Plots the execution time of Native vs VM, by contract class. - `python ./plotting/plot_compilation_memory.py native-logs`: Size of the compiled native libraries, by contract class. - `python ./plotting/plot_compilation_memory_corr.py native-logs vm-logs`: Size of the compiled native libraries, by the associated Casm contract size. - `python ./plotting/plot_compilation_memory_trend.py native-logs vm-logs`: Size of the compiled native and casm contracts, by the sierra contract size. - `python ./plotting/plot_compilation_time.py native-logs`: Native compilation time, by contract class - `python ./plotting/plot_compilation_time_trend.py native-logs vm-logs`: Native and Casm compilation time, by the sierra contract size. -- `python ./plotting/plot_execution_time.py native-logs vm-logs`: Plots the execution time of Native vs VM, by contract class. - `python ./plotting/plot_compilation_time_finer.py native-logs`: Native compilation time, with fine-grained stage separation, by contract class. diff --git a/plotting/plot_execution_time.py b/plotting/plot_execution_time.py index 14cd90f4..f8fecda6 100644 --- a/plotting/plot_execution_time.py +++ b/plotting/plot_execution_time.py @@ -1,55 +1,155 @@ from argparse import ArgumentParser -argument_parser = ArgumentParser('Stress Test Plotter') -argument_parser.add_argument("native_logs_path") -argument_parser.add_argument("vm_logs_path") -arguments = argument_parser.parse_args() - import matplotlib.pyplot as plt import pandas as pd import seaborn as sns +import io +from utils import format_hash + +parser = ArgumentParser("Stress Test Plotter") +parser.add_argument("native_data") +parser.add_argument("vm_data") +parser.add_argument("-s", "--speedup", action="store_true") +args = parser.parse_args() + +pd.set_option("display.max_columns", None) +pd.set_option("display.max_rows", None) + -datasetNative = pd.read_json(arguments.native_logs_path, lines=True, typ="series") -datasetVM = pd.read_json(arguments.vm_logs_path, lines=True, typ="series") +def load_dataset(path, f): + return pd.read_json(path).apply(f, axis=1).dropna().apply(pd.Series) -def canonicalize_execution_time_by_contract_class(event): - # skip caching logs - if find_span(event, "caching block range") != None: - return None - # keep contract execution finished logs - if "contract execution finished" not in event["fields"]["message"]: - return None +def process_row(row): + class_hash = row.class_hash + selector = row.selector + time = row.time["nanos"] + row.time["secs"] * 10e9 return { - "class hash": event["span"]["class_hash"], - "time": float(event["fields"]["time"]), + "class_hash": class_hash, + "selector": selector, + "time": time, } -def find_span(event, name): - for span in event["spans"]: - if name in span["name"]: - return span - return None -def format_hash(class_hash): - return f"0x{class_hash[:6]}..." +dataNative = load_dataset(args.native_data, process_row) +dataNative["executor"] = "native" +dataVM = load_dataset(args.vm_data, process_row) +dataVM["executor"] = "vm" +data = pd.concat([dataNative, dataVM]) + +# GROUP BY SELECTOR + +# calculate mean by class hash +data_by_selector = ( + data.groupby(["executor", "class_hash", "selector"]) + .agg( + total_time=("time", "sum"), + mean_time=("time", "mean"), + samples=("time", "size"), + ) + .unstack("executor") +) +data_by_selector.columns = data_by_selector.columns.map("_".join) + +if (data_by_selector["samples_native"] != data_by_selector["samples_vm"]).any(): + raise Exception("Native and VM should have the same number of samples") + +# calculate speedup +data_by_selector["speedup"] = ( + data_by_selector["total_time_vm"] / data_by_selector["total_time_native"] +) +total_native = data_by_selector["total_time_native"].sum() / 10e9 +total_vm = data_by_selector["total_time_vm"].sum() / 10e9 +print(f"Total Native: {total_native} seconds") +print(f"Total VM: {total_vm} seconds") +print("Total Speedup:", total_vm / total_native) -datasetNative = datasetNative.apply(canonicalize_execution_time_by_contract_class).dropna().apply(pd.Series) -datasetVM = datasetVM.apply(canonicalize_execution_time_by_contract_class).dropna().apply(pd.Series) +# sort by decreasing time +data_by_selector.sort_values(["total_time_vm"], ascending=[False], inplace=True) # type: ignore -datasetNative = datasetNative.groupby("class hash").mean() -datasetVM = datasetVM.groupby("class hash").mean() +s = io.StringIO() +data_by_selector.to_csv(s) +print(s.getvalue()) -figure, ax = plt.subplots() +# GROUP BY CLASS -sns.set_color_codes("bright") +data_by_class = ( + data.groupby(["executor", "class_hash"]) + .agg( + total_time=("time", "sum"), + mean_time=("time", "mean"), + samples=("time", "size"), + ) + .unstack("executor") +) +data_by_class.columns = data_by_class.columns.map("_".join) +data_by_class["speedup"] = ( + data_by_class["total_time_vm"] / data_by_class["total_time_native"] +) +data_by_class.sort_values(["total_time_vm"], ascending=[False], inplace=True) # type: ignore +data_by_class = data_by_class.nlargest(50, "total_time_vm") # type: ignore -sns.barplot(ax=ax, y="class hash", x="time", data=datasetVM, formatter=format_hash, label="VM Execution Time", color="r", alpha = 0.75) # type: ignore -sns.barplot(ax=ax, y="class hash", x="time", data=datasetNative, formatter=format_hash, label="Native Execution Time", color="b", alpha = 0.75) # type: ignore +# ====================== +# PLOTTING +# ====================== -ax.set_xlabel("Mean Time (ms)") +figure, axes = plt.subplots(1, 2) + +ax = axes[0] + +sns.barplot( + ax=ax, + y="class_hash", + x="total_time_vm", + data=data_by_class, # type: ignore + formatter=format_hash, + label="VM Execution Time", + color="r", + alpha=0.75, +) # type: ignore +sns.barplot( + ax=ax, + y="class_hash", + x="total_time_native", + data=data_by_class, # type: ignore + formatter=format_hash, + label="Native Execution Time", + color="b", + alpha=0.75, +) # type: ignore + +ax.set_xlabel("Total Time (ns)") +ax.set_ylabel("Class Hash") +ax.set_title("Total time by Contract Class") +ax.set_xscale("log", base=2) + +ax = axes[1] + +sns.barplot( + ax=ax, + y="class_hash", + x="speedup", + data=data_by_class, # type: ignore + formatter=format_hash, + label="Execution Speedup", + color="b", + alpha=0.75, +) # type: ignore + +ax.set_xlabel("Speedup") ax.set_ylabel("Class Hash") -ax.set_title("Native vs. VM by Contract Class") +ax.set_title("Speedup by Contract Class") + +if args.speedup: + fig, ax = plt.subplots() + sns.violinplot( + ax=ax, + x="speedup", + data=data_by_class, # type: ignore + cut=0, + ) + ax.set_xlabel("Speedup") + ax.set_title("Speedup Distribution") plt.show() diff --git a/plotting/utils.py b/plotting/utils.py new file mode 100644 index 00000000..f62ccdb0 --- /dev/null +++ b/plotting/utils.py @@ -0,0 +1,2 @@ +def format_hash(class_hash): + return f"{class_hash[:6]}..." diff --git a/replay/Cargo.toml b/replay/Cargo.toml index cb98eb94..35d3ee2b 100644 --- a/replay/Cargo.toml +++ b/replay/Cargo.toml @@ -4,10 +4,11 @@ version = "0.1.0" edition = "2021" [features] -benchmark = [] +benchmark = ["dep:serde", "dep:serde_json", "dep:serde_with"] # The only_cairo_vm feature is designed to avoid executing transitions with cairo_native and instead use cairo_vm exclusively only_cairo_vm = ["rpc-state-reader/only_casm"] structured_logging = [] +profiling = [] state_dump = ["dep:serde", "dep:serde_json", "dep:serde_with", "dep:starknet-types-core"] [dependencies] diff --git a/replay/src/benchmark.rs b/replay/src/benchmark.rs index 4ea93ae9..4537be13 100644 --- a/replay/src/benchmark.rs +++ b/replay/src/benchmark.rs @@ -1,17 +1,23 @@ -use std::time::Instant; +use std::{error::Error, fs::File, path::Path, time::Duration}; use blockifier::{ context::BlockContext, - execution::contract_class::RunnableCompiledClass, + execution::{call_info::CallInfo, contract_class::RunnableCompiledClass}, state::{cached_state::CachedState, state_api::StateReader}, + transaction::objects::TransactionExecutionInfo, }; use rpc_state_reader::{ execution::{execute_tx_with_blockifier, fetch_block_context}, objects::TransactionWithHash, reader::{RpcChain, RpcStateReader}, }; -use starknet_api::{block::BlockNumber, hash::StarkHash, transaction::TransactionHash}; -use tracing::{error, info, info_span}; +use serde::Serialize; +use starknet_api::{ + block::BlockNumber, + core::{ClassHash, EntryPointSelector}, + hash::StarkHash, + transaction::TransactionHash, +}; pub type BlockCachedData = ( CachedState<OptionalStateReader<RpcStateReader>>, @@ -58,15 +64,13 @@ pub fn fetch_block_range_data( /// Executes the given block range, discarding any state changes applied to it /// /// Can also be used to fill up the cache -pub fn execute_block_range(block_range_data: &mut Vec<BlockCachedData>) { +pub fn execute_block_range( + block_range_data: &mut Vec<BlockCachedData>, +) -> Vec<TransactionExecutionInfo> { + let mut executions = Vec::new(); + for (state, block_context, transactions) in block_range_data { // For each block - let _block_span = info_span!( - "block execution", - block_number = block_context.block_info().block_number.0, - ) - .entered(); - info!("starting block execution"); // The transactional state is used to execute a transaction while discarding state changes applied to it. let mut transactional_state = CachedState::create_transactional(state); @@ -77,34 +81,85 @@ pub fn execute_block_range(block_range_data: &mut Vec<BlockCachedData>) { } in transactions { // Execute each transaction - let _tx_span = info_span!("tx execution",).entered(); - - info!("tx execution started"); - - let pre_execution_instant = Instant::now(); - let result = execute_tx_with_blockifier( + let execution = execute_tx_with_blockifier( &mut transactional_state, block_context.clone(), transaction.to_owned(), transaction_hash.to_owned(), ); - let execution_time = pre_execution_instant.elapsed(); - - match result { - Ok(info) => { - info!( - time = ?execution_time, - succeeded = info.revert_error.is_none(), - "tx execution finished" - ) - } - Err(_) => error!( - time = ?execution_time, - "tx execution failed" - ), - } + let Ok(execution) = execution else { continue }; + + executions.push(execution); } } + + executions +} + +#[derive(Serialize)] +struct ClassExecutionInfo { + class_hash: ClassHash, + selector: EntryPointSelector, + time: Duration, +} + +pub fn save_executions( + path: &Path, + executions: Vec<TransactionExecutionInfo>, +) -> Result<(), Box<dyn Error>> { + let classes = executions + .into_iter() + .flat_map(|execution| { + let mut classes = Vec::new(); + + if let Some(call) = execution.validate_call_info { + classes.append(&mut get_class_executions(call)); + } + if let Some(call) = execution.execute_call_info { + classes.append(&mut get_class_executions(call)); + } + if let Some(call) = execution.fee_transfer_call_info { + classes.append(&mut get_class_executions(call)); + } + classes + }) + .collect::<Vec<_>>(); + + let file = File::create(path)?; + serde_json::to_writer_pretty(file, &classes)?; + + Ok(()) +} + +fn get_class_executions(call: CallInfo) -> Vec<ClassExecutionInfo> { + // class hash can initially be None, but it is always added before execution + let class_hash = call.call.class_hash.unwrap(); + + let mut inner_time = Duration::ZERO; + + let mut classes = call + .inner_calls + .into_iter() + .flat_map(|call| { + inner_time += call.time; + get_class_executions(call) + }) + .collect::<Vec<_>>(); + + if call.time.is_zero() { + panic!("contract time should never be zero, there is a bug somewhere") + } + let time = call.time - inner_time; + + let top_class = ClassExecutionInfo { + class_hash, + selector: call.call.entry_point_selector, + time, + }; + + classes.push(top_class); + + classes } pub fn fetch_transaction_data(tx: &str, block: BlockNumber, chain: RpcChain) -> BlockCachedData { diff --git a/replay/src/main.rs b/replay/src/main.rs index 8f0934ec..ac694977 100644 --- a/replay/src/main.rs +++ b/replay/src/main.rs @@ -1,6 +1,3 @@ -use std::thread; -use std::time::Duration; - use blockifier::state::cached_state::CachedState; use blockifier::state::errors::StateError; use blockifier::transaction::objects::{RevertError, TransactionExecutionInfo}; @@ -17,7 +14,12 @@ use tracing_subscriber::{util::SubscriberInitExt, EnvFilter}; #[cfg(feature = "benchmark")] use { - crate::benchmark::{execute_block_range, fetch_block_range_data, fetch_transaction_data}, + crate::benchmark::{ + execute_block_range, fetch_block_range_data, fetch_transaction_data, save_executions, + }, + std::path::PathBuf, + std::thread, + std::time::Duration, std::{ops::Div, time::Instant}, }; @@ -68,6 +70,8 @@ Caches all rpc data before the benchmark runs to provide accurate results" block_end: u64, chain: String, number_of_runs: usize, + #[arg(short, long, default_value=PathBuf::from("data").into_os_string())] + output: PathBuf, }, #[cfg(feature = "benchmark")] #[clap(about = "Measures the time it takes to run a single transaction. @@ -78,6 +82,8 @@ Caches all rpc data before the benchmark runs to provide accurate results" chain: String, block: u64, number_of_runs: usize, + #[arg(short, long, default_value=PathBuf::from("data").into_os_string())] + output: PathBuf, }, } @@ -150,6 +156,7 @@ fn main() { block_end, chain, number_of_runs, + output, } => { let block_start = BlockNumber(block_start); let block_end = BlockNumber(block_end); @@ -174,15 +181,27 @@ fn main() { block_range_data }; + // We pause the main thread to differentiate + // caching from benchmarking from within a profiler + #[cfg(feature = "profiling")] + thread::sleep(Duration::from_secs(1)); + { let _benchmark_span = info_span!("benchmarking block range").entered(); - let before_execution = Instant::now(); + let mut executions = Vec::new(); + + info!("executing block range"); + let before_execution = Instant::now(); for _ in 0..number_of_runs { - execute_block_range(&mut block_range_data); + executions.push(execute_block_range(&mut block_range_data)); } - let execution_time = before_execution.elapsed(); + + info!("saving execution info"); + let execution = executions.into_iter().flatten().collect::<Vec<_>>(); + save_executions(&output, execution).expect("failed to save execution info"); + let total_run_time = execution_time.as_secs_f64(); let average_run_time = total_run_time.div(number_of_runs as f64); info!( @@ -201,6 +220,7 @@ fn main() { block, chain, number_of_runs, + output, } => { let chain = parse_network(&chain); let block = BlockNumber(block); @@ -229,17 +249,25 @@ fn main() { // We pause the main thread to differentiate // caching from benchmarking from within a profiler + #[cfg(feature = "profiling")] thread::sleep(Duration::from_secs(1)); { let _benchmark_span = info_span!("benchmarking transaction").entered(); - let before_execution = Instant::now(); + let mut executions = Vec::new(); + + info!("executing block range"); + let before_execution = Instant::now(); for _ in 0..number_of_runs { - execute_block_range(&mut block_range_data); + executions.push(execute_block_range(&mut block_range_data)); } - let execution_time = before_execution.elapsed(); + + info!("saving execution info"); + let execution = executions.into_iter().flatten().collect::<Vec<_>>(); + save_executions(&output, execution).expect("failed to save execution info"); + let total_run_time = execution_time.as_secs_f64(); let average_run_time = total_run_time.div(number_of_runs as f64); info!( diff --git a/rpc-state-reader/src/execution.rs b/rpc-state-reader/src/execution.rs index 85f504ff..fd2e464f 100644 --- a/rpc-state-reader/src/execution.rs +++ b/rpc-state-reader/src/execution.rs @@ -268,7 +268,7 @@ pub fn execute_tx_with_blockifier( _ => unimplemented!(), }; - account_transaction.execute(state, &context, true, true) + account_transaction.execute(state, &context, false, true) } fn parse_to_rpc_chain(network: &str) -> RpcChain { diff --git a/scripts/benchmark_block.sh b/scripts/benchmark_block.sh index c9fc50fb..712e8a81 100755 --- a/scripts/benchmark_block.sh +++ b/scripts/benchmark_block.sh @@ -21,20 +21,24 @@ END=$2 NET=$3 LAPS=$4 -output="block-$START-$END-$NET.jsonl" -native_output="native-$output" -vm_output="vm-$output" +log_output="logs-$START-$END-$NET.jsonl" +native_log_output="native-$log_output" +vm_log_output="vm-$log_output" + +data_output="data-$START-$END-$NET.json" +native_data_output="native-$data_output" +vm_data_output="vm-$data_output" echo "Executing with Native" -cargo run --release --features benchmark,structured_logging bench-block-range "$START" "$END" "$NET" "$LAPS" > "$native_output" +cargo run --release --features benchmark,structured_logging bench-block-range "$START" "$END" "$NET" "$LAPS" -o "$native_data_output" > "$native_log_output" -native_time=$(tail -n1 "$native_output" | jq .fields.average_run_time) +native_time=$(tail -n1 "$native_log_output" | jq .fields.average_run_time) echo "Average Native time: $native_time" echo "Executing with VM" -cargo run --release --features benchmark,structured_logging,only_cairo_vm bench-block-range "$START" "$END" "$NET" "$LAPS" > "$vm_output" +cargo run --release --features benchmark,structured_logging,only_cairo_vm bench-block-range "$START" "$END" "$NET" "$LAPS" -o "$vm_data_output" > "$vm_log_output" -vm_time=$(tail -n1 "$vm_output" | jq .fields.average_run_time) +vm_time=$(tail -n1 "$vm_log_output" | jq .fields.average_run_time) echo "Average VM time: $vm_time" speedup=$(bc -l <<< "$vm_time/$native_time") diff --git a/scripts/benchmark_tx.sh b/scripts/benchmark_tx.sh index 1ba22c10..72d62ae5 100755 --- a/scripts/benchmark_tx.sh +++ b/scripts/benchmark_tx.sh @@ -20,20 +20,24 @@ NET=$2 BLOCK=$3 LAPS=$4 -output="$TX-$NET.jsonl" -native_output="native-$output" -vm_output="vm-$output" +log_output="logs-$TX-$NET.jsonl" +native_log_output="native-$log_output" +vm_log_output="vm-$log_output" + +data_output="data-$TX-$NET.json" +native_data_output="native-$data_output" +vm_data_output="vm-$data_output" echo "Executing with Native" -cargo run --release --features benchmark,structured_logging bench-tx "$TX" "$NET" "$BLOCK" "$LAPS" > "$native_output" +cargo run --release --features benchmark,structured_logging bench-tx "$TX" "$NET" "$BLOCK" "$LAPS" -o "$native_data_output" > "$native_log_output" -native_time=$(tail -n1 "$native_output" | jq .fields.average_run_time) +native_time=$(tail -n1 "$native_log_output" | jq .fields.average_run_time) echo "Average Native time: $native_time" echo "Executing with VM" -cargo run --release --features benchmark,structured_logging,only_cairo_vm bench-tx "$TX" "$NET" "$BLOCK" "$LAPS" > "$vm_output" +cargo run --release --features benchmark,structured_logging,only_cairo_vm bench-tx "$TX" "$NET" "$BLOCK" "$LAPS" -o "$vm_data_output" > "$vm_log_output" -vm_time=$(tail -n1 "$vm_output" | jq .fields.average_run_time) +vm_time=$(tail -n1 "$vm_log_output" | jq .fields.average_run_time) echo "Average VM time: $vm_time" speedup=$(bc -l <<< "$vm_time/$native_time")