Allow printing gas reports from contracts (debug mode)

[ethanfrey]

We can calculate the amount of gas used, both by wasm as well as by external callbacks, upon any call to the vm.

When optimizing contracts, it would be good to expose this number. We don't need (can't really use) rust profiling tools, but we can get deterministic gas costs for every run. With this API as well as Api.debug we could build some tools to get insights into what parts of the code are expensive, using the same tools as normal integration tests.

It's been a while since I profiled and I wonder how much is used by JSON parsing, there have been some large impacts with improved parsing. This would be useful to see if #688 among others is worth pursuing.

[maurolacy]

I like it. I could work on it after what I'm doing now.

[webmaster128]

Would it be sufficient to trigget printing a gas report from the contract? I think this is easy to do.

Returning the gas information to the contract is a whole different story. Api exists before the Instance and has no access to it. Changing this would be a huge venture.

[ethanfrey]

Api exists before the Instance and has no access to it. Changing this would be a huge venture.

Hmmm.... would it fit better in Querier, which does have access to the gas meter?

On the other hand, the minimal I would need for performance tests is some external call print_gas_report(label: &str). This would print something like: <label>: used wasm gas: 1234567 used external gas: 54321 (and be controlled by the same print_debug flag). Maybe that is easier? It doesn't return anything, easy to mock away (no op) in unit tests.

That said, I think it would also be useful (longer term if this is much harder) to return gas_left, but we can deal with that after #691 is implemented.

[webmaster128]

I just looked into the implementation again, and it turns out the imports cannot access Instance, but Environment which has the gas information available:

E.g. here

/// Prints a debug message to console.
/// This does not charge gas, so debug printing should be disabled when used in a blockchain module.
pub fn native_debug<A: Api, S: Storage, Q: Querier>(
    env: &Environment<A, S, Q>,
    message_ptr: u32,
) -> VmResult<()> {
    if env.print_debug {
        let message_data = read_region(&env.memory(), message_ptr, MAX_LENGTH_DEBUG)?;
        let msg = String::from_utf8_lossy(&message_data);
        println!("{}", msg);
    }
    Ok(())
}

However, I would be very very (very very) careful exposing gas information to the contract. The moment we do that, someone starts writing contract code that makes assumtions on how gas works. And then everything blows up when gas metering changes or the contract is used on multiple chains with different pricing for CosmWasm gas or Cosmos SDK gas.

[ethanfrey]

Okay, updated the title to match the last comments

[dakom]

Hey y'all. I was searching for this capability and @ethanfrey pointed me here.

I can't speak to the implications on the VM side, but from an app developer side this would be AMAZING.

If it's possible, a query or some way of poking and keeping the value would be better than just logging, of course. That way we can do things like accumulate the gas costs over certain regions of code, stuff like that.

I don't even want to share how many hours or days I have spent going through a process of recompiling and running tests just to look at changes in gas usage, trying to hunt down some elusive costs.

Anything I can do to help revive this issue?

[ethanfrey]

Added to next milestone to revive it from forgotten hood

[webmaster128]

This is only possible for integration tests which are run by the VM. Unit tests do not have the inforation available. Given that the entire ecosystem is moving away from integration tests, I wonder if it worth investing time here right now.

[ethanfrey]

Many people are running full stack tests. There is something called cosm-orc which provides a simple Rust interface to run your contract in a real Juno node and get gas reports. They only make sense on real nodes, not in cosmwasm-vm integration tests. Osmosis is also working on a similar tool for this as well.

If we run such a tool with a wasmd/junod/osmosisd binary configured to allow debug output, then providing a place to output "gas used up to this point" could be very useful when trying to optimize gas usage.

[ethanfrey]

Note: using this requires setting up cfg.ContractDebugMode in the wasmd configuration to enable output of the debug info.

It can be set by running the node with --trace which should be quite easy to integrate into said tools.

[webmaster128]

Good. Printing the value to stdout (like deps.api.debug) is straight forward. However, the Go caller code has no way to direct the output somewhere. Is this good enough for a first step?

[ethanfrey]

I think that is a good first step.

We should make sure it is normalised to be Cosmos SDK gas so people can compare easily.

I would like to get feedback from some other framework (like cosm-orc) how to format the output so they can do something useful with it. I see this example gas report they output.

