8 ms·

Wait-free queueing and ultra-low latency logging

81 points by mortoray 12y ago

FooBarWidget 12y ago
It's a bit sad that all these low-latency approaches require burning CPU in a loop, which uses tons of power.
- fmstephe 12y ago
  In this particular case you should be able to use no-op instructions to spin without consuming much power. Since the consumer only spins when the queue is empty we know there will be space on the ring buffer and producers won't be impacted. When the consumer wakes from a no-op loop and finds work on the queue it can switch back to a hot loop for a certain amount of time before returning to a no-op cold loop. My understanding is that even having very small no-op pauses can significantly reduce the amount of energy used, and crucially heat generated, while only having a very modest impact on latency. A good fit for bursty low latency systems. To be clear, I am only relating something that another developer described to me. I've not actually implemented this myself. :)
  - mortoray 12y ago
    My loop continually checked the buffers and the locks, it never did a noop. Those fenced instructions are probably not the most power efficient. Power consumption was not a concern, latency was our primary goal.
  - a-priori 12y ago
    I think your colleague is talking about the PAUSE instruction (which is also known as REP NOP, since they encode to the same bytes). It's a special instruction that hints to the processor that it's in a spin-loop waiting on a synchronisation variable to change. It's used in tight wait loops like this: wait_loop: pause cmp eax, sync_var jne wait_loop The PAUSE instruction introduces a small delay to synchronise the spin loop to the memory bus frequency. This is a power savings, since the value of sync_var, as seen from the perspective of this code, can't change faster than that. Also, because the CPU can execute much faster than the memory bus, it prevents many memory requests from piling up while in the loop (because of out-of-order execution; those requests will have to be unrolled when the loop exits), making the loop faster to exit. Because of Hyperthreading, the pause also gives another thread a brief opportunity to execute on the same core. https://software.intel.com/sites/default/files/m/d/4/1/d/8/17689_w_spinlock.pdf https://software.intel.com/sites/default/files/m/d/4/1/d/8/1... Intel does, however, recommend other approaches to dealing with tight loops like this. See here: https://software.intel.com/en-us/articles/long-duration-spin-wait-loops-on-hyper-threading-technology-enabled-intel-processors/ https://software.intel.com/en-us/articles/long-duration-spin...
    - fmstephe 12y ago
      I take my hat off to you a-priori
      - a-priori 12y ago
        Glad to help :)
    - arielweisberg 12y ago
      How would there be many requests? Wouldn't it load the cache line once into the shared state and then spin waiting for the line to be invalidated before reloading?
      - a-priori 12y ago
        Honestly, I don't know how this interacts with cache lines. As far as I know, Intel has not released any official details about what the PAUSE instruction does other than that it slows down spin loops to a reasonable rate. The best source I know of for this information is the Intel® 64 and IA-32 Architectures Optimization Reference Manual (http://www.intel.com/content/dam/www/public/us/en/documents/manuals/64-ia-32-architectures-optimization-manual.pdf http://www.intel.com/content/dam/www/public/us/en/documents/...). It is fairly vague about what the instruction does, but gives some useful information in 13.5.3 "Spin-Wait Loops", as well as 8.4 "Thread Synchronization", and in particular 8.4.2 "Synchronization for Short Periods" which says: "On a modern microprocessor with a superscalar speculative execution engine, [a spin loop] results in the issue of multiple simultaneous read requests from the spinning thread. These requests usually execute out-of-order with each read request being allocated a buffer resource. On detection of a write by a worker thread to a load that is in progress, the processor must guarantee no violations of memory order occur. The necessity of maintaining the order of outstanding memory operations inevitably costs the processor a severe penalty that impacts all threads." So it seems that the concern here is that (without a PAUSE) the speculative execution engine effectively unrolls the spin loop and executes a sequence of reads on the sequence variable. This queues up a list of pending memory operations that need to be unrolled in order to ensure that the result is the same as if they were executed sequentially -- even though in this case it wouldn't make any difference.
