main: log file

[staviq]

WIP implementation of #2694

Logs can be redirected runtime, to a file, stdout or stderr.

https://github.com/staviq/llama.cpp/blob/71d05b9ae438e7d2c3f05212c3dcaf3a53606fa9/examples/main/main.cpp#L61-L73

A way to disable logs completely is currently missing, and possibly i could add loglevels too, to filter by debuglevel.

[JohannesGaessler]

Somewhat similar PR: #2657

[staviq]

Somewhat similar PR: #2657

That one looks like data logging, the #2694 asked for simple debug-like logging

Unless somebody says no, I'm gonna keep working on it, and you can always end up simply not using this :)

[ggerganov]

@staviq Yes, this looks similar to what I had in mind - the idea is to use this to generate a trace of the main program so we can more easily debug what has happened during some run. The purpose is not to dump structured results - this is the goal of #2657

You will probably need some sort of helper utils to dump a vector of tokens (e.g. embd_inp).

[staviq]

Is there an example how to run this along with main? Sorry, I don't understand the image. Is it possible to use main as usual and include logging?

./main -m ~/WizardMath.gguf --color -c 2048 --keep -1 -n -1 -t 3 -b 7 -i -r "USER:" --in-prefix " " -f ~/storage/shared/PT/WizM.txt

Thank you.

The screenshot shows LOG macro dynamically writing to "screen" and a logfile.

The idea is, that this PR would provide a LOG macro, compatible with printf ( format, argumets, etc ) but automatically log to file, or to any valid file handler like stdout or stderr.

I only added a small snippet at the start of int main(), in the main example, to demonstrate the ability to use LOG while selecting different targets ( a file, stdout,stderr )

The goal is to later use LOG in main example, to provide better log trace, as mentioned in #2694

At this point, there is one header file log.h, and tiny demo in main.cpp for testing purposes.

[ggerganov]

Looks very good. When you think the functionality is in a good state, I can make a pass and add the traces that I am mostly interested to main.cpp and merge after this

[staviq]

Looks very good. When you think the functionality is in a good state, I can make a pass and add the traces that I am mostly interested to main.cpp and merge after this

I think I'm gonna wrap all of the helper functions in macros, so in the future they can be removed compile time with a define flag

I might add some more tostring helpers, but this will become clear when we start using it in main.

Other than that, I think the core concept is roughly done.

[staviq]

I think CI is stuck :)

There seems to be a job running continuously for the past 2 months ?
https://github.com/ggerganov/llama.cpp/actions/runs/5368301508

[staviq]

I wanted to un-draft this, but windows seems to hate me, so a bit of help with MSVC would be appreciated, otherwise I'm gonna need some time to find a pc to install windows and msvc on, because the CI logs are not very helpful.

[ghost]

I've been checking up on this PR - Here's 1 of the logs from a run:

[1693000292][  examples/main/main.cpp:   67][                    main] Log start
[1693000292][          ./common/log.h:  515][       _log_dump_cmdline] Cmd: ./main -m /data/data/com.termux/files/home/codellama-7b-instruct.Q4_K_M.gguf --color -c 2048 --keep -1 -n -2 -t 3 -b 7 -i -r Jack: --in-prefix " " -p "<s>[INST] create a short sample JSON for an A.I. character named Bob.[/INST]"
[1693000292][  examples/main/main.cpp:  111][                    main] main: build = 1071 (9bace22)
[1693000292][  examples/main/main.cpp:  117][                    main] main: seed  = 1693000292
[1693000292][  examples/main/main.cpp:  124][                    main] llama backend init
[1693000292][  examples/main/main.cpp:  133][                    main] load the model and apply lora adapter, if any
[1693000292][  examples/main/main.cpp:  147][                    main] 
[1693000292][  examples/main/main.cpp:  149][                    main] system_info: n_threads = 3 / 8 | AVX = 0 | AVX2 = 0 | AVX512 = 0 | AVX512_VBMI = 0 | AVX512_VNNI = 0 | FMA = 0 | NEON = 1 | ARM_FMA = 1 | F16C = 0 | FP16_VA = 1 | WASM_SIMD = 0 | BLAS = 0 | SSE3 = 0 | VSX = 0 | 
[1693000292][  examples/main/main.cpp:  207][                    main] Tokenize the prompt
[1693000292][  examples/main/main.cpp:  215][                    main] prompt: "<s>[INST] create a short sample JSON for an A.I. character named Bob.[/INST]"
[1693000292][  examples/main/main.cpp:  217][                    main] embd_inp tokenized: [ '':1, ' <':529, 's':29879, '>[':24566, 'INST':25580, ']':29962, ' create':1653, ' a':263, ' short':3273, ' sample':4559, ' JSON':4663, ' for':363, ' an':385, ' A':319, '.':29889, 'I':29902, '.':29889, ' character':2931, ' named':4257, ' Bob':7991, '.[':7226, '/':29914, 'INST':25580, ']':29962 ]
[1693000292][  examples/main/main.cpp:  244][                    main] n_ctx: 2048
[1693000292][  examples/main/main.cpp:  344][                    main] main: interactive mode on.
[1693000292][  examples/main/main.cpp:  348][                    main] Reverse prompt: 'Jack:'
[1693000292][  examples/main/main.cpp:  357][                    main] Input prefix: ' '
[1693000292][  examples/main/main.cpp:  365][                    main] sampling: repeat_last_n = 64, repeat_penalty = 1.100000, presence_penalty = 0.000000, frequency_penalty = 0.000000, top_k = 40, tfs_z = 1.000000, top_p = 0.950000, typical_p = 1.000000, temp = 0.800000, mirostat = 0, mirostat_lr = 0.100000, mirostat_ent = 5.000000
[1693000292][  examples/main/main.cpp:  366][                    main] generate: n_ctx = 2048, n_batch = 7, n_predict = -2, n_keep = 24
[1693000292][  examples/main/main.cpp:  367][                    main] 

