Rust Audio

How to do logging in the real-time critical part

Hi all.

As the title says: does anybody have an idea how to achieve this? Until now, I simply use the simple log cate, but this is not suited in a real-time context (as are most, if not all, crates around logging). This doesn’t really matter when I only enable logging during debugging, but it still doesn’t feel right.

What are your strategies for this right now? Any suggestions?

I’m not experienced in the field, but I guess you could send logs via lock-free message queue (it seems crossbeam channels have non-blocking mode) from RT to some other thread, and then do the actual logging in that other thread.

That’s probably what I would do too, with the unfortunate side-effect that your timestamps wouldn’t be accurate.

Depending on what you’re doing, you might also consider doing the following things:

  • If your algorithm isn’t producing the sample values that you expect, debug it in a non-realtime context: move your DSP algorithm to a binary crate, and do something like println!("{}, {}", sample_number, sample_value)
  • If your algorithm isn’t fast enough, write a few benchmark tests to identify the slow part of the algorithm

You might also consider just logging from the real-time context anyway during debugging, and removing the logs after you’ve figured out what you needed to. This might not be good enough if you’re trying to debug timings; that’s going to be pretty difficult to do.

1 Like

The way SuperCollider handles it is that there is a message queue between the real time engine, and the NRT engine. And SuperCollider sends a log message with a timestamp to the NRT engine, which adds it to the log file at its leisure.

I barely know rust, but I think this is a general audio processing problem.

If you want to log some numeric values usually you’d also develop or hack some way to visualize it graphically. Writing to log is slow, but you can write to an array, and then display that array in an “oscilloscope” fashion, at frame rate speed. Some audio frames might go unseen.

Thank you for the answers!

I’m mostly concerned with the following question: how do you send the log-message to the other tread?
If you just want to log a string literal, it’s not a problem. But what about more complex messages?
The problem here is that you can’t send the formatted log message, because the string formatting inevitably uses heap allocation (or maybe you pre-allocate enough string buffers?).
So if you send “structured data” (instead of a formatted string) so to speak, then the Sender needs to know about the data type you want to send to the other thread.
But this is hard to do in a modular way because then the Sender needs to know about everything that may be logged anywhere in your application, even when your application is split up into different crates.

I’m thinking of two ways to solve this:

  1. Pre-allocate string buffers for holding the formatted text. The disadvantage here is that you need to send them back to the realtime tread for “recycling”.
  2. Have a Vec<Box<dyn LogReciever>> in the non-realtime thread and during setup, let each library send a Box<dyn LogReciever> to the non-realtime thread. Here each LogReciever is a trait that is implemented by Reciever<T> where `T`` is the data type of the structured data to be sent.

What do you think about this?

This no_std-friendly crate logs to a ring buffer without allocations:

IMO it’d probably still make more sense to log e.g. a ring buffer of enums so you can avoid the formatting overhead (and get structured logs for free in the process)

See also the same question on the rust users discourse.

(I just noticed this topic, sorry for the late answer!)

Actually, that’s not quite true! If the ring buffer you’re writing your logs into implements std::io::Write, then you can use the write! macro from the standard library on it, which does not perform any memory allocations.

This method still has a bit of overhead compared to just using a ring buffer of enums (especially float serialization can be tough), but much less than using intermediary string, and this has the advantage that the log receiver does not have to know anything about the logged items since they’re already just strings.

For example, this is what the LV2 Logging spec does, (well, hints towards rather, since LV2 does not require any implementation details) except it does it C-style by just exposing a printf-like function from the host.