- mortoray 12y ago
  It is very unfortunate. On that project we looked at all sorts of ways to avoid burning cores but they all had significant latency issues. If it involved going to the kernel then there was a major context switch overhead. But the big killer is the non-constant time. Each time you go to the kernel there's a danger of loosing your timeslice or being shunted to some other core. This leads to very high variance in performance. (I must always repeat though, this variance is not likely relevant in most applications.) So we spun in loops. And we had the CPUs set to maximum performance (no idle-time scaling). The total real load was probably less than 1%, so yes, it's very unfortunate.
- nkurz 12y ago
  It would seem like MONITOR/MWAIT (https://blogs.oracle.com/dave/resource/mwait-blog-final.txt https://blogs.oracle.com/dave/resource/mwait-blog-final.txt) would be the best of both worlds: extremely low-power and low-latency. But I see very little about it. Are there reasons that it's not more widely used?
easytiger 12y ago
I wonder about the implementation of the ringbuffer itself. Would boost::spsc_queue be suitable for a similar task?
- mortoray 12y ago
  That definitely looks like it's providing the same functionality my ring buffer did. It's impossible to say whether it is as efficient as mine was without profiling it. It's possible. Even if it's almost as efficient, or even half as efficient, I'd still consider using it. Writing this stuff consumes a lot of time. I notice the newest versions of this class added a "consume" function. I assume it's for the same reason my class did it. Instead of pushing/popping you can directly modify memory in the ring buffer. This avoids one copy operation.
  - easytiger 12y ago
    interesting, i've actually been oblivious to the mechanics when i'm using it (too much business logic to do). I'm also using it and burning a whole core doing a busy wait. I was going to try and fix this but i'm not sure how much i care. if we aren't paying for cpu time then it doesn't matter
ajtulloch 12y ago
For some excellent examples of concurrent queues in C++, Facebook's `folly` C++ library contains a really clean lock-free SPSC queue [1], and a really fast MPMC queue [2]. [1]: https://github.com/facebook/folly/blob/master/folly/ProducerConsumerQueue.h https://github.com/facebook/folly/blob/master/folly/Producer... [2]: https://github.com/facebook/folly/blob/master/folly/MPMCQueue.h https://github.com/facebook/folly/blob/master/folly/MPMCQueu...
- mortoray 12y ago
  Note it's important to be "wait-free" and not just "lock-free". The first item here does appear to be "wait-free".
  - fmstephe 12y ago
    I am curious about your definition of wait-free and lock-free. There are a number of conflicting definitions for these two terms floating around the internet. If we take a very simple problem, incrementing a shared counter and doing some other work and returning its new value. In pseudo-code (with no exception handling). --- A lock based solution would look like this public void inc() { this.l.lock() this.value++ this.l.unlock() } This has the crucial property that if a thread gets descheduled by the OS while it holds the lock no other thread can make progress until that thread has been restored and releases the lock. Importantly this is true whether we use user space spin locks or OS integrated locks. --- A lock-free solution would look like public void inc() { while(!compareAndSet(&this.value, this.value+1)) } This has the charming property that if a thread gets descheduled by the OS anywhere inside this method other threads will not be impacted. However, there is a pathological case where a single thread may repeatedly fail the call to compareAndSet(...). While this does mean that some other thread(s) must be making progress an unlucky thread may be delayed indefinitely. --- A wait-free solution for this on x64 would look like public void inc() { // do some inline assembly XADD this.value 1 // that's enough assembly } where the XADD instruction is guaranteed to always work atomically and safely regardless of how many other threads are also xadding to the same address. In practice wait-free algorithms are exceptionally complex and often slower than their lock-free counterparts. Wait-free techniques are most popular with academics (because they are so hard :) and with hard real-time systems because you can't risk failing indefinitely on a contended compareAndSet(...). This is a good explanation of what I understand to be lock-free and wait-free http://rethinkdb.com/blog/lock-free-vs-wait-free-concurrency/ http://rethinkdb.com/blog/lock-free-vs-wait-free-concurrency... Here is a really good discussion about it https://groups.google.com/forum/#!topic/mechanical-sympathy/Tm3xRcvpnzE https://groups.google.com/forum/#!topic/mechanical-sympathy/... Truly no flame intended. I just often find it hard to discuss these things over the net because of the range of possible definitions.
jzwinck 12y ago
It's unfortunate that literal strings in C++ cannot be programmatically distinguished from char* buffers. It would be useful if there were a separate type for literal strings which could implicitly decay to char* when needed. And functions should be able to return that type, because you may have "literal_string toString(MyEnum)" which always returns a literal string (or perhaps null). Also, yes, Boost has some lock-free stuff now. It didn't back when the author was writing the code described.
- mortoray 12y ago
  Yes, a string-literal type would be very helpful. In my Leaf language I have literal types. I think they offer some good optimiation abilities.
- humanrebar 12y ago
  There are user-defined string literals (1) in C++11. They can do pretty much whatever you want. Also, using templates it is trivial to distinguish between arrays of characters and character pointers. Finally, there is a proposal for a string_view (2), which could be used to represent string literals, no copies needed. (1) http://en.cppreference.com/w/cpp/language/user_literal http://en.cppreference.com/w/cpp/language/user_literal (2) http://www.open-std.org/jtc1/sc22/wg21/docs/papers/2013/n3609.html http://www.open-std.org/jtc1/sc22/wg21/docs/papers/2013/n360...
zwieback 12y ago
Nice writeup, enjoyed reading this. Instead of pointers to string literals, did you consider tokens instead, e.g. a big enum with a matching string table for the consumer? That's what we did in the past in device drivers although for space reasons instead of speed.
- mortoray 12y ago
  That's essentially what pointers to string literals are. They are indexes into a constant data segment which contains the actual strings.
  - zwieback 12y ago
    Very true. The main reason we used them were a) they can be smaller and b) can we flushed to disk for later decoding more easily and c) it's easier to implement a selective logging algorithm if you're only interested in certain events.
