Proposal for new ggml logger subsystem

[bandoti]

I would like to propose a new GGML logger subsystem. I am happy to do the work on the implementation. Here are some of the ideas I have come up with so far:

Add two new files to the GGML library:

ggml-logger.h
ggml-logger.cpp

Where the interface defined within ggml-logger.h is something like:

// Move ggml_log_level from ggml.h into ggml-logger.h
enum ggml_log_level {
    GGML_LOG_LEVEL_ERROR = 2,
    GGML_LOG_LEVEL_WARN  = 3,
    GGML_LOG_LEVEL_INFO  = 4,
    GGML_LOG_LEVEL_DEBUG = 5
};

// Callback for handling log events, organized by source/log level
typedef void (*ggml_logger_log_handler) (const char *source, ggml_log_level level, const char *message, void *user_data);

void ggml_logger_log(const char *source, ggml_log_level level, ...);

#define ggml_debug(source, ...) ggml_logger_log(source, GGML_LOG_LEVEL_DEBUG, __VA_ARGS__)
#define ggml_info(source, ...) ggml_logger_log(source, GGML_LOG_LEVEL_INFO, __VA_ARGS__)
#define ggml_warn(source, ...) ggml_logger_log(source, GGML_LOG_LEVEL_WARN, __VA_ARGS__)
#define ggml_error(source, ...) ggml_logger_log(source, GGML_LOG_LEVEL_ERROR, __VA_ARGS__)

void ggml_logger_add_handler(const char *source, ggml_log_level level, ggml_logger_log_handler handler, void *user_data);
void ggml_logger_remove_handler(const char *source, ggml_log_level level, ggml_logger_log_handler handler);

void ggml_logger_add_source(const char *name);
void ggml_logger_remove_source(const char *name);

void ggml_logger_init();
void ggml_logger_cleanup();

The motivation is to allow log events to be tracked to a given subsystem (like ggml backend, ggml, llama, application etc...). This modularity will allow us to clean up the various fprintf(stderr,...) statements, and make logging capabilities more robust. In addition to the above changes, this will require changes to the llama.h/cpp sources to incorporate the above interface as well, and also in the common library.

In terms of the implementation in ggml-logger.cpp, I think a reasonable start would be to simply use something like:

// Ensure per-source thread safety.
std::unordered_map<std::string, std::mutex> g_source_locks;

// In this case, would allow for multiple log handlers for a given log level/source.
std::unordered_map<std::string, std::unordered_map<ggml_log_level, std::vector<ggml_logger_log_handler> > > g_handlers;

// ...

[slaren]

I think it would be good to have an unified logging system in ggml. Some suggestions about the proposed API:

void ggml_logger_add_handler(const char *source, ggml_log_level level, ggml_logger_log_handler handler, void *user_data);
void ggml_logger_remove_handler(const char *source, ggml_log_level level, ggml_logger_log_handler handler);

Remove the source and level parameters, the handler can do the filtering by itself.

void ggml_logger_add_source(const char *name);
void ggml_logger_remove_source(const char *name);

void ggml_logger_init();
void ggml_logger_cleanup();

Remove these entirely, and do any required initialization on the first call.

[bandoti]

I suppose we can defer the source/level specific handling to the handlers. One thing to consider is the thread safety on a per-source, per-level basis. If we don't store the separate handlers internally in the ggml-logger, the locking mechanism (for better or worse) will be either lock the whole thing, or don't be thread safe.

A scenario where this could be relevant is if we wanted to add stats logging that had a bunch of messages going through, and we want to separate it from info, debug, error. There will be lock contention there using one lock. My thought was that we can handle some of this behavior within the ggml-logger since users will basically be reinventing the wheel.

[slaren]

I don't think we need to worry about contention in a logging system, there isn't any logging in performance sensitive paths. I think that ease of use of the API is the most important concern in this case. A global lock should be fine.

[bandoti]

Yeah that makes sense. Best to err on the side of simplicity 😃. Okay I'm on board with that.

[bandoti]

@ggerganov
In light of the recent logging changes in common, is this change something that you'd be interested in having? The recently added logging mechanism in common would simply register with the handler mentioned here, should I implement it. 😊

[ggerganov]

Yes, it's still necessary to add common log callback to ggml.

Regarding the implementation, I think it can be similar to what we have in llama.cpp:

• Log macros defined in ggml-impl.h, similar to llama-impl.h:
  https://github.com/ggerganov/llama.cpp/blob/70392f1f81470607ba3afef04aa56c9f65587664/src/llama-impl.h#L19-L32
• Single ggml_log_set API call simliar to llama_log_set. The callback removal can be done by passing NULL or empty callback function, so no need for separate function.
• When llama_log_set is called, it can also internally call ggml_log_set to avoid the user code to have to explicitly also set the ggml callback
• The various backend-specific log setups, should be removed and the backend should start using the macros from the ggml-impl.h
  https://github.com/ggerganov/llama.cpp/blob/70392f1f81470607ba3afef04aa56c9f65587664/src/llama.cpp#L21414-L21420

[bandoti]

Sounds good to me. I'll create an issue to track this and start working on it. Thanks.

[bandoti]

I created #9706 to track the GGML logging changes.