Skip to content

Commit 1c2f595

Browse files
ggerganovggerganov
committed
log : update defaults
ggml-ci
1 parent 523a7d9 commit 1c2f595

File tree

9 files changed

+120
-41
lines changed

9 files changed

+120
-41
lines changed

‎.github/workflows/build.yml

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,8 @@ env:
2323
BRANCH_NAME: ${{ github.head_ref || github.ref_name }}
2424
GGML_NLOOP: 3
2525
GGML_N_THREADS: 1
26+
LLAMA_LOG_COLORS: 1
27+
LLAMA_LOG_TIMESTAMPS: 1
2628

2729
jobs:
2830
macOS-latest-cmake-arm64:

‎.github/workflows/server.yml

Lines changed: 7 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,11 @@ on:
2020
types: [opened, synchronize, reopened]
2121
paths: ['.github/workflows/server.yml', '**/CMakeLists.txt', '**/Makefile', '**/*.h', '**/*.hpp', '**/*.c', '**/*.cpp', '**/*.cu', '**/*.swift', '**/*.m', 'examples/server/**.*']
2222

23+
env:
24+
LLAMA_LOG_COLORS: 1
25+
LLAMA_LOG_TIMESTAMPS: 1
26+
LLAMA_LOG_VERBOSITY: 10
27+
2328
concurrency:
2429
group: ${{ github.workflow }}-${{ github.ref }}-${{ github.head_ref || github.run_id }}
2530
cancel-in-progress: true
@@ -116,14 +121,14 @@ jobs:
116121
id: server_integration_tests
117122
run: |
118123
cd examples/server/tests
119-
LLAMA_LOG=10 PORT=8888 ./tests.sh
124+
PORT=8888 ./tests.sh
120125
121126
- name: Slow tests
122127
id: server_integration_tests_slow
123128
if: ${{ (github.event.schedule || github.event.inputs.slow_tests == 'true') && matrix.build_type == 'Release' }}
124129
run: |
125130
cd examples/server/tests
126-
LLAMA_LOG=10 PORT=8888 ./tests.sh --stop --no-skipped --no-capture --tags slow
131+
PORT=8888 ./tests.sh --stop --no-skipped --no-capture --tags slow
127132
128133
129134
server-windows:

‎ci/run.sh

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -737,6 +737,8 @@ function gg_sum_embd_bge_small {
737737

738738
## main
739739

740+
export LLAMA_LOG_TIMESTAMPS=1
741+
740742
if [ -z ${GG_BUILD_LOW_PERF} ]; then
741743
# Create symlink: ./llama.cpp/models-mnt -> $MNT/models/models-mnt
742744
rm -rf ${SRC}/models-mnt

‎common/arg.cpp

Lines changed: 28 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1951,6 +1951,34 @@ gpt_params_context gpt_params_parser_init(gpt_params & params, llama_example ex,
19511951
gpt_log_set_file(gpt_log_main(), value.c_str());
19521952
}
19531953
));
1954+
add_opt(llama_arg(
1955+
{"--log-colors"},
1956+
"Enable colored logging",
1957+
[](gpt_params &) {
1958+
gpt_log_set_colors(gpt_log_main(), true);
1959+
}
1960+
).set_env("LLAMA_LOG_COLORS"));
1961+
add_opt(llama_arg(
1962+
{"-lv", "--log-verbose"},
1963+
"Set verbosity level to infinity (i.e. log all messages, useful for debugging)",
1964+
[](gpt_params &) {
1965+
gpt_log_set_verbosity_thold(INT_MAX);
1966+
}
1967+
));
1968+
add_opt(llama_arg(
1969+
{"--log-verbosity"}, "THOLD",
1970+
"Set the verbosity threshold. Messages with a lower verbosity will be ignored.",
1971+
[](gpt_params &, int value) {
1972+
gpt_log_set_verbosity_thold(value);
1973+
}
1974+
).set_env("LLAMA_LOG_VERBOSITY"));
1975+
add_opt(llama_arg(
1976+
{"--log-timestamps"},
1977+
"Enable timestamps in log messages",
1978+
[](gpt_params &) {
1979+
gpt_log_set_timestamps(gpt_log_main(), true);
1980+
}
1981+
).set_env("LLAMA_LOG_TIMESTAMPS"));
19541982

19551983
return ctx_arg;
19561984
}