emerson_clarke 12y ago
Another approach is just to use two stacks, one for writing and one for flushing. User threads write log lines directly to buffers from an allocator usually via a TLS mediated stream. The use of an allocator avoids locking on system calls during memory allocation and minimizes copying between user code and eventual flush to disc/network. Buffers are written to the write stack using atomic CAS, if no buffers are available from the allocator the user thread may spin, or force a flush in the same way as the flushing thread. A single flushing thread watches the write stack on a timer and when it reaches some threshold it uses an atomic CAS to switch the head pointer between the flush and write stacks before enumerating the flush stack and writing all buffers to disc/network freeing the buffers back to the allocator (again using atomic operations). It is subtle but if done right user threads and the flushing thread interact optimally in response to demand. This solution is much more flexible than a ring buffer and also much simpler and faster in testing than any complicated patterns like disruptor and competitive with expensive hardware logging solutions. It recognizes the fact that much of the overhead in logging comes from expensive copying of log data in memory, and it also ensures that minimum context switching takes place which is essential if you are not to defeat the entire point of fast lock free algorithms. Unlike a ring bufffer it has no blocking or performance degredation when the buffer gets full and requires no large chunk of memory to be permanently allocated, although the allocator may periodically allocate new temporary memory if its buckets are full or if a log line is too large for a the maximum bucket size. What you end up with is a logging system where user threads are minimally impacted during writes and throughput is able to max out the disc/network.
- j_s 12y ago
  Thanks for sharing this technique. Are you aware of any existing open source implementations?
  - emerson_clarke 12y ago
    Unfortunately no, thus far i have only implemented it in a commercial context as part of a high frequency trading system.