[staviq]

Fun fact, IntelliSense and MSVC compiler, on Windows, in the same VisualStudio environment, installed from the same installer, use different preprocessors and have wildly incompatible opinions on variadics :)

I ended up dumping preprocessed code directly with the cl compiler.

No errors now, and none of the warnings from CI are mine.

I'm un-drafting this, and going to sleep, it's already getting bright outside :)

[ggerganov]

I think b97958a broke the Windows build, but I don't have a machine to debug and fix it

[ggerganov]

After fixing the Windows build we can merge

@JackJollimore

You can use this branch to run a test that fails for you and send the generated log for analysis. The generated trace is very useful and I've already discovered a bug where we are often using --in-prefix ' ' which is generally incorrect for the SPM tokenizer. I haven't fixed this in the PR - will do after we merge this and debug the issues that you reported

Here is a sample log from example/chat.sh

main.0x1e5112080.log

[staviq]

I saw the review and comments, and I'll be back at this in couple of hours after work.

[ghost]

I've already discovered a bug where we are often using --in-prefix ' ' which is generally incorrect for the SPM tokenizer. I haven't fixed this in the PR - will do after we merge this and debug the issues that you reported

Here's Vicuna logs

Edit: I'll exclude --in-prefix " ".

[staviq]

Still fighting MSVC. I fixed compilation errors,

But i found a problem where std::isprint() is failing ?

Can it be because llama_token_to_str was replaced by llama_token_to_piece ?

Edit: Uhmmm, so changing const char c to const unsigned char c seems to fix it, but i can't wrap my head around why would std::isprint upcast char to signed int, and then assert c >= -1 ?

Edit2: I see 3 solutions here, I can spend more time and make it play nice with unicode etc (not a problem for me), or I can naively cast to unsigned and let it potentially strip everything remotely non alnum, or I can remove that filter entirely and let it print whatever it wants.

[staviq]

I went with quick and safe fix for std::isprint, if there is a need for proper unicode-nes in logs, I think It would be less convoluted if I do it in a separate PR.

MSVC is fixed, things appear to be working properly, and if I didn't miss anything, code should be consistent with review suggestions now.

[cebtenzzre]

I didn't miss anything, code should be consistent with review suggestions now.

Eliminate the redundant 'else' clauses after 'if' statements that return in the true case (which I think is what the NOLINT comments are suppressing), and I'll call it good enough.

[staviq]

I've looked at the logs from clang tidy review CI, and they are all easily doable, do you want me to fix those too ? Shouldn't take too long.

[cebtenzzre]

I've looked at the logs from clang tidy review CI, and they are all easily doable, do you want me to fix those too ?

Sure, go ahead and fix them. I suppose the functions that start with _ could be changed to end with e.g. _impl.

edit: clang-tidy is clearly trying to generate markdown output like this (generated with jq after downloading the artifact): clang-tidy.md

But it doesn't seem to be actually generating any review comments like it's supposed to.

edit 2: It was disabled in a pull request: #1705

[staviq]

I think I just wasted half an hour to do something clang-tidy recommends only to realize it's a bug in clang-tidy :)

It insists on wrapping lambda captures in round brackets, and i couldn't figure out why it doesn't compile, until it hit me: lambda captures cannot be expressions, they have to be identifiers and wrapping them in brackets makes them invalid identifiers :)

[ggerganov]

Thank you! I think these logs will be very helpful for debugging issues in the future

[ggerganov]

@staviq On MacOS, after adding the log.h I'm getting the following compile warnings:

At some point, I removed the ',' to fix the warning on my machine (b97958a), but it made its way back - I guess it breaks something for someone else. Let's look into resolving this

[staviq]

@staviq On MacOS, after adding the log.h I'm getting the following compile warnings:

At some point, I removed the ',' to fix the warning on my machine (b97958a), but it made its way back - I guess it breaks something for someone else. Let's look into resolving this

I don't have a mac to test it on, I'll see if I can get osx to run in VM. But basically, either removing ## or using the msvc trick should work.

[cebtenzzre]

At some point, I removed the ',' to fix the warning on my machine (b97958a), but it made its way back

Whoops, I added that macro in #3038, actually. I compile with GCC so I didn't see those warnings. Clang will show those warnings on any platform, macOS is not required.