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