userbinator 12y ago
> Profiling revealed that copying the format string was a significant part of the overall time. Not surprising. In general, memory allocations and copying are to be avoided unless absolutely necessary, if you want efficient code. I've made huge performance improvements to systems simply by getting rid of a memory copy that was located in a tight loop. As the saying goes, "the fastest way to do something is to not do it at all." Also, does anyone find the term "wait-free queueing" somewhat oxymoronic? A queue is usually something to wait in.
- mortoray 12y ago
  Well, only one side of the queue was wait-free. The other side, the consumer, was a whole mess of queues and buffers. It's simply the process of putting something in the queue that is fast. Getting out of that queue is a terribly slow operatino.
dllthomas 12y ago
Nice - this is pretty much exactly my solution to the same problem. One thing I noticed on my architecture (not sure how well it generalizes) is that explicitly flushing the cacheline from the sending core dropped cache misses quite a bit.
- nkurz 12y ago
  Do you mean flushing it with _mm_clflush()/CLFLUSH? Which architecture, and what's your use case? Any theories on why this was helping?
  - dllthomas 12y ago
    Right. Architecture is Sandy Bridge, use case is sending messages from one core to another. The theory is straightforward: After I populate a message slot (sized at 1 cache line) in the ring buffer I know I'm not going to need to do anything with that memory on that core anytime soon. Pre-emptively evicting it from cache in favor of something that has a greater chance of being used soon has a chance of avoiding a cache miss. There remains the question of whether the CPU can figure out enough of this on its own. Empirically, the answer was "no" in my case.
VikingCoder 12y ago
> A key requirement for logging is to write statements, from any thread, in order, to a single log-file. I do not agree that it's a necessary requirement that all threads must write to a single log-file. > Formatting strings, required by a log system, is a slow operation. I also do not agree that it's a necessary requirement that a log system must format strings. Binary log files have their uses. I've used Google Protocol Buffers quite happily. They may not be appropriate for extremely high-speed logs, like a low-latency trading system implies, but they have their uses. I'd be tempted to try something like Cap'n Proto, if I were taking a whack at it.
- kentonv 12y ago
  FWIW, CloudFlare uses Cap'n Proto for logging.
  - VikingCoder 12y ago
    Yeah, what do you know about it? ;-)
llogiq 12y ago
Note that log4j2, which can log asynchronously, uses the LMAX disruptor, which is a java implementation of the same technique.
zwieback 12y ago
Most of my high speed experience is in embedded systems with direct control over HW. Question: for these higher-level systems, is it possible to prevent preemption for a very short time? I'm guessing that a userland app can't do that easily but if it could then that would effectively give you larger atomic operations, which can aid in implementing lock-free solutions.
- javert 12y ago
  If I understand your suggestion, that only works when all the threads that share a critical section can only run on the same core. For instance, if you have a producer on core 0 and a consumer on core 1, even if the producer disables preemptions, the consumer can still enter the critical section (unless you protect it with locks). Off the top of my head I actually don't know if you can turn off preemptions from userspace in Linux, I've never needed to. You can give threads sched_fifo or sched_rr priorities that will prevent them from being interrupted by anything of lower priority (but that doesn't include the kernel itself... unless you are on preempt_rt and then there are things you can do).
  - zwieback 12y ago
    Yes, excellent point. Multi-core changes how critical sections would be implemented and whether they'd be useful at all.
lomnakkus 12y ago
I'm not sure if it's just me, but I found the lack of reference to system time interesting. Maybe it's one those things everyone does (but never talks about), but if you're logging, one of the absolute performance killers can actually turn out to be getting the system time via gettimeofday() or whatever. That's a syscall which involves a context switch, which... (It goes downhill from there.) Much better to just get the time every once in a while and cache it.
- nkurz 12y ago
  Historically this is true, but recent x64 Linux has made a lot of improvement here. In particular, gettimeofday() is usually optimized so as not to require a context switch: http://blog.tinola.com/?e=5 http://blog.tinola.com/?e=5. And then there are some even faster options that do the caching for you: https://access.redhat.com/site/documentation/en-US/Red_Hat_Enterprise_MRG/1.3/html/Realtime_Tuning_Guide/sect-Realtime_Tuning_Guide-General_System_Tuning-gettimeofday_speedup.html https://access.redhat.com/site/documentation/en-US/Red_Hat_E...

81 points by mortoray 12y ago

FooBarWidget 12y ago

It's a bit sad that all these low-latency approaches require burning CPU in a loop, which uses tons of power.

fmstephe 12y ago
In this particular case you should be able to use no-op instructions to spin without consuming much power. Since the consumer only spins when the queue is empty we know there will be space on the ring buffer and producers won't be impacted. When the consumer wakes from a no-op loop and finds work on the queue it can switch back to a hot loop for a certain amount of time before returning to a no-op cold loop. My understanding is that even having very small no-op pauses can significantly reduce the amount of energy used, and crucially heat generated, while only having a very modest impact on latency. A good fit for bursty low latency systems. To be clear, I am only relating something that another developer described to me. I've not actually implemented this myself. :)
- mortoray 12y ago
  My loop continually checked the buffers and the locks, it never did a noop. Those fenced instructions are probably not the most power efficient. Power consumption was not a concern, latency was our primary goal.