• Do we want them to include this?
• Do we just want to trail the stdout for that?
• Do we want to format this in some constant structure (at least for easy prepping)?
• Do we want to include the filename/line of the triggering statement (maybe we need a macro here)?

Plenty of questions to iterate on. I would work on a good-enough version and hope other code can adapt to it. Or adjust later on. For now, I would propose something as follows. A user can type something like:

deps.api.output_gas("AAA"); OR deps.api.output_gas(format!("{}: {}", filename!(), line!()));
(if people like the later form, we could make a macro for that like show_gas!(deps)

The vm code would calculate gas used, convert to sdk gas and output something like:

{ "gas_used": 123456, "message": "contract.rs:345" }

[webmaster128]

We should make sure it is normalised to be Cosmos SDK gas so people can compare easily.

Hmm, cosmwasm-vm cannot do that. If this is needed we have to do the whole journey from contract into chain like we do with e.g. api.addr_humanize, just without a return value.

[dakom]

I don't quite see how cosm-orc would be able to capture this info, since it merely logs the final gasUsed via the execution result (same thing we get with other clients like cosmjs)

More to the point - if these logs only appear on the Go side, that's understandable, but can someone please point me to where I can direct that debug output to a file? (stdout spits a lot of stuff! I'd like to be able to have a debug file with just debug messages)

In a pinch I've added my own file logging to wasmd, but I'm sure I was re-inventing this particular wheel and just missed it in the docs...

[ethanfrey]

Thanks for the input @dakom these are open questions.

I think we agree on the need to do so, now we figure out how to do so in the best way.
Converting gas unit and figuring out where to output to be easily visible have proven to be important questions. Let's keep discussion in this issue, and you are welcome to make suggestions. Especially giving some idea of your ideal setup as a user of this.

[dakom]

Ah, okay, gotcha.

In terms of the contract side:

1. It would be nicer to receive the gasUsed via like a fn gas_used(&self) -> u64 call on the api, so that contracts can decide how to log it (or even emit an event). From the discussion above, it seems like this is not possible, and that's okay :)

2. If that's not possible, then can it be done via a callback, like fn log_gas_used(&self, f: impl FnOnce(u64) -> String) ?

3. If that's not possible, then the suggested approach of logging it with an optional message string makes sense and would still be super helpful!

To be clear, the callback approach would be something like:

let some_contract_context = ...;

deps.api.log_gas_used(move |gas_used| {
  format!("gas used is {}. context: {:#?}", gas_used, some_contract_context)
});

Please note that this is a closure, not a function pointer. This is very important. It's fine for the FnOnce to be 'static though (note the move above)

In terms of the chain logging side:

I am not sure of the current capabilities, but I would like to have a separate (and configurable) wasm.log file that only contains things that go through wasm logging.

So for example, there could be a general deps.api.log() which writes to this wasm log file, and then deps.api.log_gas_used() builds on that.

I'm also a fan of some sort of structured logging, even just basic info/warn/error differentiation and a verbosity flag, but this is less essential (i.e. with the above I'm free to do my own string formatting and logic to supress logs, so it's not a big deal)

---

I'm also going to share some thoughts and experiences which may be helpful to get a sense of where I face friction. I expect there are no surprises here, and some of these thoughts have already been shared elsewhere, but I think it's worthwhile to add here:

• Local in-memory tests are much more pleasant than tests which require a full deploy. Even against a local chain with block time sped up, it is just so much faster to iterate with multi-test and unit tests.

• I have been unable to build a perfectly accurate virtual gas calculator. I've taken into account invocation cost, storage (including json/base64), smart queries, and hooked up the vm to get computational costs. Somehow, in real-world deploys there are extra costs sneaking in that I haven't been able to account for yet (even just baseline invocation, it's 120_000+ whereas I'd think it should be like 60_000). This point is a bit long-winded, but what I'm getting at is that even though local in-memory tests are faster and my preference, for accurate gas estimation I typically deploy on a local chain.

• Local chain tests are more pleasant than remote testnet. Mostly because of the ability to speed up block time

• I am starting to get my feet wet with wasmd instead of relying on localjuno / localosmosis / etc. It's new territory for me as of now, but testing capabilities that have only landed in wasmd but not third-parties are completely acceptable.

