Coverage Report

Created: 2025-12-28 06:26

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