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