Coverage Report

Created: 2026-06-13 06:24

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