- a-priori 12y ago
  I think your colleague is talking about the PAUSE instruction (which is also known as REP NOP, since they encode to the same bytes). It's a special instruction that hints to the processor that it's in a spin-loop waiting on a synchronisation variable to change. It's used in tight wait loops like this: wait_loop: pause cmp eax, sync_var jne wait_loop The PAUSE instruction introduces a small delay to synchronise the spin loop to the memory bus frequency. This is a power savings, since the value of sync_var, as seen from the perspective of this code, can't change faster than that. Also, because the CPU can execute much faster than the memory bus, it prevents many memory requests from piling up while in the loop (because of out-of-order execution; those requests will have to be unrolled when the loop exits), making the loop faster to exit. Because of Hyperthreading, the pause also gives another thread a brief opportunity to execute on the same core. https://software.intel.com/sites/default/files/m/d/4/1/d/8/17689_w_spinlock.pdf https://software.intel.com/sites/default/files/m/d/4/1/d/8/1... Intel does, however, recommend other approaches to dealing with tight loops like this. See here: https://software.intel.com/en-us/articles/long-duration-spin-wait-loops-on-hyper-threading-technology-enabled-intel-processors/ https://software.intel.com/en-us/articles/long-duration-spin...
  - fmstephe 12y ago
    I take my hat off to you a-priori
    - a-priori 12y ago
      Glad to help :)
  - arielweisberg 12y ago
    How would there be many requests? Wouldn't it load the cache line once into the shared state and then spin waiting for the line to be invalidated before reloading?
    - a-priori 12y ago
      Honestly, I don't know how this interacts with cache lines. As far as I know, Intel has not released any official details about what the PAUSE instruction does other than that it slows down spin loops to a reasonable rate. The best source I know of for this information is the Intel® 64 and IA-32 Architectures Optimization Reference Manual (http://www.intel.com/content/dam/www/public/us/en/documents/manuals/64-ia-32-architectures-optimization-manual.pdf http://www.intel.com/content/dam/www/public/us/en/documents/...). It is fairly vague about what the instruction does, but gives some useful information in 13.5.3 "Spin-Wait Loops", as well as 8.4 "Thread Synchronization", and in particular 8.4.2 "Synchronization for Short Periods" which says: "On a modern microprocessor with a superscalar speculative execution engine, [a spin loop] results in the issue of multiple simultaneous read requests from the spinning thread. These requests usually execute out-of-order with each read request being allocated a buffer resource. On detection of a write by a worker thread to a load that is in progress, the processor must guarantee no violations of memory order occur. The necessity of maintaining the order of outstanding memory operations inevitably costs the processor a severe penalty that impacts all threads." So it seems that the concern here is that (without a PAUSE) the speculative execution engine effectively unrolls the spin loop and executes a sequence of reads on the sequence variable. This queues up a list of pending memory operations that need to be unrolled in order to ensure that the result is the same as if they were executed sequentially -- even though in this case it wouldn't make any difference.
