Looking into source of logging overhead

[houqp]

https://tech.marksblogg.com/roapi-rust-data-api.html mentioned that changing logging level from info to error resulted in 50% speed boost, this is certainly not expected :(

[Dandandan]

A part might be from sqlparser?
At least it might be better to move most of that logging to debug level instead of info.

[houqp]

@Dandandan I am not seeing info logging from sqlparser, looks like it's only using log::debug at the moment?

[houqp]

After taking a closer look, turns out the benchmark command used in the sample blog post is not using the rest api, not the sql api, so it by passes the sql planner entirely. The rest api arguments are mapped to dataframes directly. I tried removing actix-web's logging middleware and was able to confirm that this is the main source of bottleneck, which is very surprising :D

I am going to prioritize #76 instead instead of digging into the middleware code.

[Dandandan]

Ah yes - good find. Sounds like a good idea 👍

[marklit]

A few blogs ago I was given a tip to allocate let mut line = String::new(); ahead of time and use a buffer to print out. It had a pretty large impact on the codebase I was working on. You can find the src/main.rs where this technique is used here: https://tech.marksblogg.com/rdns-domain-name-tld-extract-rust.html

I'm not sure how much work it would be to patch Actix versus replace it entirely but I thought I'd throw this out there.

[houqp]

Thanks @marklit for the tip. I will verify the logging overhead once we moved to a new web framework and optimize it if it still turns out to be an issue.

[houqp]

I wrote a custom logger implementation at

roapi/roapi-http/src/layers.rs

Line 16 in 246bc6d

pub struct HttpLoggerLayer {}

, which reduces the RPS degradation to about 10% for requests completes in less than 1ms. The overhead should be much less noticeable for real world serving scenarios. So I am closing this issue for now until there is valid case to call for more optimizations.