Coverage Report

Created: 2025-11-24 06:10

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