mortoray 12y ago
It is very unfortunate. On that project we looked at all sorts of ways to avoid burning cores but they all had significant latency issues. If it involved going to the kernel then there was a major context switch overhead. But the big killer is the non-constant time. Each time you go to the kernel there's a danger of loosing your timeslice or being shunted to some other core. This leads to very high variance in performance. (I must always repeat though, this variance is not likely relevant in most applications.) So we spun in loops. And we had the CPUs set to maximum performance (no idle-time scaling). The total real load was probably less than 1%, so yes, it's very unfortunate.
nkurz 12y ago
It would seem like MONITOR/MWAIT (https://blogs.oracle.com/dave/resource/mwait-blog-final.txt https://blogs.oracle.com/dave/resource/mwait-blog-final.txt) would be the best of both worlds: extremely low-power and low-latency. But I see very little about it. Are there reasons that it's not more widely used?

easytiger 12y ago

I wonder about the implementation of the ringbuffer itself. Would boost::spsc_queue be suitable for a similar task?

mortoray 12y ago
That definitely looks like it's providing the same functionality my ring buffer did. It's impossible to say whether it is as efficient as mine was without profiling it. It's possible. Even if it's almost as efficient, or even half as efficient, I'd still consider using it. Writing this stuff consumes a lot of time. I notice the newest versions of this class added a "consume" function. I assume it's for the same reason my class did it. Instead of pushing/popping you can directly modify memory in the ring buffer. This avoids one copy operation.
- easytiger 12y ago
  interesting, i've actually been oblivious to the mechanics when i'm using it (too much business logic to do). I'm also using it and burning a whole core doing a busy wait. I was going to try and fix this but i'm not sure how much i care. if we aren't paying for cpu time then it doesn't matter

ajtulloch 12y ago

For some excellent examples of concurrent queues in C++, Facebook's `folly` C++ library contains a really clean lock-free SPSC queue [1], and a really fast MPMC queue [2]. [1]: https://github.com/facebook/folly/blob/master/folly/ProducerConsumerQueue.h https://github.com/facebook/folly/blob/master/folly/Producer... [2]: https://github.com/facebook/folly/blob/master/folly/MPMCQueue.h https://github.com/facebook/folly/blob/master/folly/MPMCQueu...

mortoray 12y ago
Note it's important to be "wait-free" and not just "lock-free". The first item here does appear to be "wait-free".
- fmstephe 12y ago
  I am curious about your definition of wait-free and lock-free. There are a number of conflicting definitions for these two terms floating around the internet. If we take a very simple problem, incrementing a shared counter and doing some other work and returning its new value. In pseudo-code (with no exception handling). --- A lock based solution would look like this public void inc() { this.l.lock() this.value++ this.l.unlock() } This has the crucial property that if a thread gets descheduled by the OS while it holds the lock no other thread can make progress until that thread has been restored and releases the lock. Importantly this is true whether we use user space spin locks or OS integrated locks. --- A lock-free solution would look like public void inc() { while(!compareAndSet(&this.value, this.value+1)) } This has the charming property that if a thread gets descheduled by the OS anywhere inside this method other threads will not be impacted. However, there is a pathological case where a single thread may repeatedly fail the call to compareAndSet(...). While this does mean that some other thread(s) must be making progress an unlucky thread may be delayed indefinitely. --- A wait-free solution for this on x64 would look like public void inc() { // do some inline assembly XADD this.value 1 // that's enough assembly } where the XADD instruction is guaranteed to always work atomically and safely regardless of how many other threads are also xadding to the same address. In practice wait-free algorithms are exceptionally complex and often slower than their lock-free counterparts. Wait-free techniques are most popular with academics (because they are so hard :) and with hard real-time systems because you can't risk failing indefinitely on a contended compareAndSet(...). This is a good explanation of what I understand to be lock-free and wait-free http://rethinkdb.com/blog/lock-free-vs-wait-free-concurrency/ http://rethinkdb.com/blog/lock-free-vs-wait-free-concurrency... Here is a really good discussion about it https://groups.google.com/forum/#!topic/mechanical-sympathy/Tm3xRcvpnzE https://groups.google.com/forum/#!topic/mechanical-sympathy/... Truly no flame intended. I just often find it hard to discuss these things over the net because of the range of possible definitions.

jzwinck 12y ago

It's unfortunate that literal strings in C++ cannot be programmatically distinguished from char* buffers. It would be useful if there were a separate type for literal strings which could implicitly decay to char* when needed. And functions should be able to return that type, because you may have "literal_string toString(MyEnum)" which always returns a literal string (or perhaps null). Also, yes, Boost has some lock-free stuff now. It didn't back when the author was writing the code described.

mortoray 12y ago
Yes, a string-literal type would be very helpful. In my Leaf language I have literal types. I think they offer some good optimiation abilities.
humanrebar 12y ago
There are user-defined string literals (1) in C++11. They can do pretty much whatever you want. Also, using templates it is trivial to distinguish between arrays of characters and character pointers. Finally, there is a proposal for a string_view (2), which could be used to represent string literals, no copies needed. (1) http://en.cppreference.com/w/cpp/language/user_literal http://en.cppreference.com/w/cpp/language/user_literal (2) http://www.open-std.org/jtc1/sc22/wg21/docs/papers/2013/n3609.html http://www.open-std.org/jtc1/sc22/wg21/docs/papers/2013/n360...

zwieback 12y ago

Nice writeup, enjoyed reading this. Instead of pointers to string literals, did you consider tokens instead, e.g. a big enum with a matching string table for the consumer? That's what we did in the past in device drivers although for space reasons instead of speed.

mortoray 12y ago
That's essentially what pointers to string literals are. They are indexes into a constant data segment which contains the actual strings.
- zwieback 12y ago
  Very true. The main reason we used them were a) they can be smaller and b) can we flushed to disk for later decoding more easily and c) it's easier to implement a selective logging algorithm if you're only interested in certain events.

