Why does the cpu usage reported by top change when console_subscriber is enabled?

[juliusl]

When I enabled console_subscriber I notice that the cpu usage ends up dropping in top

Is this expected behavior?

[hds]

This is not expected. Are you able to share some more details about the application that you're instrumenting? Once you enable the console-subscriber, does it still perform about as well?

It seems like if you're running a multi-threaded runtime, something might be blocking it (hence the much lower CPU usage).

[juliusl]

Are you able to share some more details about the application that you're instrumenting?

It's basically two http servers (tcp listeners) w/ poem, I think this where the tasks are being spawned (https://github.com/poem-web/poem/blob/b1bf63404781a6fdcd7c14e4affd9e3bd5585ed6/poem/src/server.rs#L168). Tokio is running in multi-thread w/ .enable_all() and no other customizations. I tested in several configurations but I tried to narrow it down to as bare-bones as possible to narrow it down to console-subscriber. I also tried running without console-subscriber but w/ tokio_unstable/tracing feature to see if it was that, but it only repros when I add console-subscriber to tracing. I am configuring my tracing_subscriber registry so I am using console_subscriber::spawn() like so:

    let console_layer = console_subscriber::spawn();
    std::env::set_var("RUST_LOG", "tokio=trace,runtime=trace");
    tracing_subscriber::registry()
        .with(console_layer)
        .with(fmt::layer())
        .with(EnvFilter::from_default_env())
        .init();

I'm also running on ubuntu 22.04 in WSL2 if that gives any more clues.

Once you enable the console-subscriber, does it still perform about as well?

As far as I can tell it seems to be running about the same, but I spent most of my time trying to figure out what was changing the top usage so I didn't get around to running a benchmark. When I was tinkering, these servers are just at idle listening for connections.

It seems like if you're running a multi-threaded runtime, something might be blocking it (hence the much lower CPU usage).

I was thinking that at first but, top -H shows multiple tokio-runtime-w so I'm assuming worker threads are running? Also tokio-console seemed to be showing multiple workers but I'm not sure if that's evidence enough.

Maybe I could try reproing w/ mini-redis?

[hds]

When I was tinkering, these servers are just at idle listening for connections.

Were the servers idle when you recorded the 863% CPU from the first measurement? This seems like a lot for a web server not doing anything (70% also seems like a lot for a web server not doing anything).

Given that you're already filtering globally for what the console-subscriber would filter for, and that this behavior doesn't happen when you have the fmt::layer() in the same configuration, it seems like maybe the console-subscriber is slowing things down.

Do you observe this behavior immediately upon starting the application, or does it take some time? Did you have a tokio-console connected at the time you saw this behavior or is the console-subscriber running without connections?

Maybe I could try reproing w/ mini-redis?

That would be amazing if you could!

[juliusl]

Were the servers idle when you recorded the 863% CPU from the first measurement? This seems like a lot for a web server not doing anything (70% also seems like a lot for a web server not doing anything).

Agreed, which is originally why I was trying to use console-subscriber to figure out what was going on, so when the usage dropped I was really surprised.

Do you observe this behavior immediately upon starting the application, or does it take some time?

The former

Did you have a tokio-console connected at the time you saw this behavior or is the console-subscriber running without connections?

For the screenshots I posted that was w/o tokio-console running, but I observed the same behavior with it enabled.

[hds]

At this point, I would try running cargo flamegraph on each of the cases and look at where the CPU time is being spent.

I'd be happy to look at the results (actually I would love to look at the results, I'm really curious now).

[juliusl]

Hah, so I figured out what the usage was.

There were several places where I was calling wake_by_ref() incorrectly. My future implementation was wrapping a task and instead of relying on the task to call wake_by_ref() I was calling wake_by_ref() whenever poll_unpin returned Pending. Big oops. After I fixed that the cpu usage dropped back down to 0%.

The drop in usage is probably due to console-subscriber slowing the polling rate down, but since tracing was still emitting events I was able to see the unusual flux of events coming from tokio. Mini-redis is completely silent btw, so that gave me a hint that a constant flow of events during idle is unusual.

console_subscriber for the win!

[hds]

Great! I'm glad you found the answer!

One question, did you see a warning on your task that you were self-waking a lot?

I would expect that to show up (becaues that's what you were doing if I understand correctly, waking the task from itself). I hadn't considered this error pattern, so it's probably worth adding into a description of reasons that might be causing the lint to trigger a warning.