LukeMathWalker / LukeMathWalker/tracing-bunyan-formatter

Performance issues

Open
#36 1 comment 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

Dominant language
Rust
Stars
112
Forks
44
PR merge metrics
No merged PRs in 30d

Description

Awesome crate. The only thing that got me interested in it was the execution time, as well as a request id. But, turns out there's a more simpler solution if you only care about these 2 additional info along side the name etc.

Was going throught it, and wanted to see whether there's a little overhead in return to this exceptionally well structured logging output. Turns out, the performance implication was more severe than I originally expected. More on the benchmark numbers later.

To achieve a unique `request_id` or `span_id` everytime on a new request + getting the time duration in milliseconds for that current function I fall back to `tracing::instrument` and `actix::Log`

### Adding a unique `request_id` using `tracing::instrument`
```rs
#[tracing::instrument(name = "Subscribe to newsletter", skip(db_connection), fields(span_id = nanoid::nanoid!()))]
async fn my_fn(
form: web::Form,
db_connection: web::Data,
) {}
```

### Showing request duration in millis
```rs
App::new().wrap(Logger::new("%{r}a Time taken: (%Dms) %s %r %{User-Agent}i").log_target("[ACTIX]"))
.app_data(db_pool.clone())
.service(health_check)
.route("/subscriptions", web::post().to(subscribe))
```
The output of this log is in this format -
```
2023-07-23T00:21:22.922595Z INFO Health Check: news_pubsub::routes::health:5: new span_id="Xic-R2tGcWj0zBd8hkUXG"
2023-07-23T00:21:22.922704Z INFO Health Check: news_pubsub::routes::health:7: Health check is OK span_id="Xic-R2tGcWj0zBd8hkUXG"
2023-07-23T00:21:22.922763Z INFO Health Check: news_pubsub::routes::health:5: close time.busy=57.3µs time.idle=121µs span_id="Xic-R2tGcWj0zBd8hkUXG"
2023-07-23T00:21:22.923020Z INFO [ACTIX]:421: 127.0.0.1 Time taken: (0.997000ms) 200 GET /health_check HTTP/1.1 Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/115.0.0.0 Safari/537.36
```

The `new` and `close` are the type of span events, that's mostly what we are concerned about. I specified to capture only those using the `FmtSpan::NEW | FmtSpan::CLOSE` value (shown below). Also we're capturing both the time for that request and the span_id for that particular request, which is usually enough to get out of the debug info.

# Benchmark
For a simple synthetic benchmark, I used `tracing_subscriber` and `tracing_bunyan_formatter` for comparison.

## Tracing disabled
With tracing completely disabled, I was hitting `143,000` requests per second.

## With `tracing_subscriber`
With the `tracing_subscriber` consumer I was getting around `129,000`-`133,000` requests per second.

```rs
let env_filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info"));
let log_file: rolling::RollingFileAppender = rolling::hourly("./logs", "Main_Log");
let (non_blocking, _guard) = tracing_appender::non_blocking(log_file);

tracing_subscriber::fmt()
.compact()
.with_env_filter(env_filter)
.with_ansi(false)
.with_line_number(true)
.with_writer(non_blocking)
.with_span_events(FmtSpan::NEW | FmtSpan::CLOSE)
.init();
```

## With `tracing_bunyan_formatter`
With the `tracing_bunyan_formatter` crate, I was only managing to hit `48,000` - `53,000` request per second, which is actually pretty low.

What could be causing this issue? Are there some tweaks I can try to do to get better results?

Contributor guide

No contributing guide indexed for this repository

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start by reproducing the reported benchmark comparison using tracing_subscriber, tracing_bunyan_formatter, and the shown FmtSpan::NEW | FmtSpan::CLOSE configuration. Compare the disabled, tracing_subscriber, and bunyan formatter request rates, then document the cause and a measurable improvement or confirmed limitation. No source files or tests are named in the issue.

Written by the indexing model from the issue text.

Assessment

Tech stack
rust
Domain
observability-sre, performance
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
25/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.