common: update logging to enforce max_capacity and optimize queue resizing

[max-krasnyansky]

Overview

I'm working on adding more Op tracing to the hexagon backend and ran into an issue with our current logging implementation. If the logging rate is consistently much higher than the flushing rate then the queue will just keep growing and growing without any bounds eventually resulting in an exception when malloc finally fails.

This PR updates the logger to enforce max_capacity limit which is currently set to 4K entries.
I also re-wrote how the queue resizing is done. Now the producer threads are super simple they just block on full queue.
The consumer thread does all the resizing and flushing. Because the queue is only modified by the consumer thread we can get rid of all of the copies (ie for the current entry and when resizing).

Additional information

@ggerganov @CISC
I used a branch in the main repo. Feel free to update directly as needed.

Requirements

• I have read and agree with the contributing guidelines
• AI usage disclosure: Yes, just for the code review.

[max-krasnyansky]

@ggml-org/llama-common should we add NOMINMAX at the CMake level at this point? I just ran into that issue in common/log.cpp and I see that most other .cpp sources already have that. I think we should just set it in CMake at this point and remove from the individual files.

[max-krasnyansky]

@ggml-org/llama-common @ggml-org/maintainers
Folks, any comments / suggestions? If not can I get the approvals please.
About to start a PR on hexagon op-tracing support that triggers the issue I mentioned in the description here.

[max-krasnyansky]

@ggerganov sorry for bugging you.
I'm ready to un-draft #24592 but it needs this PR. When you get the chance please take a look. Thx.

[ngxson]

IMO this implementation is quite complicated in a way that it can be error-prone in the future if someone wants to expand it.

It smells like the expand_and_flush is just a linked list of multiple queues:

• When current queue is full, we swap it with a new one
• Consumer thread try to flush the old queue

Imagine if expand_and_flush is called multiple times in a large log calls surge, multiple "old queue" will be queued in the order of old_0 -> old_1 -> ... -> old_N and will be free in the same order, so just a linked list.

I believe that implementing a proper linked list of queues is the better approach here. While it's not less complicated than the current approach, it makes things explicit and easier to maintain in the long run.

[max-krasnyansky]

IMO this implementation is quite complicated in a way that it can be error-prone in the future if someone wants to expand it.

It smells like the expand_and_flush is just a linked list of multiple queues:

• When current queue is full, we swap it with a new one
• Consumer thread try to flush the old queue

Imagine if expand_and_flush is called multiple times in a large log calls surge, multiple "old queue" will be queued in the order of old_0 -> old_1 -> ... -> old_N and will be free in the same order, so just a linked list.

I believe that implementing a proper linked list of queues is the better approach here. While it's not less complicated than the current approach, it makes things explicit and easier to maintain in the long run.

Actually there is no additional queuing involved. That other PR I mentioned hits this exact expand case all the time.
There is only one old queue. If the producer threads happened to fill up the new expanded queue they'll just block while the old queue is being flushed. This happens 16 times (ie default 256 gets expanded 16 times till we hit the 4K max) and that's it, we reach the steady state. So the scenarios is basically q0-full, q1-expanded, q0-flushed, q1-full, q2-expanded, q1-flushed, ...
Makes sense?
I don't think we need to link the old queues, that would actually add complexity, this implementation seems to handle the expansion pretty smoothly.
If it helps to visualize I can add some instrumentation to log.cpp to demonstrate the sequence form my tests if needed.

[ngxson]

Actually there is no additional queuing involved. That other PR I mentioned hits this exact expand case all the time.
There is only one old queue. If the producer threads happened to fill up the new expanded queue they'll just block while the old queue is being flushed.

that's a linked list with max number of elements = 2, the linkage happens inside expand_and_flush

• log.cpp starts with Q0
• first time expand_and_flush is called, it creates Q1 that replaces Q0 --> try to flush Q0 --> free Q0
• next time it's called, Q2 replaces Q1 --> try to flush Q1 --> free Q1

If the producer threads happened to fill up the new expanded queue they'll just block while the old queue is being flushed.

Tbh if we expect it to be blocking at some points, then I would prefer the old, more simple way where the whole queue is resized and entries are moved.

The resize+move should be pretty fast, you can even optimize it to make it faster. example:

• queue is full: [....., head, tail, ......]
• resized queue: [....., head, tail, ......, (empty space)]
• shift elements: [....., head, (empty space), tail, ......]
• then update head/tail indexes