• It's acceptable that this sort of debug capability would be done against a local chain deploy (with sped up block time) and not exist on any testnet deploy, even if/when it lands in juno/osmosis/etc.. Sometimes, I kinda need to test on a remote testnet deploy, no matter how slow, e.g. due to state which was created gradually by users, but that's life.

• All the above means that debugging gas issues is often a very painful process of re-compiling contracts with either feature-gating or some stateful logic to break early, log out the gas, and try again. It is not only painful, it's slow, and this also means conditions can change between deploys.

---

Tangential point: 100% accurate gas reports in multi-test, with ability to poke at any time during contract lifecycle. Would be amazing! I assume this is just not possible for a variety of reasons, which is why we're only talking about logging on the chain side.

[ethanfrey]

Thank you for those real-world experiences and requests on your work flow. Great help to direct this development.

Currently deps.api.debug (which we would likely extend with gas info) is handled completely in rust (log to stdout) just a boolean flag on the constructor to optionally enable it (and avoid log pollution on production).

Providing things like cosmos sdk gas value, or logging anywhere besides stdout/stderr (like some file set by go flags) would require integration with the Go side. Which, while not impossible, would greatly increase the scope and repos required. If that is required for a usable functionality, we need to consider that.

100% accurate gas reports in multi-test, with ability to poke at any time during contract lifecycle. Would be amazing!

Ideally... we could possibly provide accurate cost for storage and calling wasm to wasm contracts, but we cannot properly simulate bank (even passing funds between wasm contracts), staking, etc as those have native Go implementations and the cost and implementation may (and does) change between minor releases of the cosmos sdk. Furthermore, there is a more or less fixed cost of say 50-60k per transaction for the ante-handlers, tx size, sig verification, deducting fees, etc etc that we cannot address. Testing against a local node with proper Cosmos SDK version / binary is the only way to get those correct numbers.

[ethanfrey]

Update: we cannot measure gas costs for contract execution as we run them in Rust (not wasm), so we don't meter instructions. We also have no hooks for gas metering in the existing framework

[dakom]

Ahh, okay... I see how to use the stdout debug logging now. For anyone landing here and getting their feet wet with this:

1. wasmd start --log_level panic --trace (panic may be a bit extreme - point is some level lower than info, which is just way too noisy to see anything)
2. deps.api.debug() messages will now appear in the wasmd console

@ethanfrey I think what confused me, in case this makes its way into documentation, is that for contract developers we're usually just told to start some local chain instance without any tips for silencing the massive amount of logs, and debug messages also don't appear by default. Combined with the fact that we can just call println!() directly in multi-test/unit-tests, tbh deps.api.debug() is just not something I've ever even used before ;)

Currently deps.api.debug (which we would likely extend with gas info) is handled completely in rust (log to stdout) just a boolean flag on the constructor to optionally enable it (and avoid log pollution on production).

Digging a bit deeper, is that here?

cosmwasm/packages/vm/src/imports.rs

Line 353 in 942a346

