/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 | } |