Skip to content

Commit

Permalink
Lightweight log macro (#32)
Browse files Browse the repository at this point in the history
* Add log standalone crate

* Refactored

* Fix return value

* Remove additional crate

* Tidy up

* Use memcpy

* Improve digit formatting

* Improve slice formatting

* Improve comments

* Add readme

* Update README.md

* Update README.md

* Remove doctests

* Use workspace values
  • Loading branch information
febo authored Nov 10, 2024
1 parent 5311c27 commit 40cb22a
Show file tree
Hide file tree
Showing 9 changed files with 905 additions and 1 deletion.
50 changes: 50 additions & 0 deletions Cargo.lock

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

9 changes: 8 additions & 1 deletion Cargo.toml
Original file line number Diff line number Diff line change
@@ -1,6 +1,13 @@
[workspace]
resolver = "2"
members = ["programs/system", "programs/token", "sdk/pinocchio", "sdk/pubkey"]
members = [
"programs/system",
"programs/token",
"sdk/log/crate",
"sdk/log/macro",
"sdk/pinocchio",
"sdk/pubkey",
]

[workspace.package]
edition = "2021"
Expand Down
18 changes: 18 additions & 0 deletions sdk/log/crate/Cargo.toml
Original file line number Diff line number Diff line change
@@ -0,0 +1,18 @@
[package]
name = "pinocchio-log"
description = "Lightweight log utility for Solana programs"
version = "0.1.0"
edition = { workspace = true }
license = { workspace = true }
readme = "./README.md"
repository = { workspace = true }

[dependencies]
pinocchio-log-macro = { version = "^0", path = "../macro", optional = true }

[lints.rust]
unexpected_cfgs = {level = "warn", check-cfg = ['cfg(target_os, values("solana"))'] }

[features]
default = ["macro"]
macro = ["dep:pinocchio-log-macro"]
79 changes: 79 additions & 0 deletions sdk/log/crate/README.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,79 @@
# <img height="70" alt="pinocchio-log" src="https://github.com/user-attachments/assets/caee2220-d11b-4b6a-aefd-6f6bd9815b73"/>

Lightweight log utility for Solana programs.

## Overview

Currently, logging messages that require formatting are a bit heavy on the CU consumption. There are two aspects when comes to determining the cost of a log message:

1. `base cost`: this is the cost of the log syscall. It will either be the [`syscall_base_cost`](https://github.com/anza-xyz/agave/blob/master/compute-budget/src/compute_budget.rs#L167) (currently `100` CU) or a number of CUs equal to the length of the message, whichever value is higher.

2. `formatting cost`: the compute units required to format the message. This is variable and depends on the number and type of the arguments. Formatting is performed using Rust built-in `format!` routines, which in turn use `format_args!`.

It is known that Rust formatting routines are CPU-intensive for constrained environments. This has been noted on both the `solana-program` [`msg!`](https://docs.rs/solana-program/latest/solana_program/macro.msg.html) documentation and more generally on [rust development](https://github.com/rust-lang/rust/issues/99012).

While the cost related to (1) is *fixed*, in the sense that it does not change with the addition of formatting, it is possible to improve the overall cost of logging a formatted message using a lightweight formatting routine &mdash; this is what this crate does.

This crate defines a lightweight `Logger` type to format log messages and a companion `log!` macro. The logger is a fixed size buffer that can be used to format log messages before sending them to the log output. Any type that implements the `Log` trait can be appended to the logger.

Below is a sample of the improvements observed when formatting log messages, measured in terms of compute units (CU):
| Ouput message | `log!` | `msg!` | Improvement (%) |
|------------------------------------|--------|--------------|-----------------|
| `"Hello world!"` | 103 | 103 | - |
| `"lamports={}"` + `u64` | 374 | 627 (+253) | 40% |
| `"{}"` + `[&str; 2]` | 384 | 1648 (+1264) | 76% |
| `"{}"` + `[u64; 2]` | 601 | 1060 (+459) | 44% |
| `"lamports={}"` + `i64` | 389 | 660 (+271) | 41% |
| `"{}"` + `[u8; 32]` (pubkey bytes) | 3147 | 8401 (+5254) | 62% |

> Note: The improvement in CU is accumulative, meaning that if you are logging multiple `u64` values, there will be a 40% improvement per formatted `u64` value.
## Features

* Zero dependencies and `no_std` crate
* Independent of SDK (i.e., works with `pinocchio`, `solana-program` or `anchor`)
* Support for `&str`, unsigned and signed integer types
* `log!` macro to facilitate log message formatting

## Getting Started

From your project folder:
```bash
cargo add pinocchio-log
```

## Usage

The `Logger` can be used directly:
```rust
use pinocchio_log::logger::Logger;

let mut logger = Logger::<100>::default();
logger.append("Hello ");
logger.append("world!");
logger.log();
```

or via the `log!` macro:
```rust
use pinocchio_log::log

let amount = 1_000_000_000;
log!("transfer amount: {}", amount);
```

Since the formatting routine does not perform additional allocations, the `Logger` type has a fixed size specified on its creation. When using the `log!` macro, it is also possible to specify the size of the logger buffer:

```rust
use pinocchio_log::log

let amount = 1_000_000_000;
log!(100, "transfer amount: {}", amount);
```
## Limitations

Currently the `log!` macro does not offer extra formatting options apart from the placeholder "`{}`" for argument values.

## License

The code is licensed under the [Apache License Version 2.0](LICENSE)
113 changes: 113 additions & 0 deletions sdk/log/crate/src/lib.rs
Original file line number Diff line number Diff line change
@@ -0,0 +1,113 @@
//! Lightweight log utility for Solana programs.
//!
//! This crate provides a `Logger` struct that can be used to efficiently log messages
//! in a Solana program. The `Logger` struct is a wrapper around a fixed-size buffer,
//! where types that implement the `Log` trait can be appended to the buffer.
//!
//! The `Logger` struct is generic over the size of the buffer, and the buffer size
//! should be chosen based on the expected size of the log messages. When the buffer is
//! full, the log message will be truncated. This is represented by the `@` character
//! at the end of the log message.
//!
//! # Example
//!
//! Creating a `Logger` with a buffer size of 100 bytes, and appending a string and an
//! `u64` value:
//!
//! ```
//! use pinocchio_log::logger::Logger;
//!
//! let mut logger = Logger::<100>::default();
//! logger.append("balance=");
//! logger.append(1_000_000_000);
//! logger.log();
//!
//! // Clear the logger buffer.
//! logger.clear();
//!
//! logger.append(&["Hello ", "world!"]);
//! logger.log();
//! ```
#![no_std]

pub mod logger;

#[cfg(feature = "macro")]
pub use pinocchio_log_macro::*;

#[cfg(test)]
mod tests {
use crate::logger::Logger;

#[test]
fn test_logger() {
let mut logger = Logger::<100>::default();
logger.append("Hello ");
logger.append("world!");

assert!(&*logger == "Hello world!".as_bytes());

logger.clear();

logger.append("balance=");
logger.append(1_000_000_000);

assert!(&*logger == "balance=1000000000".as_bytes());
}

#[test]
fn test_logger_trucated() {
let mut logger = Logger::<8>::default();
logger.append("Hello ");
logger.append("world!");

assert!(&*logger == "Hello w@".as_bytes());

let mut logger = Logger::<12>::default();

logger.append("balance=");
logger.append(1_000_000_000);

assert!(&*logger == "balance=100@".as_bytes());
}

#[test]
fn test_logger_slice() {
let mut logger = Logger::<20>::default();
logger.append(&["Hello ", "world!"]);

assert!(&*logger == "[\"Hello \", \"world!\"]".as_bytes());

let mut logger = Logger::<20>::default();
logger.append(&[123, 456]);

assert!(&*logger == "[123, 456]".as_bytes());
}

#[test]
fn test_logger_truncated_slice() {
let mut logger = Logger::<5>::default();
logger.append(&["Hello ", "world!"]);

assert!(&*logger == "[\"He@".as_bytes());

let mut logger = Logger::<4>::default();
logger.append(&[123, 456]);

assert!(&*logger == "[12@".as_bytes());
}

#[test]
fn test_logger_signed() {
let mut logger = Logger::<2>::default();
logger.append(-2);

assert!(&*logger == "-2".as_bytes());

let mut logger = Logger::<5>::default();
logger.append(-200_000_000);

assert!(&*logger == "-200@".as_bytes());
}
}
Loading

0 comments on commit 40cb22a

Please sign in to comment.