emerson_clarke 12y ago

Another approach is just to use two stacks, one for writing and one for flushing. User threads write log lines directly to buffers from an allocator usually via a TLS mediated stream. The use of an allocator avoids locking on system calls during memory allocation and minimizes copying between user code and eventual flush to disc/network. Buffers are written to the write stack using atomic CAS, if no buffers are available from the allocator the user thread may spin, or force a flush in the same way as the flushing thread. A single flushing thread watches the write stack on a timer and when it reaches some threshold it uses an atomic CAS to switch the head pointer between the flush and write stacks before enumerating the flush stack and writing all buffers to disc/network freeing the buffers back to the allocator (again using atomic operations). It is subtle but if done right user threads and the flushing thread interact optimally in response to demand. This solution is much more flexible than a ring buffer and also much simpler and faster in testing than any complicated patterns like disruptor and competitive with expensive hardware logging solutions. It recognizes the fact that much of the overhead in logging comes from expensive copying of log data in memory, and it also ensures that minimum context switching takes place which is essential if you are not to defeat the entire point of fast lock free algorithms. Unlike a ring bufffer it has no blocking or performance degredation when the buffer gets full and requires no large chunk of memory to be permanently allocated, although the allocator may periodically allocate new temporary memory if its buckets are full or if a log line is too large for a the maximum bucket size. What you end up with is a logging system where user threads are minimally impacted during writes and throughput is able to max out the disc/network.

j_s 12y ago
Thanks for sharing this technique. Are you aware of any existing open source implementations?
- emerson_clarke 12y ago
  Unfortunately no, thus far i have only implemented it in a commercial context as part of a high frequency trading system.

userbinator 12y ago

> Profiling revealed that copying the format string was a significant part of the overall time. Not surprising. In general, memory allocations and copying are to be avoided unless absolutely necessary, if you want efficient code. I've made huge performance improvements to systems simply by getting rid of a memory copy that was located in a tight loop. As the saying goes, "the fastest way to do something is to not do it at all." Also, does anyone find the term "wait-free queueing" somewhat oxymoronic? A queue is usually something to wait in.