I don't think we need to link the old queues, that would actually add complexity, this implementation seems to handle the expansion pretty smoothly.

while a linked list adds complexity, it has these benefits:

1. being a generic approach where any software engineer with the right mind can understand at first glance
2. save on memory: the linked list can contain queues of same size, can be allocated and freed on demand. the current approach keeps the resized queue and never shorten it back to initial size

[ngxson]

that would actually add complexity

to clarify: this vibe-code version seems to be the same size as your PR here: master...ngxson:llama.cpp:xsn/demo_linked_list_log

so I don't think a linked list is that much (more) complicated

although, before diving to linked list approach, I'd suggest testing my assumption about optimizing resize queue + shift entries

edit: actually, CC comes up with an idea a bit clever than mine:

        if (tail == head) {
            const size_t old_size = entries.size();

            // extend the buffer in-place; new slots are default-constructed
            entries.resize(2 * old_size);
            for (size_t i = old_size; i < entries.size(); i++) {
                entries[i].msg.resize(256);
            }

            // [head..old_size-1] is already in the right place after resize.
            // only move the wrapped front [0..head-1] to just after the old end.
            std::move(entries.begin(), entries.begin() + head, entries.begin() + old_size);

            // reinitialize the moved-from slots so msg buffers are ready to use
            for (size_t i = 0; i < head; i++) {
                entries[i].msg.resize(256);
            }

            tail = old_size + head;
            // head is unchanged
        }

[max-krasnyansky]

that would actually add complexity

to clarify: this vibe-code version seems to be the same size as your PR here: master...ngxson:llama.cpp:xsn/demo_linked_list_log

so I don't think a linked list is that much (more) complicated

although, before diving to linked list approach, I'd suggest testing my assumption about optimizing resize queue + shift entries

edit: actually, CC comes up with an idea a bit clever than mine:
[SNIP]

We could do something like that. I also had a version that used std::deque that is already optimized for similar use-case and uses chunked allocation.
It honestly seems like more complicated than needed.
There are still copies (ie moves) involved, the producer thread is doing more work than it should, etc.

My idea was simple:

• Keep producers lean and simple: block if full, append to tail, move on
• Do all queue updates (resizing, etc) in the consumer: no need for copies, if the queue is full and need resizing, allocate new empty queue and flush the old one (no need to copy any messages). It's a simple double-buffering.
  The only reason it flushes the old queue separately is to avoid having to copy those old messages into the new queue.
  Why copy if we just going to flush them?

Any technique where producers are resizing the queue will require copies, etc.
I just don't see a good reason why. Maybe I'm still missing something.

[max-krasnyansky]

@ngxson Did my comment above convince you :) ?

Again, maybe just a quick summary. The main goal of this PR was to fix out-of-memory condition under heavy logging load (ie low-level backend op tracing). This by definition requires blocking by the producer threads. While implementing it I realized that if we move the queue resizing into the consumer thread we can get rid of all the copies, while also making producer threads very simple (block-if-full, append, done). The consumer thread now does simple double buffering (allocate new queue, swap new and old (std::vector.swap), flush old).

Currently, we do not shrink the queue back for a couple of reasons. I picked a fairly small upper bound (just 4K entries), and at least in the use-cases I have in mind the logging load is fairly constant (ie if the tracing is on, it's on for the lifetime of the process). If you feel strongly about shrinking the queue back we can easily add a simple logic in the consumer. Something like "if the queue has been half-empty last 100 iterations we can shrink it back". The shrinking would use the exact same mechanism as the expanding (alloc new, swap, flush old).

I'm happy to iterate further. Also happy to drop this if there is a better solution that fixes the original issue.
Would be good to resolve this soon as I have one important PR #24592 ready to go that needs this. And I have another that builds on that further.

@ggerganov any preferences?

[ggerganov]

Now that the producer can wait, do we even need the expansion logic? If we don't need it, let's simplify by removing it and keeping the ring buffer at fixed size.

[max-krasnyansky]

Now that the producer can wait, do we even need the expansion logic? If we don't need it, let's simplify by removing it and keeping the ring buffer at fixed size.

@ggerganov
Done.
Removed the expansion, bumped the default to 512.
I also kept the efficient bulk flush. i.e. it's safe to flush/print all entries between cached_head and cached_tail without holding the lock.
It removes the lock/unlock pingpong if the consumer is always behind.