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