blockworks-foundation
/
mango-v4
mirror of https://github.com/blockworks-foundation/mango-v4.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

program-test improvements: performance, cu test output, warnings (#749) 

* tests: Upgrade tx log capturing

Instead of overriding the system logger to intercept the logs, we can
now ask solana to return the logs of a tx execution directly.

This speeds up tests a lot because we don't need to hold a global lock
on tx execution anymore!

* tests: Improve token, serum, perp cu test
* benchmark: add a few more operations
This commit is contained in:
Christian Kamm 2023-10-11 15:18:23 +02:00 committed by GitHub
parent a4745dae27
commit 20eb02af01
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
8 changed files with 219 additions and 130 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

26
programs/mango-v4/src/instructions/benchmark.rs
View File

@ -42,6 +42,7 @@ pub fn benchmark(_ctx: Context<Benchmark>) -> Result<()> {
run_bench("conversion_f64_to_i80f48", || I80F48::from_num(f));
let a2: I80F48 = a >> 64;
let b2: I80F48 = b >> 64;
run_bench("add_i80f48", || a2.checked_add(b2).unwrap());
run_bench("mul_i80f48", || a2.checked_mul(b2).unwrap());
}
@ -65,24 +66,33 @@ pub fn benchmark(_ctx: Context<Benchmark>) -> Result<()> {
run_bench("division_i32", || a.checked_div(b).unwrap());
}
{
let a = s as u32;
let b = t as u32;
run_bench("division_u32", || a.checked_div(b).unwrap());
}
{
let a = s as f64;
let b = t as f64;
run_bench("division_f64", || a / b);
run_bench("add_f64", || a + b);
run_bench("mul_f64", || a * b);
run_bench("division_f64", || a / b);
}
{
let a = s as f32;
let b = t as f32;
run_bench("division_f32", || a / b);
run_bench("add_f32", || a + b);
run_bench("mul_f32", || a * b);
run_bench("division_f32", || a / b);
}
{
let a = s as u32;
let b = t as u32;
run_bench("add_u32", || a + b);
run_bench("division_u32", || a.checked_div(b).unwrap());
}
{
let a = s as u64;
let b = t as u64;
run_bench("add_u64", || a + b);
run_bench("division_u64", || a.checked_div(b).unwrap());
}
Ok(())

9
programs/mango-v4/tests/cases/test_benchmark.rs
View File

@ -8,14 +8,17 @@ async fn test_benchmark() -> Result<(), TransportError> {
let context = TestContext::new().await;
let solana = &context.solana.clone();
send_tx(solana, BenchmarkInstruction {}).await.unwrap();
let result = send_tx_get_metadata(solana, BenchmarkInstruction {})
.await
.unwrap();
let meta = result.metadata.unwrap();
let log_lines = solana.program_log();
let log_lines = meta.log_messages;
let bench_regions = log_lines
.iter()
.enumerate()
.filter_map(|(index, line)| {
if line.starts_with(&"BENCH") {
if line.starts_with(&"Program log: BENCH") {
Some(index)
} else {
None

176
programs/mango-v4/tests/cases/test_health_compute.rs
View File

@ -1,4 +1,28 @@
use super::*;
use mango_v4::accounts_ix::{Serum3OrderType, Serum3SelfTradeBehavior, Serum3Side};
async fn deposit_cu_datapoint(
solana: &SolanaCookie,
account: Pubkey,
owner: TestKeypair,
token_account: Pubkey,
) -> u64 {
let result = send_tx_get_metadata(
solana,
TokenDepositInstruction {
amount: 10,
reduce_only: false,
account,
owner,
token_account,
token_authority: owner,
bank_index: 0,
},
)
.await
.unwrap();
result.metadata.unwrap().compute_units_consumed
}
// Try to reach compute limits in health checks by having many different tokens in an account
#[tokio::test]
@ -24,11 +48,27 @@ async fn test_health_compute_tokens() -> Result<(), TransportError> {
.create(solana)
.await;
// each deposit ends with a health check
create_funded_account(&solana, group, owner, 0, &context.users[1], mints, 1000, 0).await;
let account =
create_funded_account(&solana, group, owner, 0, &context.users[1], &[], 1000, 0).await;
// TODO: actual explicit CU comparisons.
// On 2023-8-18 the final deposit costs 56245 CU and each new token increases it by roughly 2800 CU
let mut cu_measurements = vec![];
for token_account in &context.users[0].token_accounts[..mints.len()] {
cu_measurements.push(deposit_cu_datapoint(solana, account, owner, *token_account).await);
}
for (i, pair) in cu_measurements.windows(2).enumerate() {
println!(
"after adding token {}: {} (+{})",
i,
pair[1],
pair[1] - pair[0]
);
}
let avg_cu_increase = cu_measurements.windows(2).map(|p| p[1] - p[0]).sum::<u64>()
/ (cu_measurements.len() - 1) as u64;
println!("average cu increase: {avg_cu_increase}");
assert!(avg_cu_increase < 3200);
Ok(())
}
@ -37,7 +77,7 @@ async fn test_health_compute_tokens() -> Result<(), TransportError> {
#[tokio::test]
async fn test_health_compute_serum() -> Result<(), TransportError> {
let mut test_builder = TestContextBuilder::new();
test_builder.test().set_compute_max_units(90_000);
test_builder.test().set_compute_max_units(150_000);
let context = test_builder.start_default().await;
let solana = &context.solana.clone();
@ -45,7 +85,7 @@ async fn test_health_compute_serum() -> Result<(), TransportError> {
let owner = context.users[0].key;
let payer = context.users[1].key;
let mints = &context.mints[0..5];
let payer_mint_accounts = &context.users[1].token_accounts[0..mints.len()];
let token_account = context.users[0].token_accounts[0];
//
// SETUP: Create a group and an account
@ -60,10 +100,29 @@ async fn test_health_compute_serum() -> Result<(), TransportError> {
.create(solana)
.await;
let account = send_tx(
// Also activate all token positions
let account = create_funded_account(
&solana,
group,
owner,
0,
&context.users[1],
&mints,
10000,
0,
)
.await;
// Allow 8 tokens + 8 serum
send_tx(
solana,
AccountCreateInstruction {
AccountExpandInstruction {
account_num: 0,
token_count: 8,
serum3_count: 8,
perp_count: 0,
perp_oo_count: 0,
token_conditional_swap_count: 0,
group,
owner,
payer,
@ -71,8 +130,7 @@ async fn test_health_compute_serum() -> Result<(), TransportError> {
},
)
.await
.unwrap()
.account;
.unwrap();
//
// SETUP: Create serum markets and register them
@ -111,11 +169,15 @@ async fn test_health_compute_serum() -> Result<(), TransportError> {
);
}
let mut cu_measurements = vec![];
// Get the baseline cost of a deposit without an active serum3 oo
cu_measurements.push(deposit_cu_datapoint(solana, account, owner, token_account).await);
//
// TEST: Create open orders and trigger a Deposit to check health
//
for (i, &serum_market) in serum_markets.iter().enumerate() {
println!("adding market {}", i);
for &serum_market in serum_markets.iter() {
send_tx(
solana,
Serum3CreateOpenOrdersInstruction {
@ -128,24 +190,61 @@ async fn test_health_compute_serum() -> Result<(), TransportError> {
.await
.unwrap();
// Place a bid and ask to make the health computation use more compute
send_tx(
solana,
TokenDepositInstruction {
amount: 10,
reduce_only: false,
Serum3PlaceOrderInstruction {
side: Serum3Side::Bid,
limit_price: 1,
max_base_qty: 1,
max_native_quote_qty_including_fees: 1,
self_trade_behavior: Serum3SelfTradeBehavior::AbortTransaction,
order_type: Serum3OrderType::Limit,
client_order_id: 0,
limit: 10,
account,
owner,
token_account: payer_mint_accounts[0],
token_authority: payer.clone(),
bank_index: 0,
serum_market,
},
)
.await
.unwrap();
send_tx(
solana,
Serum3PlaceOrderInstruction {
side: Serum3Side::Ask,
limit_price: 2,
max_base_qty: 1,
max_native_quote_qty_including_fees: 1,
self_trade_behavior: Serum3SelfTradeBehavior::AbortTransaction,
order_type: Serum3OrderType::Limit,
client_order_id: 1,
limit: 10,
account,
owner,
serum_market,
},
)
.await
.unwrap();
// Simple deposit: it's cost is what we use as reference for health compute cost
cu_measurements.push(deposit_cu_datapoint(solana, account, owner, token_account).await);
}
// TODO: actual explicit CU comparisons.
// On 2023-2-23 the final deposit costs 81141 CU and each new market increases it by roughly 6184 CU
for (i, pair) in cu_measurements.windows(2).enumerate() {
println!(
"after adding market {}: {} (+{})",
i,
pair[1],
pair[1] - pair[0]
);
}
let avg_cu_increase = cu_measurements.windows(2).map(|p| p[1] - p[0]).sum::<u64>()
/ (cu_measurements.len() - 1) as u64;
println!("average cu increase: {avg_cu_increase}");
assert!(avg_cu_increase < 10000);
Ok(())
}
@ -162,7 +261,7 @@ async fn test_health_compute_perp() -> Result<(), TransportError> {
let owner = context.users[0].key;
let payer = context.users[1].key;
let mints = &context.mints[0..5];
let payer_mint_accounts = &context.users[1].token_accounts[0..mints.len()];
let token_account = context.users[0].token_accounts[0];
//
// SETUP: Create a group and an account
@ -226,6 +325,11 @@ async fn test_health_compute_perp() -> Result<(), TransportError> {
perp_market.native_price_to_lot(I80F48::from(1))
};
let mut cu_measurements = vec![];
// Get the baseline cost of a deposit without an active serum3 oo
cu_measurements.push(deposit_cu_datapoint(solana, account, owner, token_account).await);
//
// TEST: Create a perp order for each market
//
@ -246,24 +350,22 @@ async fn test_health_compute_perp() -> Result<(), TransportError> {
.await
.unwrap();
send_tx(
solana,
TokenDepositInstruction {
amount: 10,
reduce_only: false,
account,
owner,
token_account: payer_mint_accounts[0],
token_authority: payer.clone(),
bank_index: 0,
},
)
.await
.unwrap();
cu_measurements.push(deposit_cu_datapoint(solana, account, owner, token_account).await);
}
// TODO: actual explicit CU comparisons.
// On 2023-8-18 the final deposit costs 51879 CU and each new market increases it by roughly 4100 CU
for (i, pair) in cu_measurements.windows(2).enumerate() {
println!(
"after adding perp market {}: {} (+{})",
i,
pair[1],
pair[1] - pair[0]
);
}
let avg_cu_increase = cu_measurements.windows(2).map(|p| p[1] - p[0]).sum::<u64>()
/ (cu_measurements.len() - 1) as u64;
println!("average cu increase: {avg_cu_increase}");
assert!(avg_cu_increase < 4800);
Ok(())
}

12
programs/mango-v4/tests/cases/test_health_region.rs
View File

@ -123,7 +123,7 @@ async fn test_health_wrap() -> Result<(), TransportError> {
affected_bank: None,
})
.await;
tx.send().await
tx.send_get_metadata().await
}
};
@ -131,8 +131,9 @@ async fn test_health_wrap() -> Result<(), TransportError> {
// TEST: Placing a giant order fails
//
{
send_test_tx(1.0, 100000, false).await.unwrap_err();
let logs = solana.program_log();
let result = send_test_tx(1.0, 100000, false).await.unwrap();
assert!(result.result.is_err());
let logs = result.metadata.unwrap().log_messages;
// reaches the End instruction
assert!(logs
.iter()
@ -154,8 +155,9 @@ async fn test_health_wrap() -> Result<(), TransportError> {
// TEST: If we cancel the order again before the HealthRegionEnd, it can go through
//
{
send_test_tx(1.0, 100000, true).await.unwrap();
let logs = solana.program_log();
let result = send_test_tx(1.0, 100000, true).await.unwrap();
assert!(result.result.is_ok());
let logs = result.metadata.unwrap().log_messages;
// health computed only once
assert_eq!(
logs.iter()

4
programs/mango-v4/tests/cases/test_margin_trade.rs
View File

@ -440,10 +440,6 @@ async fn test_flash_loan_creates_ata_accounts() -> Result<(), BanksClientError>
let mints = &context.mints[0..2];
let payer_mint0_account = context.users[1].token_accounts[0];
let payer_mint1_account = context.users[1].token_accounts[1];
let loan_origination_fee = 0.0005;
// higher resolution that the loan_origination_fee for one token
let balance_f64eq = |a: f64, b: f64| utils::assert_equal_f64_f64(a, b, 0.0001);
//
// SETUP: Create a group, account, register a token (mint0)

35
programs/mango-v4/tests/program_test/mango_client.rs
View File

@ -11,7 +11,7 @@ use mango_v4::accounts_ix::{
};
use mango_v4::state::{MangoAccount, MangoAccountValue};
use solana_program::instruction::Instruction;
use solana_program_test::BanksClientError;
use solana_program_test::{BanksClientError, BanksTransactionResultWithMetadata};
use solana_sdk::instruction;
use solana_sdk::transport::TransportError;
use std::sync::Arc;
@ -41,7 +41,7 @@ impl ClientAccountLoader for &SolanaCookie {
}
}
// TODO: report error outwards etc
// This fill return a failure if the tx resulted in an error
pub async fn send_tx<CI: ClientInstruction>(
solana: &SolanaCookie,
ix: CI,
@ -49,12 +49,26 @@ pub async fn send_tx<CI: ClientInstruction>(
let (accounts, instruction) = ix.to_instruction(solana).await;
let signers = ix.signers();
let instructions = vec![instruction];
solana
let result = solana
.process_transaction(&instructions, Some(&signers[..]))
.await?;
result.result?;
Ok(accounts)
}
// This will return success even if the tx failed to finish
pub async fn send_tx_get_metadata<CI: ClientInstruction>(
solana: &SolanaCookie,
ix: CI,
) -> std::result::Result<BanksTransactionResultWithMetadata, BanksClientError> {
let (_, instruction) = ix.to_instruction(solana).await;
let signers = ix.signers();
let instructions = vec![instruction];
solana
.process_transaction(&instructions, Some(&signers[..]))
.await
}
/// Build a transaction from multiple instructions
pub struct ClientTransaction {
solana: Arc<SolanaCookie>,
@ -87,7 +101,20 @@ impl<'a> ClientTransaction {
self.signers.push(keypair);
}
// Fails on tx error
pub async fn send(&self) -> std::result::Result<(), BanksClientError> {
let tx_result = self
.solana
.process_transaction(&self.instructions, Some(&self.signers))
.await?;
tx_result.result?;
Ok(())
}
// Tx error still returns success
pub async fn send_get_metadata(
&self,
) -> std::result::Result<BanksTransactionResultWithMetadata, BanksClientError> {
self.solana
.process_transaction(&self.instructions, Some(&self.signers))
.await
@ -365,7 +392,7 @@ pub async fn check_prev_instruction_post_health(solana: &SolanaCookie, account:
let logs = solana.program_log();
let post_health_str = logs
.iter()
.find_map(|line| line.strip_prefix("post_init_health: "))
.find_map(|line| line.strip_prefix("Program log: post_init_health: "))
.unwrap();
let post_health = post_health_str.parse::<f64>().unwrap();

47
programs/mango-v4/tests/program_test/mod.rs
View File

@ -2,9 +2,8 @@
use std::cell::RefCell;
use std::str::FromStr;
use std::{sync::Arc, sync::RwLock};
use std::sync::Arc;
use log::*;
use solana_program::{program_option::COption, program_pack::Pack};
use solana_program_test::*;
use solana_sdk::pubkey::Pubkey;
@ -47,36 +46,6 @@ impl AddPacked for ProgramTest {
}
}
struct LoggerWrapper {
inner: env_logger::Logger,
capture: Arc<RwLock<Vec<String>>>,
}
impl Log for LoggerWrapper {
fn enabled(&self, metadata: &log::Metadata) -> bool {
self.inner.enabled(metadata)
}
fn log(&self, record: &log::Record) {
if record
.target()
.starts_with("solana_runtime::message_processor")
{
let msg = record.args().to_string();
if let Some(data) = msg.strip_prefix("Program log: ") {
self.capture.write().unwrap().push(data.into());
} else if let Some(data) = msg.strip_prefix("Program data: ") {
self.capture.write().unwrap().push(data.into());
} else if let Some(data) = msg.strip_prefix("Program consumption: ") {
self.capture.write().unwrap().push(data.into());
}
}
self.inner.log(record);
}
fn flush(&self) {}
}
pub struct MarginTradeCookie {
pub program: Pubkey,
pub token_account: TestKeypair,
@ -86,15 +55,9 @@ pub struct MarginTradeCookie {
pub struct TestContextBuilder {
test: ProgramTest,
logger_capture: Arc<RwLock<Vec<String>>>,
mint0: Pubkey,
}
lazy_static::lazy_static! {
static ref LOGGER_CAPTURE: Arc<RwLock<Vec<String>>> = Arc::new(RwLock::new(vec![]));
static ref LOGGER_LOCK: Arc<RwLock<()>> = Arc::new(RwLock::new(()));
}
impl TestContextBuilder {
pub fn new() -> Self {
// We need to intercept logs to capture program log output
@ -106,10 +69,7 @@ impl TestContextBuilder {
env_logger::Builder::from_env(env_logger::Env::new().default_filter_or(log_filter))
.format_timestamp_nanos()
.build();
let _ = log::set_boxed_logger(Box::new(LoggerWrapper {
inner: env_logger,
capture: LOGGER_CAPTURE.clone(),
}));
let _ = log::set_boxed_logger(Box::new(env_logger));
let mut test = ProgramTest::new("mango_v4", mango_v4::id(), processor!(mango_v4::entry));
@ -118,7 +78,6 @@ impl TestContextBuilder {
Self {
test,
logger_capture: LOGGER_CAPTURE.clone(),
mint0: Pubkey::new_unique(),
}
}
@ -282,8 +241,6 @@ impl TestContextBuilder {
let solana = Arc::new(SolanaCookie {
context: RefCell::new(context),
rent,
logger_capture: self.logger_capture.clone(),
logger_lock: LOGGER_LOCK.clone(),
last_transaction_log: RefCell::new(vec![]),
});

40
programs/mango-v4/tests/program_test/solana.rs
View File

@ -1,7 +1,6 @@
#![allow(dead_code)]
use std::cell::RefCell;
use std::sync::{Arc, RwLock};
use super::utils::TestKeypair;
use anchor_lang::AccountDeserialize;
@ -20,8 +19,6 @@ use spl_token::*;
pub struct SolanaCookie {
pub context: RefCell<ProgramTestContext>,
pub rent: Rent,
pub logger_capture: Arc<RwLock<Vec<String>>>,
pub logger_lock: Arc<RwLock<()>>,
pub last_transaction_log: RefCell<Vec<String>>,
}
@ -30,17 +27,7 @@ impl SolanaCookie {
&self,
instructions: &[Instruction],
signers: Option<&[TestKeypair]>,
) -> Result<(), BanksClientError> {
// The locking in this function is convoluted:
// We capture the program log output by overriding the global logger and capturing
// messages there. This logger is potentially shared among multiple tests that run
// concurrently.
// To allow each independent SolanaCookie to capture only the logs from the transaction
// passed to process_transaction, wo globally hold the "program_log_lock" for the
// duration that the tx needs to process. So only a single one can run at a time.
let tx_log_lock = Arc::new(self.logger_lock.write().unwrap());
self.logger_capture.write().unwrap().clear();
) -> Result<BanksTransactionResultWithMetadata, BanksClientError> {
let mut context = self.context.borrow_mut();
let blockhash = context.get_new_latest_blockhash().await?;
@ -62,15 +49,16 @@ impl SolanaCookie {
let result = context
.banks_client
.process_transaction_with_commitment(
transaction,
solana_sdk::commitment_config::CommitmentLevel::Processed,
)
.process_transaction_with_metadata(transaction)
.await;
*self.last_transaction_log.borrow_mut() = self.logger_capture.read().unwrap().clone();
*self.last_transaction_log.borrow_mut() = result
.as_ref()
.ok()
.and_then(|r| r.metadata.as_ref())
.map(|v| v.log_messages.clone())
.unwrap_or_default();
drop(tx_log_lock);
drop(context);
result
@ -264,11 +252,15 @@ impl SolanaCookie {
self.program_log()
.iter()
.filter_map(|data| {
let bytes = base64::decode(data).ok()?;
if bytes[0..8] != T::discriminator() {
return None;
if let Some(event) = data.strip_prefix("Program data: ") {
let bytes = base64::decode(event).ok()?;
if bytes[0..8] != T::discriminator() {
return None;
}
T::try_from_slice(&bytes[8..]).ok()
} else {
None
}
T::try_from_slice(&bytes[8..]).ok()
})
.collect()
}