‎common/common.cpp

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -364,7 +364,7 @@ bool parse_cpu_mask(const std::string & mask, bool (&boolmask)[GGML_MAX_N_THREAD
364364

365365
void gpt_init() {
366366
llama_log_set([](ggml_log_level level, const char * text, void * /*user_data*/) {
367-
if (LOG_DEFAULT_LLAMA <= gpt_log_verbosity_env) {
367+
if (LOG_DEFAULT_LLAMA <= gpt_log_verbosity_thold) {
368368
gpt_log_add(gpt_log_main(), level, "%s", text);
369369
}
370370
}, NULL);

‎common/log.cpp

Lines changed: 67 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -8,11 +8,12 @@
88
#include <thread>
99
#include <vector>
1010

11-
int gpt_log_verbosity_env = getenv("LLAMA_LOG") ? atoi(getenv("LLAMA_LOG")) : LOG_DEFAULT_LLAMA;
11+
int gpt_log_verbosity_thold = LOG_DEFAULT_LLAMA;
1212

13-
#define LOG_COLORS // TMP
13+
void gpt_log_set_verbosity_thold(int verbosity) {
14+
gpt_log_verbosity_thold = verbosity;
15+
}
1416

15-
#ifdef LOG_COLORS
1617
#define LOG_COL_DEFAULT "\033[0m"
1718
#define LOG_COL_BOLD "\033[1m"
1819
#define LOG_COL_RED "\033[31m"
@@ -22,22 +23,37 @@ int gpt_log_verbosity_env = getenv("LLAMA_LOG") ? atoi(getenv("LLAMA_LOG")) : LO
2223
#define LOG_COL_MAGENTA "\033[35m"
2324
#define LOG_COL_CYAN "\033[36m"
2425
#define LOG_COL_WHITE "\033[37m"
25-
#else
26-
#define LOG_COL_DEFAULT ""
27-
#define LOG_COL_BOLD ""
28-
#define LOG_COL_RED ""
29-
#define LOG_COL_GREEN ""
30-
#define LOG_COL_YELLOW ""
31-
#define LOG_COL_BLUE ""
32-
#define LOG_COL_MAGENTA ""
33-
#define LOG_COL_CYAN ""
34-
#define LOG_COL_WHITE ""
35-
#endif
3626

3727
static int64_t t_us() {
3828
return std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::system_clock::now().time_since_epoch()).count();
3929
}
4030

31+
// colors
32+
enum gpt_log_col : int {
33+
GPT_LOG_COL_DEFAULT = 0,
34+
GPT_LOG_COL_BOLD,
35+
GPT_LOG_COL_RED,
36+
GPT_LOG_COL_GREEN,
37+
GPT_LOG_COL_YELLOW,
38+
GPT_LOG_COL_BLUE,
39+
GPT_LOG_COL_MAGENTA,
40+
GPT_LOG_COL_CYAN,
41+
GPT_LOG_COL_WHITE,
42+
};
43+
44+
// disable colors by default
45+
static std::vector<const char *> g_col = {
46+
"",
47+
"",
48+
"",
49+
"",
50+
"",
51+
"",
52+
"",
53+
"",
54+
"",
55+
};
56+
4157
struct gpt_log_entry {
4258
enum ggml_log_level level;
4359

@@ -53,7 +69,7 @@ struct gpt_log_entry {
5369
if (!fcur) {
5470
// stderr displays DBG messages only when the verbosity is high
5571
// these messages can still be logged to a file
56-
if (level == GGML_LOG_LEVEL_DEBUG && gpt_log_verbosity_env < LOG_DEFAULT_DEBUG) {
72+
if (level == GGML_LOG_LEVEL_DEBUG && gpt_log_verbosity_thold < LOG_DEFAULT_DEBUG) {
5773
return;
5874
}
5975

@@ -67,18 +83,20 @@ struct gpt_log_entry {
6783
if (level != GGML_LOG_LEVEL_NONE) {
6884
if (timestamp) {
6985
// [M.s.ms.us]
70-
fprintf(fcur, "" LOG_COL_BLUE "%d.%02d.%03d.%03d" LOG_COL_DEFAULT " ",
86+
fprintf(fcur, "%s%d.%02d.%03d.%03d%s ",
87+
g_col[GPT_LOG_COL_BLUE],
7188
(int) (timestamp / 1000000 / 60),
7289
(int) (timestamp / 1000000 % 60),
7390
(int) (timestamp / 1000 % 1000),
74-
(int) (timestamp % 1000));
91+
(int) (timestamp % 1000),
92+
g_col[GPT_LOG_COL_DEFAULT]);
7593
}
7694

7795
switch (level) {
78-
case GGML_LOG_LEVEL_INFO: fprintf(fcur, LOG_COL_GREEN "I " LOG_COL_DEFAULT); break;
79-
case GGML_LOG_LEVEL_WARN: fprintf(fcur, LOG_COL_MAGENTA "W " ); break;
80-
case GGML_LOG_LEVEL_ERROR: fprintf(fcur, LOG_COL_RED "E " ); break;
81-
case GGML_LOG_LEVEL_DEBUG: fprintf(fcur, LOG_COL_YELLOW "D " ); break;
96+
case GGML_LOG_LEVEL_INFO: fprintf(fcur, "%sI %s", g_col[GPT_LOG_COL_GREEN], g_col[GPT_LOG_COL_DEFAULT]); break;
97+
case GGML_LOG_LEVEL_WARN: fprintf(fcur, "%sW %s", g_col[GPT_LOG_COL_MAGENTA], "" ); break;
98+
case GGML_LOG_LEVEL_ERROR: fprintf(fcur, "%sE %s", g_col[GPT_LOG_COL_RED], "" ); break;
99+
case GGML_LOG_LEVEL_DEBUG: fprintf(fcur, "%sD %s", g_col[GPT_LOG_COL_YELLOW], "" ); break;
82100
default:
83101
break;
84102
}
@@ -87,7 +105,7 @@ struct gpt_log_entry {
87105
fprintf(fcur, "%s", msg.data());
88106

89107
if (level == GGML_LOG_LEVEL_WARN || level == GGML_LOG_LEVEL_ERROR || level == GGML_LOG_LEVEL_DEBUG) {
90-
fprintf(fcur, "%s", LOG_COL_DEFAULT);
108+
fprintf(fcur, "%s", g_col[GPT_LOG_COL_DEFAULT]);
91109
}
92110

93111
fflush(fcur);
@@ -97,7 +115,7 @@ struct gpt_log_entry {
97115
struct gpt_log {
98116
gpt_log(size_t capacity) {
99117
file = nullptr;
100-
timestamps = true;
118+
timestamps = false;
101119
running = false;
102120
t_start = t_us();
103121
entries.resize(capacity);
@@ -284,6 +302,28 @@ struct gpt_log {
284302
resume();
285303
}
286304

305+
void set_colors(bool colors) {
306+
pause();
307+
308+
if (colors) {
309+
g_col[GPT_LOG_COL_DEFAULT] = LOG_COL_DEFAULT;
310+
g_col[GPT_LOG_COL_BOLD] = LOG_COL_BOLD;
311+
g_col[GPT_LOG_COL_RED] = LOG_COL_RED;
312+
g_col[GPT_LOG_COL_GREEN] = LOG_COL_GREEN;
313+
g_col[GPT_LOG_COL_YELLOW] = LOG_COL_YELLOW;
314+
g_col[GPT_LOG_COL_BLUE] = LOG_COL_BLUE;
315+
g_col[GPT_LOG_COL_MAGENTA] = LOG_COL_MAGENTA;
316+
g_col[GPT_LOG_COL_CYAN] = LOG_COL_CYAN;
317+
g_col[GPT_LOG_COL_WHITE] = LOG_COL_WHITE;
318+
} else {
319+
for (size_t i = 0; i < g_col.size(); i++) {
320+
g_col[i] = "";
321+
}
322+
}
323+
324+
resume();
325+
}
326+
287327
void set_timestamps(bool timestamps) {
288328
std::lock_guard<std::mutex> lock(mtx);
289329

@@ -324,6 +364,10 @@ void gpt_log_set_file(struct gpt_log * log, const char * file) {
324364
log->set_file(file);
325365
}
326366

367+
void gpt_log_set_colors(struct gpt_log * log, bool colors) {
368+
log->set_colors(colors);
369+
}
370+
327371
void gpt_log_set_timestamps(struct gpt_log * log, bool timestamps) {
328372
log->set_timestamps(timestamps);
329373
}

‎common/log.h

Lines changed: 9 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -13,8 +13,11 @@
1313
#define LOG_DEFAULT_DEBUG 10
1414
#define LOG_DEFAULT_LLAMA 5
1515

16-
// intialized in log.cpp from environment variable LLAMA_LOG
17-
extern int gpt_log_verbosity_env;
16+
// needed by the LOG_TMPL macro to avoid computing log arguments if the verbosity lower
17+
// set via gpt_log_set_verbosity()
18+
extern int gpt_log_verbosity_thold;
19+
20+
void gpt_log_set_verbosity_thold(int verbosity); // not thread-safe
1821

1922
struct gpt_log;
2023

@@ -27,12 +30,13 @@ void gpt_log_free (struct gpt_log * log);
2730
LOG_ATTRIBUTE_FORMAT(3, 4)
2831
void gpt_log_add(struct gpt_log * log, enum ggml_log_level level, const char * fmt, ...);
2932

30-
void gpt_log_set_file (struct gpt_log * log, const char * file); // not thread-safe
31-
void gpt_log_set_timestamps(struct gpt_log * log, bool timestamps);
33+
void gpt_log_set_file (struct gpt_log * log, const char * file); // not thread-safe
34+
void gpt_log_set_colors (struct gpt_log * log, bool colors); // not thread-safe
35+
void gpt_log_set_timestamps(struct gpt_log * log, bool timestamps);
3236

3337
#define LOG_TMPL(level, verbosity, ...) \
3438
do { \
35-
if ((verbosity) <= gpt_log_verbosity_env) { \
39+
if ((verbosity) <= gpt_log_verbosity_thold) { \
3640
gpt_log_add(gpt_log_main(), (level), __VA_ARGS__); \
3741
} \
3842
} while (0)

‎examples/main/main.cpp

Lines changed: 0 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -133,12 +133,6 @@ static std::string chat_add_and_format(struct llama_model * model, std::vector<l
133133
int main(int argc, char ** argv) {
134134
gpt_init();
135135

136-
llama_log_set([](ggml_log_level level, const char * text, void * /*user_data*/) {
137-
if (LOG_DEFAULT_LLAMA <= gpt_log_verbosity_env) {
138-
gpt_log_add(gpt_log_main(), level, "%s", text);
139-
}
140-
}, NULL);
141-
142136
gpt_params params;
143137
g_params = &params;
144138
if (!gpt_params_parse(argc, argv, params, LLAMA_EXAMPLE_MAIN, print_usage)) {

‎examples/server/server.cpp

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1905,7 +1905,7 @@ struct server_context {
19051905

19061906
// we haven't tokenized the prompt yet - do it now:
19071907
if (prompt_tokens.empty()) {
1908-
SRV_DBG("tokenizing prompt, id_slot = %d, id_task = %d\n", slot.id, slot.id_task);
1908+
SRV_INF("tokenizing prompt, id_slot = %d, id_task = %d\n", slot.id, slot.id_task);
19091909

19101910
slot.t_start_process_prompt = ggml_time_us();
19111911
slot.t_start_generation = 0;
@@ -1949,7 +1949,7 @@ struct server_context {
19491949
slot.n_past = 0;
19501950
slot.n_prompt_tokens = prompt_tokens.size();
19511951

1952-
SRV_INF("prompt tokenized, id_slot = %d, id_task = %d, n_ctx = %d, n_keep = %d, n_prompt_tokens = %d\n", slot.id, slot.id_task, slot.n_ctx, slot.params.n_keep, slot.n_prompt_tokens);
1952+
SRV_INF("prompt tokenized, id_slot = %d, id_task = %d, n_ctx_slot = %d, n_keep = %d, n_prompt_tokens = %d\n", slot.id, slot.id_task, slot.n_ctx, slot.params.n_keep, slot.n_prompt_tokens);
19531953

19541954
// empty prompt passed -> release the slot and send empty response
19551955
if (prompt_tokens.empty()) {
@@ -2105,7 +2105,7 @@ struct server_context {
21052105
// {"n_tokens", batch.n_tokens},
21062106
// {"progress", (float) slot.n_prompt_tokens_processed / slot.n_prompt_tokens},
21072107
//});
2108-
SRV_DBG("prompt processing progress, id_slot = %d, n_past = %d, n_ctx = %d, n_tokens = %d, progress = %f\n", slot.id, slot.n_past, n_ctx, batch.n_tokens, (float) slot.n_prompt_tokens_processed / slot.n_prompt_tokens);
2108+
SRV_INF("prompt processing progress, id_slot = %d, n_past = %d, n_tokens = %d, progress = %f\n", slot.id, slot.n_past, batch.n_tokens, (float) slot.n_prompt_tokens_processed / slot.n_prompt_tokens);
21092109

21102110
// entire prompt has been processed
21112111
if (slot.n_past == slot.n_prompt_tokens) {
@@ -2125,7 +2125,7 @@ struct server_context {
21252125
// {"n_ctx", n_ctx},
21262126
// {"n_tokens", batch.n_tokens},
21272127
//});
2128-
SRV_DBG("prompt done, id_slot = %d, n_past = %d, n_ctx = %d, n_tokens = %d\n", slot.id, slot.n_past, n_ctx, batch.n_tokens);
2128+
SRV_INF("prompt done, id_slot = %d, n_past = %d, n_tokens = %d\n", slot.id, slot.n_past, batch.n_tokens);
21292129
}
21302130
}
21312131

0 commit comments

Comments
 (0)