LukeMathWalker / LukeMathWalker/tracing-bunyan-formatter
Performance issues
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
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- 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