Coverage Report

Created: 2026-06-22 06:47

next uncovered line (L), next uncovered region (R), next uncovered branch (B)
/src/llama.cpp/common/log.cpp
Line
Count
Source
1
#include "common.h"
2
#include "log.h"
3
4
#include <chrono>
5
#include <condition_variable>
6
#include <cstdarg>
7
#include <cstdio>
8
#include <cstdlib>
9
#include <cstring>
10
#include <mutex>
11
#include <sstream>
12
#include <thread>
13
#include <vector>
14
#include <algorithm>
15
16
#if defined(_WIN32)
17
#    define WIN32_LEAN_AND_MEAN
18
#    ifndef NOMINMAX
19
#       define NOMINMAX
20
#    endif
21
#    include <io.h>
22
#    include <windows.h>
23
#    define isatty _isatty
24
#    define fileno _fileno
25
#else
26
#    include <unistd.h>
27
#endif // defined(_WIN32)
28
29
int common_log_verbosity_thold = LOG_DEFAULT_LLAMA;
30
31
0
int common_log_get_verbosity_thold(void) {
32
0
    return common_log_verbosity_thold;
33
0
}
34
35
0
void common_log_set_verbosity_thold(int verbosity) {
36
0
    common_log_verbosity_thold = verbosity;
37
0
}
38
39
0
static int64_t t_us() {
40
0
    return std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::system_clock::now().time_since_epoch()).count();
