4 ms·

I spent a lot of time trying to build a fast logging system in my last couple of jobs. The basic lesson (and I'm only talking about C/C++/C# here) is that you w

I spent a lot of time trying to build a fast logging system in my last couple of jobs. The basic lesson (and I'm only talking about C/C++/C# here) is that you will spend most of your time formatting strings if you do your file I/O asynchronously. Since this system has a preprocessor mode, I assume they learnt the same lesson. The bigger lesson is that it really doesn't matter how many millions of logs you can generate per second if you don't have the infrastructure to store and analyze them easily. No one is going to enjoy digging through these things and the more you generate, the harder it is to extract meaningful information. In other words, pay a lot more attention to what you'll do with the logs rather than how fast you can spew them out. I have rarely needed more than a few thousand log messages/sec even for a loaded MMO server. I spent way more time creating ways to look at these logs and making them accessible in near real time.

sharpshadow 7y ago
That's why I open comments first.. hypetaker +1
holy_city 7y ago
I've dealt with this problem too, mostly in trying to log/debug real-time media processing where a log trace equivalent would be long chunks of floating point data at multiple trace points in the data flow. I came to the same conclusion. Raw bandwidth to your logging endpoint is meaningless when you start dealing with big chunks of information, which is common sense I guess. You need a fast way to digest it into whatever format works for the person reading the log later, and it's tough to make it abstract since how data is interpretted can be quite varied even in the same application.
gpderetta 7y ago
> is that you will spend most of your time formatting strings if you do your file I/O asynchronously. That's why you are supposed to do your formatting in the background thread :). > doesn't matter how many millions of logs you can generate per second Usually the issue is not generating millions of line of logs (in whitch case dispatching to a background thread just adds overhead), but being able to log with minimal overhead on the surrounding code.
- Matthias247 7y ago
  > That's why you are supposed to do your formatting in the background thread :). Which then has the drawback that every argument that gets transferred to the background thread must first be heap allocated or static - instead of only the final buffer being that. My gut feeling is that the additional allocation and memory management costs typically outweigh the cost of formatting in the current thread. Even if one pools all logging buffers less buffers are needed for transferring only formatted buffers.
  - paulddraper 7y ago
    Or you'd copy them. Unless you do something dumb (like copy a vector when you only need to print the size), copying is significantly faster than string formatting.
    - dclusin 7y ago
      I think what OP is hinting at here is cache invalidation/eviction caused by the additional thread's processing and memory operations. If your requirements are down to nanosecond granularities then cache misses are probably being measured and noticeable. A third party logging thread doing memory copies and other log processing sounds like a fine way to unintentionally evict a bunch of cache entries. You might be able to mitigate this to some extent with CPU affinities for threads I suppose. Another option would be to move logging to the network and record packets in/out with an out of band monitoring solution.
      - paulddraper 7y ago
        Well yes, using another thread is a only good idea if you have an extra core available. L1 cache is per-core anyway, and I doubt L2 is going to hurt much.
      - Rapzid 7y ago
        Logging the raw structured log entry and off-loading any string formatting to another system is a very interesting idea. Just push the whole "friendly message" stuff off to other logging infrastructure where the latencies matter less.
profitnot 7y ago
This is, of course, true. Many fail with the mindset that if only they can build big enough haystacks, the needles will coalesce like shiny seaglass upon the shore, because surely they will hire the algorithmic wizards, and oh yes.. AI(!!) and ML(!!). Still, this really could have useful applications in scientific applications where the goal is to capture extremely fast events in detail... super-colliders, fast-fusion events, etc...
cjensen 7y ago
Your points about logging with care saving more cycles that logging efficiently is very right. That said, here's how I've handled efficient logging in realtime threads since the old days of 100MHz processors: postpone the formatting to a non-realtime thread. Assume your log_printf() will have no more than 10 int-sized args. Grab and save the 10 "ints". When doing the format in the non-realtime thread, pass in the 10 ints. Obviously this won't work with every CPU arch, but it does work fine for all the most common ones. Now every time you do a log_printf(), 1 pointer and 10 ints are copied to a buffer, which is very quick. The catch is that your format string must be not be changed (e.g. use a string literal). Also any strings you want to print must also be const.
cbsmith 7y ago
> you will spend most of your time formatting strings if you do your file I/O asynchronously Which is why good logging systems try to defer as much formatting logic as possible until the last possible moment (ideally render time). I wish more logging frameworks would log in some efficient intermediary serialization format like Cap'nProto or Protobuf.

sharpshadow 7y ago

That's why I open comments first.. hypetaker +1

holy_city 7y ago

I've dealt with this problem too, mostly in trying to log/debug real-time media processing where a log trace equivalent would be long chunks of floating point data at multiple trace points in the data flow. I came to the same conclusion. Raw bandwidth to your logging endpoint is meaningless when you start dealing with big chunks of information, which is common sense I guess. You need a fast way to digest it into whatever format works for the person reading the log later, and it's tough to make it abstract since how data is interpretted can be quite varied even in the same application.

gpderetta 7y ago

> is that you will spend most of your time formatting strings if you do your file I/O asynchronously. That's why you are supposed to do your formatting in the background thread :). > doesn't matter how many millions of logs you can generate per second Usually the issue is not generating millions of line of logs (in whitch case dispatching to a background thread just adds overhead), but being able to log with minimal overhead on the surrounding code.

Matthias247 7y ago
> That's why you are supposed to do your formatting in the background thread :). Which then has the drawback that every argument that gets transferred to the background thread must first be heap allocated or static - instead of only the final buffer being that. My gut feeling is that the additional allocation and memory management costs typically outweigh the cost of formatting in the current thread. Even if one pools all logging buffers less buffers are needed for transferring only formatted buffers.
- paulddraper 7y ago
  Or you'd copy them. Unless you do something dumb (like copy a vector when you only need to print the size), copying is significantly faster than string formatting.
  - dclusin 7y ago
    I think what OP is hinting at here is cache invalidation/eviction caused by the additional thread's processing and memory operations. If your requirements are down to nanosecond granularities then cache misses are probably being measured and noticeable. A third party logging thread doing memory copies and other log processing sounds like a fine way to unintentionally evict a bunch of cache entries. You might be able to mitigate this to some extent with CPU affinities for threads I suppose. Another option would be to move logging to the network and record packets in/out with an out of band monitoring solution.
    - paulddraper 7y ago
      Well yes, using another thread is a only good idea if you have an extra core available. L1 cache is per-core anyway, and I doubt L2 is going to hurt much.
    - Rapzid 7y ago
      Logging the raw structured log entry and off-loading any string formatting to another system is a very interesting idea. Just push the whole "friendly message" stuff off to other logging infrastructure where the latencies matter less.

profitnot 7y ago

This is, of course, true. Many fail with the mindset that if only they can build big enough haystacks, the needles will coalesce like shiny seaglass upon the shore, because surely they will hire the algorithmic wizards, and oh yes.. AI(!!) and ML(!!). Still, this really could have useful applications in scientific applications where the goal is to capture extremely fast events in detail... super-colliders, fast-fusion events, etc...

cjensen 7y ago

Your points about logging with care saving more cycles that logging efficiently is very right. That said, here's how I've handled efficient logging in realtime threads since the old days of 100MHz processors: postpone the formatting to a non-realtime thread. Assume your log_printf() will have no more than 10 int-sized args. Grab and save the 10 "ints". When doing the format in the non-realtime thread, pass in the 10 ints. Obviously this won't work with every CPU arch, but it does work fine for all the most common ones. Now every time you do a log_printf(), 1 pointer and 10 ints are copied to a buffer, which is very quick. The catch is that your format string must be not be changed (e.g. use a string literal). Also any strings you want to print must also be const.

cbsmith 7y ago

> you will spend most of your time formatting strings if you do your file I/O asynchronously Which is why good logging systems try to defer as much formatting logic as possible until the last possible moment (ideally render time). I wish more logging frameworks would log in some efficient intermediary serialization format like Cap'nProto or Protobuf.