diff --git a/cli/src/lib.rs b/cli/src/lib.rs index b1f5b11b6c..7535acaf20 100644 --- a/cli/src/lib.rs +++ b/cli/src/lib.rs @@ -152,6 +152,9 @@ pub enum Command { /// Architecture to use when building the program #[clap(value_enum, long, default_value = "sbf")] arch: ProgramArch, + /// Add compute unit logging at key points in the program + #[clap(long)] + log_compute_units: bool, }, /// Expands macros (wrapper around cargo expand) /// @@ -234,6 +237,9 @@ pub enum Command { /// Arguments to pass to the underlying `cargo build-sbf` command. #[clap(required = false, last = true)] cargo_args: Vec, + /// Add compute unit logging at key points in the program + #[clap(long)] + log_compute_units: bool, }, /// Creates a new program. New { @@ -1117,6 +1123,42 @@ fn get_npm_init_license() -> Result { Ok(license.trim().to_string()) } +fn ensure_program_feature( + cfg_override: &ConfigOverride, + program_name: Option, + feature: &str, + flag_name: &str, +) -> Result<()> { + let cfg = Config::discover(cfg_override)? + .ok_or_else(|| anyhow!("The `{flag_name}` flag requires an Anchor workspace."))?; + let programs = cfg.get_programs(program_name)?; + let mut missing = Vec::new(); + + for program in programs { + let cargo_toml = program.path.join("Cargo.toml"); + let manifest = Manifest::from_path(&cargo_toml)?; + if !manifest.features.contains_key(feature) { + missing.push((program.lib_name, cargo_toml)); + } + } + + if missing.is_empty() { + return Ok(()); + } + + let mut message = format!( + "`{flag_name}` requires each program to define the `{feature}` feature in its Cargo.toml.\nMissing in:\n" + ); + for (name, path) in missing { + message.push_str(&format!(" - {name} ({})\n", path.display())); + } + message.push_str(&format!( + "\nAdd to each program's Cargo.toml:\n\n[features]\n{feature} = []\n\nOr run without `{flag_name}`." + )); + + Err(anyhow!(message)) +} + fn process_command(opts: Opts) -> Result<()> { match opts.command { Command::Init { @@ -1159,25 +1201,39 @@ fn process_command(opts: Opts) -> Result<()> { ignore_keys, no_docs, arch, - } => build( - &opts.cfg_override, - no_idl, - idl, - idl_ts, - verifiable, - skip_lint, - ignore_keys, - program_name, - solana_version, - docker_image, - bootstrap, - None, - None, - env, - cargo_args, - no_docs, - arch, - ), + log_compute_units, + } => { + let mut cargo_args = cargo_args; + if log_compute_units { + ensure_program_feature( + &opts.cfg_override, + program_name.clone(), + "log-compute-units", + "--log-compute-units", + )?; + cargo_args.push("--features".to_string()); + cargo_args.push("log-compute-units".to_string()); + } + build( + &opts.cfg_override, + no_idl, + idl, + idl_ts, + verifiable, + skip_lint, + ignore_keys, + program_name, + solana_version, + docker_image, + bootstrap, + None, + None, + env, + cargo_args, + no_docs, + arch, + ) + } Command::Verify { program_id, repo_url, @@ -1252,22 +1308,38 @@ fn process_command(opts: Opts) -> Result<()> { cargo_args, skip_lint, arch, - } => test( - &opts.cfg_override, - program_name, - skip_deploy, - skip_local_validator, - skip_build, - skip_lint, - no_idl, - detach, - run, - validator, - args, - env, - cargo_args, - arch, - ), + log_compute_units, + } => { + let mut cargo_args = cargo_args; + if log_compute_units { + if !skip_build { + ensure_program_feature( + &opts.cfg_override, + program_name.clone(), + "log-compute-units", + "--log-compute-units", + )?; + } + cargo_args.push("--features".to_string()); + cargo_args.push("log-compute-units".to_string()); + } + test( + &opts.cfg_override, + program_name, + skip_deploy, + skip_local_validator, + skip_build, + skip_lint, + no_idl, + detach, + run, + validator, + args, + env, + cargo_args, + arch, + ) + } Command::Airdrop { amount, pubkey } => airdrop(&opts.cfg_override, amount, pubkey), Command::Cluster { subcmd } => cluster(subcmd), Command::Config { subcmd } => config_cmd(&opts.cfg_override, subcmd), diff --git a/cli/src/rust_template.rs b/cli/src/rust_template.rs index 6949c069c9..9d1d64e436 100644 --- a/cli/src/rust_template.rs +++ b/cli/src/rust_template.rs @@ -217,6 +217,7 @@ cpi = ["no-entrypoint"] no-entrypoint = [] no-idl = [] no-log-ix-name = [] +log-compute-units = [] idl-build = ["anchor-lang/idl-build"] anchor-debug = [] custom-heap = [] diff --git a/lang/src/lib.rs b/lang/src/lib.rs index bacc9b4a66..afa5a03541 100644 --- a/lang/src/lib.rs +++ b/lang/src/lib.rs @@ -132,6 +132,25 @@ pub mod solana_program { #[cfg(not(target_os = "solana"))] core::hint::black_box(data); } + + /// Print the remaining compute units available to the program. + pub fn sol_log_compute_units() { + #[cfg(target_os = "solana")] + unsafe { + solana_define_syscall::definitions::sol_log_compute_units_() + }; + } + + /// Get the remaining compute units available to the program. + pub fn sol_remaining_compute_units() -> u64 { + #[cfg(target_os = "solana")] + unsafe { + solana_define_syscall::definitions::sol_remaining_compute_units() + } + + #[cfg(not(target_os = "solana"))] + 0 + } } pub mod sysvar { pub use solana_sysvar_id::{declare_deprecated_sysvar_id, declare_sysvar_id, SysvarId}; @@ -502,6 +521,7 @@ pub mod prelude { pub use crate as anchor_lang; pub use crate::solana_program::account_info::{next_account_info, AccountInfo}; pub use crate::solana_program::instruction::AccountMeta; + pub use crate::solana_program::log::sol_remaining_compute_units; pub use crate::solana_program::program_error::ProgramError; pub use crate::solana_program::pubkey::Pubkey; pub use crate::solana_program::*; diff --git a/lang/syn/src/codegen/program/entry.rs b/lang/syn/src/codegen/program/entry.rs index 350e814f3b..5207719a81 100644 --- a/lang/syn/src/codegen/program/entry.rs +++ b/lang/syn/src/codegen/program/entry.rs @@ -37,6 +37,12 @@ pub fn generate(program: &Program) -> proc_macro2::TokenStream { /// The `entry` function here, defines the standard entry to a Solana /// program, where execution begins. pub fn entry<'info>(program_id: &Pubkey, accounts: &'info [AccountInfo<'info>], data: &[u8]) -> anchor_lang::solana_program::entrypoint::ProgramResult { + // Log compute units at program start. Note: This won't be exactly 200,000 because + // the Solana runtime consumes CUs for tx deserialization, program loading, + // account loading, and signature verification before calling your program. + #[cfg(feature = "log-compute-units")] + anchor_lang::prelude::msg!("anchor-compute: program-start, {} units", anchor_lang::solana_program::log::sol_remaining_compute_units()); + try_entry(program_id, accounts, data).map_err(|e| { e.log(); e.into() @@ -48,6 +54,10 @@ pub fn generate(program: &Program) -> proc_macro2::TokenStream { { msg!("anchor-debug is active"); } + + #[cfg(feature = "log-compute-units")] + anchor_lang::prelude::msg!("anchor-compute: entry, {} units", anchor_lang::solana_program::log::sol_remaining_compute_units()); + if *program_id != ID { return Err(anchor_lang::error::ErrorCode::DeclaredProgramIdMismatch.into()); } diff --git a/lang/syn/src/codegen/program/handlers.rs b/lang/syn/src/codegen/program/handlers.rs index 06e73a072e..7bba8b1de1 100644 --- a/lang/syn/src/codegen/program/handlers.rs +++ b/lang/syn/src/codegen/program/handlers.rs @@ -107,12 +107,20 @@ pub fn generate(program: &Program) -> proc_macro2::TokenStream { #[cfg(not(feature = "no-log-ix-name"))] anchor_lang::prelude::msg!(#ix_name_log); + // Log compute units at handler start (before any deserialization) + #[cfg(feature = "log-compute-units")] + anchor_lang::prelude::msg!("anchor-compute: begin, {} units", anchor_lang::solana_program::log::sol_remaining_compute_units()); + #param_validation // Deserialize data. let ix = instruction::#ix_name::deserialize(&mut &__ix_data[..]) .map_err(|_| anchor_lang::error::ErrorCode::InstructionDidNotDeserialize)?; let instruction::#variant_arm = ix; + // Log compute units after instruction data deserialization + #[cfg(feature = "log-compute-units")] + anchor_lang::prelude::msg!("anchor-compute: ix-deser, {} units", anchor_lang::solana_program::log::sol_remaining_compute_units()); + // Bump collector. let mut __bumps = <#anchor as anchor_lang::Bumps>::Bumps::default(); @@ -128,6 +136,10 @@ pub fn generate(program: &Program) -> proc_macro2::TokenStream { &mut __reallocs, )?; + // Log compute units after account deserialization (often most expensive) + #[cfg(feature = "log-compute-units")] + anchor_lang::prelude::msg!("anchor-compute: accts-deser, {} units", anchor_lang::solana_program::log::sol_remaining_compute_units()); + // Invoke user defined handler. let result = #program_name::#ix_method_name( anchor_lang::context::Context::new( @@ -139,6 +151,10 @@ pub fn generate(program: &Program) -> proc_macro2::TokenStream { #(#ix_arg_names),* )?; + // Log compute units after user handler execution + #[cfg(feature = "log-compute-units")] + anchor_lang::prelude::msg!("anchor-compute: handler, {} units", anchor_lang::solana_program::log::sol_remaining_compute_units()); + // Maybe set Solana return data. #maybe_set_return_data diff --git a/tests/log-compute-units/Anchor.toml b/tests/log-compute-units/Anchor.toml new file mode 100644 index 0000000000..49a0a0ccd3 --- /dev/null +++ b/tests/log-compute-units/Anchor.toml @@ -0,0 +1,20 @@ +[toolchain] + +[features] +resolution = true +skip-lint = false + +[programs.localnet] +log_compute_units = "848vVGVxp1kcRABrBid3uGCu1iiuPAHFuwpYfMMPPVZ7" + +[registry] +url = "https://api.apr.dev" + +[provider] +cluster = "localnet" +wallet = "~/.config/solana/id.json" + +[scripts] +test = "yarn run ts-mocha -p ./tsconfig.json -t 1000000 tests/**/*.ts" + +[hooks] diff --git a/tests/log-compute-units/Cargo.toml b/tests/log-compute-units/Cargo.toml new file mode 100644 index 0000000000..97d6280542 --- /dev/null +++ b/tests/log-compute-units/Cargo.toml @@ -0,0 +1,8 @@ +[workspace] +members = [ + "programs/*" +] +resolver = "2" + +[profile.release] +overflow-checks = true diff --git a/tests/log-compute-units/package.json b/tests/log-compute-units/package.json new file mode 100644 index 0000000000..7b6b39fa25 --- /dev/null +++ b/tests/log-compute-units/package.json @@ -0,0 +1,19 @@ +{ + "name": "log-compute-units", + "version": "0.32.1", + "license": "(MIT OR Apache-2.0)", + "homepage": "https://github.com/coral-xyz/anchor#readme", + "bugs": { + "url": "https://github.com/coral-xyz/anchor/issues" + }, + "repository": { + "type": "git", + "url": "https://github.com/coral-xyz/anchor.git" + }, + "engines": { + "node": ">=17" + }, + "scripts": { + "test": "anchor test --skip-lint" + } +} diff --git a/tests/log-compute-units/programs/log-compute-units/Cargo.toml b/tests/log-compute-units/programs/log-compute-units/Cargo.toml new file mode 100644 index 0000000000..51942d5294 --- /dev/null +++ b/tests/log-compute-units/programs/log-compute-units/Cargo.toml @@ -0,0 +1,24 @@ +[package] +name = "log-compute-units" +version = "0.1.0" +description = "Test for log-compute-units feature" +edition = "2021" + +[lib] +crate-type = ["cdylib", "lib"] +name = "log_compute_units" + +[features] +default = ["log-compute-units"] +no-entrypoint = [] +cpi = ["no-entrypoint"] +no-idl = [] +no-log-ix-name = [] +log-compute-units = [] +idl-build = ["anchor-lang/idl-build"] +anchor-debug = [] +custom-heap = [] +custom-panic = [] + +[dependencies] +anchor-lang = { path = "../../../../lang" } diff --git a/tests/log-compute-units/programs/log-compute-units/src/lib.rs b/tests/log-compute-units/programs/log-compute-units/src/lib.rs new file mode 100644 index 0000000000..26ef87c6b8 --- /dev/null +++ b/tests/log-compute-units/programs/log-compute-units/src/lib.rs @@ -0,0 +1,44 @@ +use anchor_lang::prelude::*; + +declare_id!("848vVGVxp1kcRABrBid3uGCu1iiuPAHFuwpYfMMPPVZ7"); + +#[program] +mod log_compute_units { + use super::*; + + pub fn initialize(ctx: Context) -> Result<()> { + msg!("custom-compute: init, {} units", sol_remaining_compute_units()); + ctx.accounts.data.value = 42; + Ok(()) + } + + pub fn update(ctx: Context, new_value: u64) -> Result<()> { + msg!("custom-compute: update, {} units", sol_remaining_compute_units()); + ctx.accounts.data.value = new_value; + Ok(()) + } +} + +#[derive(Accounts)] +pub struct Initialize<'info> { + #[account( + init, + payer = payer, + space = 8 + 8 + )] + pub data: Account<'info, Data>, + #[account(mut)] + pub payer: Signer<'info>, + pub system_program: Program<'info, System>, +} + +#[derive(Accounts)] +pub struct Update<'info> { + #[account(mut)] + pub data: Account<'info, Data>, +} + +#[account] +pub struct Data { + pub value: u64, +} diff --git a/tests/log-compute-units/tests/log-compute-units.ts b/tests/log-compute-units/tests/log-compute-units.ts new file mode 100644 index 0000000000..e0d1f66193 --- /dev/null +++ b/tests/log-compute-units/tests/log-compute-units.ts @@ -0,0 +1,130 @@ +import * as anchor from "@anchor-lang/core"; +import { Program } from "@anchor-lang/core"; +import { assert } from "chai"; +import { LogComputeUnits } from "../target/types/log_compute_units"; + +// Helper to fetch transaction with retries +async function getTransactionWithRetry( + connection: anchor.web3.Connection, + signature: string, + maxRetries = 10 +) { + for (let i = 0; i < maxRetries; i++) { + const txDetails = await connection.getTransaction(signature, { + commitment: "confirmed", + maxSupportedTransactionVersion: 0, + }); + if (txDetails) { + return txDetails; + } + // Wait before retry + await new Promise((resolve) => setTimeout(resolve, 500)); + } + throw new Error( + `Transaction ${signature} not found after ${maxRetries} retries` + ); +} + +describe("log-compute-units", () => { + // Configure the client to use the local cluster. + const provider = anchor.AnchorProvider.local(); + anchor.setProvider(provider); + const program = anchor.workspace.LogComputeUnits as Program; + + it("Logs compute units during initialize", async () => { + const data = anchor.web3.Keypair.generate(); + + const tx = await program.methods + .initialize() + .accounts({ + data: data.publicKey, + payer: provider.wallet.publicKey, + systemProgram: anchor.web3.SystemProgram.programId, + }) + .signers([data]) + .rpc({ commitment: "confirmed" }); + + console.log("Initialize transaction signature:", tx); + + // Fetch the transaction to check logs (with retry) + const txDetails = await getTransactionWithRetry(provider.connection, tx); + + console.log("\n--- Transaction Logs ---"); + txDetails.meta?.logMessages?.forEach((log) => console.log(log)); + console.log("------------------------\n"); + + // Verify compute unit logs are present + const logs = txDetails.meta?.logMessages || []; + const anchorLogs = logs.filter( + (log) => log.includes("anchor-compute:") && log.includes("units") + ); + const customLogs = logs.filter( + (log) => log.includes("custom-compute:") && log.includes("units") + ); + + // Should have 6 anchor compute logs + 1 custom log from user handler + assert.ok( + anchorLogs.length >= 6, + `Expected at least 6 anchor compute logs, got ${anchorLogs.length}` + ); + assert.ok( + customLogs.length >= 1, + `Expected at least 1 custom compute log, got ${customLogs.length}` + ); + }); + + it("Logs compute units during update", async () => { + const data = anchor.web3.Keypair.generate(); + + // First initialize + await program.methods + .initialize() + .accounts({ + data: data.publicKey, + payer: provider.wallet.publicKey, + systemProgram: anchor.web3.SystemProgram.programId, + }) + .signers([data]) + .rpc({ commitment: "confirmed" }); + + // Then update + const tx = await program.methods + .update(new anchor.BN(100)) + .accounts({ + data: data.publicKey, + }) + .rpc({ commitment: "confirmed" }); + + console.log("Update transaction signature:", tx); + + // Fetch the transaction to check logs (with retry) + const txDetails = await getTransactionWithRetry(provider.connection, tx); + + console.log("\n--- Transaction Logs ---"); + txDetails.meta?.logMessages?.forEach((log) => console.log(log)); + console.log("------------------------\n"); + + // Verify compute unit logs are present + const logs = txDetails.meta?.logMessages || []; + const anchorLogs = logs.filter( + (log) => log.includes("anchor-compute:") && log.includes("units") + ); + const customLogs = logs.filter( + (log) => log.includes("custom-compute:") && log.includes("units") + ); + + // Should have 6 anchor compute logs + 1 custom log from user handler + assert.ok( + anchorLogs.length >= 6, + `Expected at least 6 anchor compute logs, got ${anchorLogs.length}` + ); + assert.ok( + customLogs.length >= 1, + `Expected at least 1 custom compute log, got ${customLogs.length}` + ); + + // Verify the data was actually updated + const dataAccount = await program.account.data.fetch(data.publicKey); + assert.equal(dataAccount.value.toNumber(), 100); + }); +}); diff --git a/tests/log-compute-units/tsconfig.json b/tests/log-compute-units/tsconfig.json new file mode 100644 index 0000000000..cd5d2e3d06 --- /dev/null +++ b/tests/log-compute-units/tsconfig.json @@ -0,0 +1,10 @@ +{ + "compilerOptions": { + "types": ["mocha", "chai"], + "typeRoots": ["./node_modules/@types"], + "lib": ["es2015"], + "module": "commonjs", + "target": "es6", + "esModuleInterop": true + } +} diff --git a/tests/package.json b/tests/package.json index f5428d6cc2..a2429c60c6 100644 --- a/tests/package.json +++ b/tests/package.json @@ -53,7 +53,8 @@ "multiple-suites-run-single", "bpf-upgradeable-state", "duplicate-mutable-accounts", - "signature-verification" + "signature-verification", + "log-compute-units" ], "dependencies": { "@project-serum/common": "^0.0.1-beta.3",