41
0
}
42
43
// colors
44
enum common_log_col : int {
45
    COMMON_LOG_COL_DEFAULT = 0,
46
    COMMON_LOG_COL_BOLD,
47
    COMMON_LOG_COL_RED,
48
    COMMON_LOG_COL_GREEN,
49
    COMMON_LOG_COL_YELLOW,
50
    COMMON_LOG_COL_BLUE,
51
    COMMON_LOG_COL_MAGENTA,
52
    COMMON_LOG_COL_CYAN,
53
    COMMON_LOG_COL_WHITE,
54
};
55
56
// disable colors by default
57
static const char* g_col[] = {
58
    "",
59
    "",
60
    "",
61
    "",
62
    "",
63
    "",
64
    "",
65
    "",
66
    "",
67
};
68
69
struct common_log_entry {
70
    enum ggml_log_level level {GGML_LOG_LEVEL_INFO};
71
72
    std::vector<char> msg;
73
74
    int64_t timestamp { 0 };
75
    bool is_end       { false }; // signals the worker thread to stop
76
    bool prefix       { false };
77
78
0
    common_log_entry(size_t size = 256) : msg(size) { }
79
80
0
    void print(FILE * file = nullptr) const {
81
0
        FILE * fcur = file;
82
0
        if (!fcur) {
83
            // stderr displays DBG messages only when their verbosity level is not higher than the threshold
84
            // these messages will still be logged to a file
85
0
            if (level == GGML_LOG_LEVEL_DEBUG && common_log_verbosity_thold < LOG_DEFAULT_DEBUG) {
86
0
                return;
87
0
            }
88
89
0
            fcur = stdout;
90
91
0
            if (level != GGML_LOG_LEVEL_NONE) {
92
0
                fcur = stderr;
93
0
            }
94
0
        }
95
96
0
        if (level != GGML_LOG_LEVEL_NONE && level != GGML_LOG_LEVEL_CONT && prefix) {
97
0
            if (timestamp) {
98
                // [M.s.ms.us]
99
0
                fprintf(fcur, "%s%d.%02d.%03d.%03d%s ",
100
0
                        g_col[COMMON_LOG_COL_BLUE],
101
0
                        (int) (timestamp / 1000000 / 60),
102
0
                        (int) (timestamp / 1000000 % 60),
103
0
                        (int) (timestamp / 1000 % 1000),
104
0
                        (int) (timestamp % 1000),
105
0
                        g_col[COMMON_LOG_COL_DEFAULT]);
106
0
            }
107
108
0
            switch (level) {
109
0
                case GGML_LOG_LEVEL_INFO:  fprintf(fcur, "%sI %s", g_col[COMMON_LOG_COL_GREEN],   g_col[COMMON_LOG_COL_DEFAULT]); break;
110
0
                case GGML_LOG_LEVEL_WARN:  fprintf(fcur, "%sW %s", g_col[COMMON_LOG_COL_MAGENTA], ""                        ); break;
111
0
                case GGML_LOG_LEVEL_ERROR: fprintf(fcur, "%sE %s", g_col[COMMON_LOG_COL_RED],     ""                        ); break;
112
0
                case GGML_LOG_LEVEL_DEBUG: fprintf(fcur, "%sD %s", g_col[COMMON_LOG_COL_YELLOW],  ""                        ); break;
113
0
                default:
114
0
                    break;
115
0
            }
116
0
        }
117
118
0
        fprintf(fcur, "%s", msg.data());
119
120
0
        if (level == GGML_LOG_LEVEL_WARN || level == GGML_LOG_LEVEL_ERROR || level == GGML_LOG_LEVEL_DEBUG) {
121
0
            fprintf(fcur, "%s", g_col[COMMON_LOG_COL_DEFAULT]);
122
0
        }
123
124
0
        fflush(fcur);
125
0
    }
126
};
127
128
struct common_log {
129
    // default capacity
130
0
    common_log(size_t capacity = 512) {
131
0
        file       = nullptr;
132
0
        prefix     = false;
133
0
        timestamps = false;
134
0
        running    = false;
135
0
        t_start    = t_us();
136
137
0
        queue.resize(capacity, common_log_entry(256));
138
0
        head = 0;
139
0
        tail = 0;
140
141
0
        resume();
142
0
    }
143
144
0
    ~common_log() {
145
0
        pause();
146
0
        if (file) {
147
0
            fclose(file);
148
0
        }
149
0
    }
150
151
private:
152
    std::mutex              mtx;
153
    std::thread             thrd;
154
    std::condition_variable cv_new;  // new entry
155
    std::condition_variable cv_full; // wait on full
156
157
    FILE * file;
158
159
    bool prefix;
160
    bool timestamps;
161
    bool running;
162
163
    int64_t t_start;
164
165
    // queue of entries
166
    std::vector<common_log_entry> queue;
167
    size_t head;
168
    size_t tail;
169
170
0
    bool print_entry(const common_log_entry & e) const {
171
0
        if (e.is_end) return true;
172
173
0
        e.print();
174
0
        if (file) {
175
0
            e.print(file);
176
0
        }
177
0
        return false;
178
0
    }
179
180
0
    bool flush_queue(size_t start_head, size_t end_tail, size_t & out_head) const {
181
0
        bool stop = false;
182
0
        size_t h = start_head;
183
0
        while (h != end_tail && !stop) {
184
0
            stop = print_entry(queue[h]);
185
0
            h = (h + 1) % queue.size();
186
0
        }
187
0
        out_head = h;
188
0
        return stop;
189
0
    }
190
191
public:
192
0
    bool is_full() const {
193
0
        return ((tail + 1) % queue.size()) == head;
194
0
    }
195
196
0
    bool is_empty() const {
197
0
        return head == tail;
198
0
    }
199
200
0
    void add(enum ggml_log_level level, const char * fmt, va_list args) {
201
0
        std::unique_lock<std::mutex> lock(mtx);
202
203
        // block if the queue is full
204
0
        cv_full.wait(lock, [this]() { return !running || !is_full(); });
205
206
0
        if (!running) {
207
            // discard messages while the worker thread is paused
208
0
            return;
209
0
        }
210
211
0
        auto & entry = queue[tail];
212
213
0
        {
214
            // cannot use args twice, so make a copy in case we need to expand the buffer
215
0
            va_list args_copy;
216
0
            va_copy(args_copy, args);
217
218
0
#if 1
219
0
            const size_t n = vsnprintf(entry.msg.data(), entry.msg.size(), fmt, args);
220
0
            if (n >= entry.msg.size()) {
221
0
                entry.msg.resize(n + 1);
222
0
                vsnprintf(entry.msg.data(), entry.msg.size(), fmt, args_copy);
223
0
            }
224
#else
225
            // hack for bolding arguments
226
227
            std::stringstream ss;
228
            for (int i = 0; fmt[i] != 0; i++) {
229
                if (fmt[i] == '%') {
230
                    ss << LOG_COL_BOLD;
231
                    while (fmt[i] != ' ' && fmt[i] != ')' && fmt[i] != ']' && fmt[i] != 0) ss << fmt[i++];
232
                    ss << LOG_COL_DEFAULT;
233
                    if (fmt[i] == 0) break;
234
                }
235
                ss << fmt[i];
236
            }
237
            const size_t n = vsnprintf(entry.msg.data(), entry.msg.size(), ss.str().c_str(), args);
238
            if (n >= entry.msg.size()) {
239
                entry.msg.resize(n + 1);
240
                vsnprintf(entry.msg.data(), entry.msg.size(), ss.str().c_str(), args_copy);
241
            }
242
#endif
243
0
            va_end(args_copy);
244
0
        }
245
246
0
        entry.is_end    = false;
247
0
        entry.level     = level;
248
0
        entry.prefix    = prefix;
249
0
        entry.timestamp = 0;
250
0
        if (timestamps) {
251
0
            entry.timestamp = t_us() - t_start;
252
0
        }
253
254
0
        tail = (tail + 1) % queue.size();
255
0
        cv_new.notify_one();
256
0
    }
257
258
0
    void resume() {
259
0
        std::lock_guard<std::mutex> lock(mtx);
260
261
0
        if (running) {
262
0
            return;
263
0
        }
264
265
0
        running = true;
266
267
0
        thrd = std::thread([this]() {
268
0
            while (true) {
269
0
                std::unique_lock<std::mutex> lock(mtx);
270
0
                cv_new.wait(lock, [this]() { return !is_empty(); });
271
272
0
                size_t cached_head = head;
273
0
                size_t cached_tail = tail;
274
275
0
                lock.unlock(); // drop the lock during flush
276
277
0
                size_t next_head;
278
0
                bool stop = flush_queue(cached_head, cached_tail, next_head);
279
280
0
                lock.lock();
281
0
                head = next_head;
282
0
                cv_full.notify_all();
283
284
0
                if (stop) {
285
0
                    break;
286
0
                }
287
0
            }
288
0
        });
289
0
    }
290
291
0
    void pause() {
292
0
        {
293
0
            std::lock_guard<std::mutex> lock(mtx);
294
295
0
            if (!running) {
296
0
                return;
297
0
            }
298
299
0
            running = false;
300
301
            // push an entry to signal the worker thread to stop
302
0
            auto & entry = queue[tail];
303
0
            entry.is_end = true;
304
0
            tail = (tail + 1) % queue.size();
305
306
            // wakeup everyone
307
0
            cv_new.notify_one();
308
0
            cv_full.notify_all();
309
0
        }
310
311
0
        thrd.join();
312
0
    }
313
314
0
    void set_file(const char * path) {
315
0
        pause();
316
317
0
        if (file) {
318
0
            fclose(file);
319
0
        }
320
321
0
        if (path) {
322
0
            file = fopen(path, "w");
323
0
        } else {
324
0
            file = nullptr;
325
0
        }
326
327
0
        resume();
328
0
    }
329
330
0
    void set_colors(bool colors) {
331
0
        pause();
332
333
0
        if (colors) {
334
0
            g_col[COMMON_LOG_COL_DEFAULT] = LOG_COL_DEFAULT;
335
0
            g_col[COMMON_LOG_COL_BOLD]    = LOG_COL_BOLD;
336
0
            g_col[COMMON_LOG_COL_RED]     = LOG_COL_RED;
337
0
            g_col[COMMON_LOG_COL_GREEN]   = LOG_COL_GREEN;
338
0
            g_col[COMMON_LOG_COL_YELLOW]  = LOG_COL_YELLOW;
339
0
            g_col[COMMON_LOG_COL_BLUE]    = LOG_COL_BLUE;
340
0
            g_col[COMMON_LOG_COL_MAGENTA] = LOG_COL_MAGENTA;
341
0
            g_col[COMMON_LOG_COL_CYAN]    = LOG_COL_CYAN;
342
0
            g_col[COMMON_LOG_COL_WHITE]   = LOG_COL_WHITE;
343
0
        } else {
344
0
            for (size_t i = 0; i < std::size(g_col); i++) {
345
0
                g_col[i] = "";
346
0
            }
347
0
        }
348
349
0
        resume();
350
0
    }
351
352
0
    void set_prefix(bool prefix) {
353
0
        std::lock_guard<std::mutex> lock(mtx);
354
355
0
        this->prefix = prefix;
356
0
    }
357
358
0
    void set_timestamps(bool timestamps) {
359
0
        std::lock_guard<std::mutex> lock(mtx);
360
361
0
        this->timestamps = timestamps;
362
0
    }
363
};
364
365
//
366
// public API
367
//
368
369
0
struct common_log * common_log_init() {
370
0
    return new common_log;
371
0
}
372
373
0
struct common_log * common_log_main() {
374
    // We intentionally leak (i.e. do not delete) the logger singleton because
375
    // common_log destructor called at DLL teardown phase will cause hanging on Windows.
376
    // OS will release resources anyway so it should not be a significant issue,
377
    // though this design may cause logs to be lost if not flushed before the program exits.
378
    // Refer to https://github.com/ggml-org/llama.cpp/issues/22142 for details.
379
0
    static struct common_log * log;
380
0
    static std::once_flag    init_flag;
381
0
    std::call_once(init_flag, [&]() {
382
0
        log = new common_log;
383
        // Set default to auto-detect colors
384
0
        log->set_colors(tty_can_use_colors());
385
0
    });
386
387
0
    return log;
388
0
}
389
390
0
void common_log_pause(struct common_log * log) {
391
0
    log->pause();
392
0
}
393
394
0
void common_log_resume(struct common_log * log) {
395
0
    log->resume();
396
0
}
397
398
0
void common_log_free(struct common_log * log) {
399
0
    delete log;
400
0
}
401
402
0
void common_log_add(struct common_log * log, enum ggml_log_level level, const char * fmt, ...) {
403
0
    va_list args;
404
0
    va_start(args, fmt);
405
0
    log->add(level, fmt, args);
406
0
    va_end(args);
407
0
}
408
409
0
void common_log_set_file(struct common_log * log, const char * file) {
410
0
    log->set_file(file);
411
0
}
412
413
0
void common_log_set_colors(struct common_log * log, log_colors colors) {
414
0
    if (colors == LOG_COLORS_AUTO) {
415
0
        log->set_colors(tty_can_use_colors());
416
0
        return;
417
0
    }
418
419
0
    if (colors == LOG_COLORS_DISABLED) {
420
0
        log->set_colors(false);
421
0
        return;
422
0
    }
423
424
0
    GGML_ASSERT(colors == LOG_COLORS_ENABLED);
425
0
    log->set_colors(true);
426
0
}
427
428
0
void common_log_set_prefix(struct common_log * log, bool prefix) {
429
0
    log->set_prefix(prefix);
430
0
}
431
432
0
void common_log_set_timestamps(struct common_log * log, bool timestamps) {
433
0
    log->set_timestamps(timestamps);
434
0
}
435
436
0
void common_log_flush(struct common_log * log) {
437
0
    log->pause();
438
0
    log->resume();
439
0
}
440
441
0
static int common_get_verbosity(enum ggml_log_level level) {
442
0
    switch (level) {
443
0
        case GGML_LOG_LEVEL_DEBUG: return LOG_LEVEL_DEBUG;
444
0
        case GGML_LOG_LEVEL_INFO:  return LOG_LEVEL_TRACE;
445
0
        case GGML_LOG_LEVEL_WARN:  return LOG_LEVEL_WARN;
446
0
        case GGML_LOG_LEVEL_ERROR: return LOG_LEVEL_ERROR;
447
0
        case GGML_LOG_LEVEL_CONT:  return LOG_LEVEL_TRACE;
448
0
        case GGML_LOG_LEVEL_NONE:
449
0
        default:
450
0
            return LOG_LEVEL_OUTPUT;
451
0
    }
452
0
}
453
454
0
void common_log_default_callback(enum ggml_log_level level, const char * text, void * /*user_data*/) {
455
0
    auto verbosity = common_get_verbosity(level);
456
0
    if (verbosity <= common_log_verbosity_thold) {
457
0
        common_log_add(common_log_main(), level, "%s", text);
458
0
    }
459
0
}