pub fn do_debug<A: BackendApi, S: Storage, Q: Querier>(

If so, can we not have a do_env_callback() that takes a callback_ptr instead of a message_ptr, and passes a reference to Environment in? Or, alternatively, do_gas_callback() with the same idea?

I would be happy to experiment with this a bit, but I'm not entirely clear on the full path from api.debug() in a contract, to do_debug() here... e.g. is it going back and forth over the Go FFI somewhere? any pointers (pun not intended!) would be appreciated

[dakom]

Update: we cannot measure gas costs for contract execution as we run them in Rust (not wasm), so we don't meter instructions. We also have no hooks for gas metering in the existing framework

Bummer... In the meantime, I was digging further into the codebase.

Is my understanding here at least correct-ish?

1. the vm crate exports do_debug()
2. the vm crate makes this available via an environment export
3. .... (I am not sure about this step! ... it seems the vm injects this export into std somehow by way of Wasmer Exports, but I don't see exactly how that works yet..)
4. the std crate binds to some FFI debug()
5. the std crate calls debug() in ExternalApi

[webmaster128]

Is my understanding here at least correct-ish?

Yes, pretty good. Just some hints that help better understand the codebase:

• debug is not an export but an import In the sense of the Wasm specification. The contract requires this import and the VM provides this import. An export is something else.
• Point 3 is done here:

  cosmwasm/packages/vm/src/instance.rs

  Line 230 in 942a346

  WasmerInstance::new(module, &import_obj)

  The VM provides the import implementation to the contract when the contract is instantiated.
• Nothing here is really FFI. We just need the extern "C" block in the Rust source code to tell the compiler to create an required import when compiling to Wasm. extern "C" { fn debug(source_ptr: u32); } compiled to the required import "env.debug".

I think we should track the deps.api.debug output separately. It is pretty straight forward and can be made configurable in Rust or Go code. This was requested by another project as well. I just did not touch this so far because I'd like to do it after the Wasmer 3 upgrade if it is not urgent.

[dakom]

Thanks for the tips @webmaster128

I am stopping for today... but to pick up tomorrow, is this roughly how to make local changes to the vm so I can hack around and try stuff out?

SETUP

1. in wasmd go.mod replace( github.com/CosmWasm/wasmvm => path/to/my/wasmvm)
2. in local wasmvm edit libwasmvm's Cargo.toml to point at a local cosmwasm-vm via path = ...
3. generally point at local crates as-needed (e.g. a local cosmwasm-std, local cw-storage-plus, etc.)

ITERATIVE DEV

1. Make changes in local cosmwasm-vm
2. recompile the libwasmvm (make build-rust in wasmvm)
3. rebuild wasmd so it will use this new wasmvm build (LEDGER_ENABLED=false make install on osx)

edit: the above works, I can see custom changes in do_debug() 🎉

[dakom]

fwiw, I added this into do_debug() locally:

println!("GAS LEFT: {}", env.get_gas_left());
env.with_gas_state(|gas_state| {
    println!("GAS STATE: {:?}", gas_state);
});

and called deps.api.debug() at the beginning and end of the execution handler

In a contract that does pretty much nothing, the actual result gas used is 120_855, but we get here:

BEGIN EXECUTION
GAS LEFT: 2477255900000
GAS STATE: GasState { gas_limit: 2480660000000, externally_used_gas: 0 }

END EXECUTION
GAS LEFT: 2477116700000
GAS STATE: GasState { gas_limit: 2480660000000, externally_used_gas: 0 }

And when saving some item to storage, the actual result gas used is 126_806, but we get here:

BEGIN EXECUTION
GAS LEFT: 3528976600000
GAS STATE: GasState { gas_limit: 3532900000000, externally_used_gas: 0 }


END EXECUTION
GAS LEFT: 2727001650000
GAS STATE: GasState { gas_limit: 3532900000000, externally_used_gas: 800800000000 }

I am really not sure what to make of these numbers or if they correlate to anything meaningful

[ethanfrey]

Welcome to the core of cosmwasm-vm @dakom you are brave 😄

Few people out of Confio have dug so deep. I can't dig more right now, just want to commend you for your perseverance. I'd be happy for a good solution and glad you can try to customise yourself to test this out.

[dakom]

Thanks @ethanfrey , that is very kind!

[dakom]

Btw while I am still not sure on what to make for the raw gas_left, the externally_used_gas comes very close to adding up to what I'd expect for the storage cost. Progress :)

Breakdown

config

WRITE_COST_FLAT = 2000
WRITE_COST_PER_BYTE = 30
GAS_MULTIPLIER = 140_000_000

on-chain result

externally_used_gas = 5720 SDK gas = 800_800_000_000 / GAS_MULTIPLIER

expectation

5840 SDK gas = 2000 + ((112 + 16) * 30)

expectation calculation

fn storage_binary_len(data: &impl Serialize) -> usize {
    // to_vec is ultimately a wrapper around serde_json_wasm::to_vec
    let bytes:Vec<u8> = cosmwasm_std::to_vec(data).unwrap();
    let bytes_len = bytes.len();

    // however, I think it gets written as base64, which adds a bit of extra bloat
    ((bytes_len as f32 / 3.0).ceil() * 4.0) as usize
}

let foo_size = storage_binary_len(&Foo::new()); // 112
let item_namespace_size = storage_binary_len("item-foo"); // 16
let store_foo_item_cost = WRITE_COST_FLAT + ((foo_size + item_namespace_size) * WRITE_COST_PER_BYTE); //5840

[dakom]

Two thoughts to jot down here before I forget...

What I said above about passing a closure is probably a bad idea since it could be used for non-determinism.

If it's at all possible to pass a callback, it should be a function pointer

However, even before kicking the tires on that, I am not sure it's possible to guarantee it on a type level, since it ultimately gets interpreted from a plain integer pointer on the VM side. So even if std guaranteed the signature of debug(), someone could replace that with a different debug()

More generally, having the VM interpret a pointer as a function and call it just feels like a security hazard to me.

So I'm in favor of just logging the gas alongside the string-message

more of a note to self: what bothers me about the difference in my external gas used calculation isn't that it's inexect, it's that the estimation which only accounts for the raw storage bytes is higher.. I'd expect it to be lower if there's a difference. Next step would be to find where the base64 encoding is actually happening, if it's happening, and use that to remove a bit of guesswork

[ethanfrey]

Those calculations look write. This is running in a (forked) wasmd instance, right?

// however, I think it gets written as base64, which adds a bit of extra bloat
    ((bytes_len as f32 / 3.0).ceil() * 4.0) as usize

It does not. Only Binary fields are base64 encoded. We store them just as-is (raw JSON object in storage).

If we don't multiply with that factor, we get 2000 + (84 + 16) * 30 = 5000 Or 720 gas less than expected.

Did you calls deps.api.addr_verify() anywhere? (which also charges external gas) or make any other query?

[ethanfrey]

Can you share the execute function you are checking here? And the re-calculation. Value is not base64 encoded. If you are using an Item, the key length is the un-encoded since of the key. (Maybe with 2 byte length prefix). That would be 8 here.

Huh, if I do that, I get expected gas of 2000 + (84 + 8) * 30 = 4760 to be 960 gas less than measured.

[ethanfrey]

There are charged for the response size and events returned. But I assume this measurement is inside the contract, so that wouldn't be there.

If you are forking, you could instrument the Basic GasMeter in cosmos-sdk to report every charge: https://github.com/cosmos/cosmos-sdk/blob/v0.45.9/store/types/gas.go#L90-L101

[dakom]

Interesting leads!

Did you calls deps.api.addr_verify() anywhere? (which also charges external gas) or make any other query?
Can you share ...

Here is the execute function:

pub fn execute(deps: DepsMut, _env: Env, _info: MessageInfo, msg: ExecuteMsg) -> Result<Response> {
    deps.api.debug(&format!("BEGIN {:?}", msg));
    match msg {
        //... 
        ExecuteMsg::StoreItem {rounds} => { 
            let foo = Foo::default();
            for _ in 0..rounds {
                STORE_ITEM.save(deps.storage, &foo)?;
            }
        }
        //...
     }
    deps.api.debug(&format!("END {:?}", msg));
    Ok(Response::new())
}

And I am calling it now with rounds: 1. I could try taking out the execute message, maybe that counts toward something?

Here is Foo. I deliberately made it somewhat complex, to cover the various use cases. Maybe I should simplify to just raw bytes as a starting point:

use serde::{de, ser, Deserialize, Deserializer, Serialize};
use std::fmt;
use cosmwasm_std::{StdError, StdResult};
use cw_storage_plus::{Key, KeyDeserialize, Prefixer, PrimaryKey};

/// Foo
#[derive(Serialize, Deserialize, Clone, Debug, PartialEq)]
pub struct Foo {
    pub string: String,
    pub int: u32,
    pub nested: Bar,
    pub custom: Custom
}

impl Foo {
    pub fn default() -> Self {
        Self {
            string: "Foo".to_string(),
            int: 42,
            nested: Bar::default(),
            custom: Custom::default()
        }
    }
}


/// Bar
#[derive(Serialize, Deserialize, Clone, Debug, PartialEq)]
pub struct Bar {
    pub string: String,
    pub int: u32,
}

impl Bar {
    pub fn default() -> Self {
        Self {
            string: "Bar".to_string(),
            int: 70
        }
    }
}

/// Custom
#[derive(Clone, Debug, PartialEq)]
pub struct Custom {
    pub string: String,
    pub int: u32,
}

impl Custom {
    pub fn default() -> Self {
        Self {
            string: "Custom".to_string(),
            int: 1337
        }
    }
}

/// Serializes as a string for serde
impl Serialize for Custom {
    fn serialize<S>(&self, serializer: S) -> Result<S::Ok, S::Error>
    where
        S: ser::Serializer,
    {
        serializer.serialize_str(&format!("{}|{}", self.string, self.int))
    }
}

/// Deserializes as string for serde
impl<'de> Deserialize<'de> for Custom {
    fn deserialize<D>(deserializer: D) -> Result<Custom, D::Error>
    where
        D: Deserializer<'de>,
    {
        deserializer.deserialize_str(CustomVisitor)
    }
}

struct CustomVisitor;

impl<'de> de::Visitor<'de> for CustomVisitor {
    type Value = Custom;

    fn expecting(&self, formatter: &mut fmt::Formatter) -> fmt::Result {
        formatter.write_str("string-encoded custom data struct")
    }

    fn visit_str<E>(self, s: &str) -> Result<Self::Value, E>
    where
        E: de::Error,
    {
        let mut iter = s.split("|");
        let part_1 = iter.next().ok_or_else(||
            E::custom(format!("Error parsing custom '{}'", s))
        )?;
        let part_2 = iter.next().ok_or_else(||
            E::custom(format!("Error parsing custom '{}'", s))
        )?;

        let part_2:u32 = part_2.parse().map_err(|err| {
            E::custom(format!("Error parsing custom '{}', {}", s, err))
        })?;

        Ok(Custom {
            string: part_1.to_string(),
            int: part_2
        })
    }
}


/// CustomKey
#[derive(
    Debug, Clone, PartialEq, PartialOrd, Ord, Eq, Serialize, Deserialize, Hash,
)]
pub struct CustomKey(pub String);