mortoray 12y ago
Well, only one side of the queue was wait-free. The other side, the consumer, was a whole mess of queues and buffers. It's simply the process of putting something in the queue that is fast. Getting out of that queue is a terribly slow operatino.

dllthomas 12y ago

Nice - this is pretty much exactly my solution to the same problem. One thing I noticed on my architecture (not sure how well it generalizes) is that explicitly flushing the cacheline from the sending core dropped cache misses quite a bit.

nkurz 12y ago
Do you mean flushing it with _mm_clflush()/CLFLUSH? Which architecture, and what's your use case? Any theories on why this was helping?
- dllthomas 12y ago
  Right. Architecture is Sandy Bridge, use case is sending messages from one core to another. The theory is straightforward: After I populate a message slot (sized at 1 cache line) in the ring buffer I know I'm not going to need to do anything with that memory on that core anytime soon. Pre-emptively evicting it from cache in favor of something that has a greater chance of being used soon has a chance of avoiding a cache miss. There remains the question of whether the CPU can figure out enough of this on its own. Empirically, the answer was "no" in my case.

VikingCoder 12y ago

> A key requirement for logging is to write statements, from any thread, in order, to a single log-file. I do not agree that it's a necessary requirement that all threads must write to a single log-file. > Formatting strings, required by a log system, is a slow operation. I also do not agree that it's a necessary requirement that a log system must format strings. Binary log files have their uses. I've used Google Protocol Buffers quite happily. They may not be appropriate for extremely high-speed logs, like a low-latency trading system implies, but they have their uses. I'd be tempted to try something like Cap'n Proto, if I were taking a whack at it.

kentonv 12y ago
FWIW, CloudFlare uses Cap'n Proto for logging.
- VikingCoder 12y ago
  Yeah, what do you know about it? ;-)

llogiq 12y ago

Note that log4j2, which can log asynchronously, uses the LMAX disruptor, which is a java implementation of the same technique.

zwieback 12y ago

Most of my high speed experience is in embedded systems with direct control over HW. Question: for these higher-level systems, is it possible to prevent preemption for a very short time? I'm guessing that a userland app can't do that easily but if it could then that would effectively give you larger atomic operations, which can aid in implementing lock-free solutions.

javert 12y ago
If I understand your suggestion, that only works when all the threads that share a critical section can only run on the same core. For instance, if you have a producer on core 0 and a consumer on core 1, even if the producer disables preemptions, the consumer can still enter the critical section (unless you protect it with locks). Off the top of my head I actually don't know if you can turn off preemptions from userspace in Linux, I've never needed to. You can give threads sched_fifo or sched_rr priorities that will prevent them from being interrupted by anything of lower priority (but that doesn't include the kernel itself... unless you are on preempt_rt and then there are things you can do).
- zwieback 12y ago
  Yes, excellent point. Multi-core changes how critical sections would be implemented and whether they'd be useful at all.

lomnakkus 12y ago

I'm not sure if it's just me, but I found the lack of reference to system time interesting. Maybe it's one those things everyone does (but never talks about), but if you're logging, one of the absolute performance killers can actually turn out to be getting the system time via gettimeofday() or whatever. That's a syscall which involves a context switch, which... (It goes downhill from there.) Much better to just get the time every once in a while and cache it.

nkurz 12y ago
Historically this is true, but recent x64 Linux has made a lot of improvement here. In particular, gettimeofday() is usually optimized so as not to require a context switch: http://blog.tinola.com/?e=5 http://blog.tinola.com/?e=5. And then there are some even faster options that do the caching for you: https://access.redhat.com/site/documentation/en-US/Red_Hat_Enterprise_MRG/1.3/html/Realtime_Tuning_Guide/sect-Realtime_Tuning_Guide-General_System_Tuning-gettimeofday_speedup.html https://access.redhat.com/site/documentation/en-US/Red_Hat_E...