Warp logger slow. Why?

help
1

Hi Guys! If I create a logger with pretty_env_logger, and apply it to create error log once the response code is 500, then my service performance drops from 11.500 req / sec to 8.000 req / sec. Do you have any advice? This is my code

let logger = warp::filters::log::custom(|info| {
        if info.status() == http::StatusCode::INTERNAL_SERVER_ERROR {
            log::error!(
                "log! {}{} - elapsed: {:?}",
                info.method(),
                info.path(),
                info.elapsed()
            );
        }
    });
2

Does your performance only drop that much when all of those requests are internal server errors, or does the performance also drop by just having that condition in your code, even though none of the request actually log anything?

3

Actually in my test I just have 200OK, and the performance dropped. By for a few hours I have been trying to figure it out, and one silly possibility is my laptop battery power mode. So maybe, its just something different. I need to get a server to test it out. But thank you!

All in all I do not know what is the reason of my performance drop. Now its vary between 6.000-9.000 req per sec. But in the early morning with the same code it was 11.000 req / sec. Soo strange. But I guess its not related to the logging.

4

Out of curiosity, how does the performance change if you use tracing instead of the pretty_env_logger logger?

5

I need to check. But without logging and tracing at all, the performance still vary between the same range. And thats really annoying, because yesterday the same wrk test using the same docker containers showed consistently 10.500 req / sec - 11.500 req / sec.

6

@alice I got something interesting. After my checks I removed completely all the logging codes, even I removed pretty_env_logger and log crated from my Cargo.toml. So removed everything from my code related to logging. And the performance was the same, dropped to ~8.000 req / sec.

And now I did a test. I used the same binary, but I started it with this:

RUST_LOG=trace ./target/release/api

And the performance gained back to 11.000 req / sec. The same code, the same binary, in the binary there is no logging at all, even there is no logging crates - in my code. And somehow this modifies the behavior of the crates related to my project.

Here is my code: https://github.com/gardenzilla/api/blob/master/src/main.rs

So now, using this trick, I do not know how, and why, but warp has the same amazing 11.000 req / sec performance.

7

Or maybe not... I checked again, and without that trick, now I constant have 11K req/sec performance. The only strange thing, if I run that binary directly from bash, I have 11K req/sec performance, if I put it in a docker container, but using the same port and etc, the same wrk test drops to 8K req/sec. But I saw 11K performance using it in a docker container yesterday. I have no idea whats going on. But 20-25% performance difference should mean something, and Docker should not burn that 20%.

8

To rule out Docker, can you run your test when

9

Ok, I have done it. Docker log none helped a bit, but still around 9K req / sec, instead of the 11K when I launch it without docker.

Here is my docker script:

service="api"
service_name="api_service"
docker run -d \
        --network host \
        -v $BASEDIR/data/${service}_space:/usr/local/bin/data \
        --name $service_name \
        --env-file ./ENV.list \
        --log-driver none \
        --restart always \
        $service_name
10

So now with 9K/s requests, host and none logging , how much does the throughput change when you enable RUST_LOG=trace?

Do you see similar drop when you run your test outside of docker, with stderr redirected to /dev/null?

11

Ok, so RUST_LOG=trace means 1.5K/sec, so very very low. RUST_LOG=error means 9K/sec - during the test there is no error at all.

12

I have tried the stderr redirection to /dev/null, and the performance dropped a bit to 9.5K-10.5K - based on 7 tests.

I used the following command:

RUST_LOG=error ./target/release/api 2> /dev/null
13

What does this mean?

14

To be consistent with the Docker environment, try it with RUST_LOG=trace ... so you're comparing apples to apples.

15

Yep, but getting a 1.5K result using trace, I switched to RUST_LOG=error, and that gave me 9K. So Apple to Apple now.

16

To tell the truth I find it a bit too difficult to follow which number was produced in which scenario. :slight_smile: I just wanted to make sure that the drop you see is not related to Docker and the way you're viewing/collecting log messages. We still want to generate as many log messages as we can (trace) while discarding all of them to measure how expensive it is to construct them.

There's definitely a performance hit. Depending on what you need you can try:

  • use tracing instead of logging and see if its sink implementation performs better than your logging backend
  • limit tracing to your program, ignoring traces from the dependencies (RUST_LOG=api=trace)
  • if you're in control of logging, some log messages might be too heavyweight/produce too much data so you can try to limit their size
1 Like
17

And could you help me to understand why the stderr redirection causes performance drop?

18

I'm afraid not. I wouldn't expect the redirection to reduce the performance. Perhaps it's the environment that's changing, background processes, etc. Difficult to say without running multiple tests over longer period of time.

2 Likes
19

This topic was automatically closed 90 days after the last reply. We invite you to open a new topic if you have further questions or comments.