impl<'a> PrimaryKey<'a> for CustomKey {
    type Prefix = ();
    type SubPrefix = ();
    type Suffix = Self;
    type SuperSuffix = Self;

    fn key(&self) -> Vec<Key> {
        let key = Key::Ref(self.0.as_bytes());

        vec![key]
    }
}

impl<'a> Prefixer<'a> for CustomKey {
    fn prefix(&self) -> Vec<Key> {
        let key = Key::Ref(self.0.as_bytes());
        vec![key]
    }
}

impl KeyDeserialize for CustomKey {
    type Output = CustomKey;

    #[inline(always)]
    fn from_vec(value: Vec<u8>) -> StdResult<Self::Output> {
        String::from_utf8(value)
            .map_err(StdError::invalid_utf8)
            .map(CustomKey)
    }
}

impl fmt::Display for CustomKey {
    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
        write!(f, "{}", self.0)
    }

Gotta go for now, happy to follow-up next week :)

[webmaster128]

I'm removing this from the milestone as it is currently not clear how to solve the issue

[maurolacy]

This is very useful.

In the same way that the mock instance provides get_gas_left(), there should be a similar call for non-mocked contract code (deps.api.get_gas_left() or so), that can be used to instrument code and measure performance.

Will do a PR for it.

[maurolacy]

Another useful profiling / benchmarking tool: a trace() call that provides timestamps from the system clock.

This can be enabled only with --trace, like debug(). Moreover: if the node is running in non-local (i.e. blockchain) mode, this can be made a no-op (or fallback to debug()). So, to enable it you require --trace along with the node in local mode (if that can be determined easily / robustly enough).

Another option could be to make this method feature-gated or build-gated. So that if you compile cosmwasm-vm for release, by example, it is a no-op / fallbacks to debug().

Or better: Just print the timestamps to stdout, do not return them to the contract.

Will provide a PR for it.

[webmaster128]

The debug handler is now fully customizable (pretty much what Mauro suggested but without the need for a new API). See the current default in libwasmvm:
https://github.com/CosmWasm/wasmvm/blob/v1.5.2/libwasmvm/src/calls.rs#L476-L482

So if you set the debug print flag in wasmvm to true, you get the above printed to STDERR. If you fork libwasmvm, you can use your own handler. Changing cosmwasm-vm is not needed anymore.

From the contract you trigger a call to theis handler with deps.api.debug("note to myself").

Closing for now. If you need more than that, let's refine.