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