Re: b7dbe187b1a: MDEV-34680 Asynchronous and Buffered Logging for Audit Plugin.
Hi, Alexey, See few comments below. But the main question, could you have used FILE or IO_CACHE instead of a custom implementation? On Mar 08, Alexey Botchkov wrote:
revision-id: b7dbe187b1a (mariadb-11.8.1-8-gb7dbe187b1a) parent(s): 6f1161aa34c author: Alexey Botchkov committer: Alexey Botchkov timestamp: 2025-03-02 16:27:23 +0400 message:
MDEV-34680 Asynchronous and Buffered Logging for Audit Plugin.
Buffering added to the file logger. Two buffers are created so writing to the file doesn't block other threads from logging. Operations isolated with two mutexes.
diff --git a/include/mysql/service_logger.h b/include/mysql/service_logger.h index 35c2eb1e3a9..adce7bc9038 100644 --- a/include/mysql/service_logger.h +++ b/include/mysql/service_logger.h @@ -64,41 +64,44 @@ extern struct logger_service_st { void (*logger_init_mutexes)(); LOGGER_HANDLE* (*open)(const char *path, unsigned long long size_limit, - unsigned int rotations); + unsigned int rotations, size_t buffer_size);
incompatible API change. MUST change the major service version.
int (*close)(LOGGER_HANDLE *log); int (*vprintf)(LOGGER_HANDLE *log, const char *fmt, va_list argptr) ATTRIBUTE_FORMAT_FPTR(printf, 2, 0); int (*printf)(LOGGER_HANDLE *log, const char *fmt, ...) ATTRIBUTE_FORMAT_FPTR(printf, 2, 3); - int (*write)(LOGGER_HANDLE *log, const char *buffer, size_t size); + int (*write)(LOGGER_HANDLE *log, const void *data, size_t size); int (*rotate)(LOGGER_HANDLE *log); + int (*sync)(LOGGER_HANDLE *log); } *logger_service;
#ifdef MYSQL_DYNAMIC_PLUGIN
#define logger_init_mutexes logger_service->logger_init_mutexes -#define logger_open(path, size_limit, rotations) \ - (logger_service->open(path, size_limit, rotations)) +#define logger_open(path, size_limit, rotations, buffer_size) \ + (logger_service->open(path, size_limit, rotations, buffer_size)) #define logger_close(log) (logger_service->close(log)) #define logger_rotate(log) (logger_service->rotate(log)) +#define logger_rsync(log) (logger_service->sync(log)) #define logger_vprintf(log, fmt, argptr) (logger_service->\ vprintf(log, fmt, argptr)) #define logger_printf (*logger_service->printf) -#define logger_write(log, buffer, size) \ - (logger_service->write(log, buffer, size)) +#define logger_write(log, data, size) \ + (logger_service->write(log, data, size)) #else
void logger_init_mutexes(); LOGGER_HANDLE *logger_open(const char *path, unsigned long long size_limit, - unsigned int rotations); + unsigned int rotations, size_t buffer_size); int logger_close(LOGGER_HANDLE *log); int logger_vprintf(LOGGER_HANDLE *log, const char *fmt, va_list argptr) ATTRIBUTE_FORMAT(printf, 2, 0); int logger_printf(LOGGER_HANDLE *log, const char *fmt, ...) ATTRIBUTE_FORMAT(printf, 2, 3); - int logger_write(LOGGER_HANDLE *log, const char *buffer, size_t size); + int logger_write(LOGGER_HANDLE *log, const void *data, size_t size); int logger_rotate(LOGGER_HANDLE *log); + int logger_sync(LOGGER_HANDLE *log); #endif
diff --git a/mysys/file_logger.c b/mysys/file_logger.c index a753c049f68..5464e43eddf 100644 --- a/mysys/file_logger.c +++ b/mysys/file_logger.c @@ -145,85 +230,108 @@ static int do_rotate(LOGGER_HANDLE *log) namebuf[log->path_len]= 0; result= my_rename(namebuf, logname(log, log->path, 1), MYF(0)); log->file= my_open(namebuf, LOG_FLAGS, MYF(0)); + log->in_file= 0; exit: errno= my_errno; return log->file < 0 || result; }
-/* - Return 1 if we should rotate the log -*/ - -my_bool logger_time_to_rotate(LOGGER_HANDLE *log) -{ - my_off_t filesize; - if (log->rotations > 0 && - (filesize= my_tell(log->file, MYF(0))) != (my_off_t) -1 && - ((ulonglong) filesize >= log->size_limit)) - return 1; - return 0; -} - - int logger_vprintf(LOGGER_HANDLE *log, const char* fmt, va_list ap) { - int result; char cvtbuf[1024]; size_t n_bytes;
- flogger_mutex_lock(&log->lock); - if (logger_time_to_rotate(log) && do_rotate(log)) - { - result= -1; - errno= my_errno; - goto exit; /* Log rotation needed but failed */ - } - n_bytes= my_vsnprintf(cvtbuf, sizeof(cvtbuf), fmt, ap); if (n_bytes >= sizeof(cvtbuf)) n_bytes= sizeof(cvtbuf) - 1;
- result= (int)my_write(log->file, (uchar *) cvtbuf, n_bytes, MYF(0)); - -exit: - flogger_mutex_unlock(&log->lock); - return result; + return logger_write(log, cvtbuf, n_bytes); }
-static int logger_write_r(LOGGER_HANDLE *log, my_bool allow_rotations, - const char *buffer, size_t size) +int logger_write(LOGGER_HANDLE *log, const void *data, size_t size) { int result; + size_t in_buffer; + + mysql_mutex_lock(&log->lock);
- flogger_mutex_lock(&log->lock); - if (allow_rotations && logger_time_to_rotate(log) && do_rotate(log)) + if (log->buffer_left >= size) + { + memcpy(log->buffer_pos, data, size); + log->buffer_pos+= size; + log->buffer_left-= size; + mysql_mutex_unlock(&log->lock); + return size; + } + + mysql_mutex_lock(&log->lock_buffer); + + in_buffer= log->buffer_pos - log->buffer; + + { /* swap buffers. */ + uchar *tmp_buf= log->buffer; + log->buffer= log->idle_buffer; + log->idle_buffer= tmp_buf; + } + + set_buffer_pos_and_left(log); + + /* Now other threads can write to the new buffer. */ + mysql_mutex_unlock(&log->lock); + + if ((in_buffer && + my_write(log->file, log->idle_buffer, in_buffer, MYF(0)) != in_buffer)|| + my_write(log->file, (uchar *) data, size, MYF(0)) != size) { result= -1; errno= my_errno; - goto exit; /* Log rotation needed but failed */ + goto exit_buf; } + else + result= 0;
- result= (int)my_write(log->file, (uchar *) buffer, size, MYF(0)); + log->in_file+= in_buffer + size; + if (log->rotations > 0 && log->in_file >= log->size_limit) + { + if (do_rotate(log)) + { + result= -1; + errno= my_errno; + goto exit_buf; /* Log rotation needed but failed */ + } + }
-exit: - flogger_mutex_unlock(&log->lock); +exit_buf: + mysql_mutex_unlock(&log->lock_buffer); return result; }
-int logger_write(LOGGER_HANDLE *log, const char *buffer, size_t size) -{ - return logger_write_r(log, TRUE, buffer, size); -} - int logger_rotate(LOGGER_HANDLE *log) { int result; - flogger_mutex_lock(&log->lock); - result= do_rotate(log); - flogger_mutex_unlock(&log->lock); + mysql_mutex_lock(&log->lock); + mysql_mutex_lock(&log->lock_buffer); + result= flush_buffer(log) || do_rotate(log);
I'd though you can switch buffers here too and flush/rotate only under the lock_buffer mutex
+ mysql_mutex_unlock(&log->lock_buffer); + mysql_mutex_unlock(&log->lock); + return result; +} + + +int logger_sync(LOGGER_HANDLE *log)
Why did you introduce an explicit sync API?
+{ + int result; + mysql_mutex_lock(&log->lock); + mysql_mutex_lock(&log->lock_buffer); + if ((result= flush_buffer(log))) + { + result= fsync(log->file); + } + mysql_mutex_unlock(&log->lock_buffer); + mysql_mutex_unlock(&log->lock); return result; }
diff --git a/plugin/server_audit/server_audit.c b/plugin/server_audit/server_audit.c index 5fc0e3373f3..e51df7ab6b5 100644 --- a/plugin/server_audit/server_audit.c +++ b/plugin/server_audit/server_audit.c @@ -1393,26 +1401,15 @@ static void change_connection(struct connection_info *cn, static int write_log(const char *message, size_t len, int take_lock) { int result= 0; + if (take_lock) - { - /* Start by taking a read lock */ mysql_prlock_rdlock(&lock_operations); - }
if (output_type == OUTPUT_FILE) { if (logfile) { - my_bool allow_rotate= !take_lock; /* Allow rotate if caller write lock */ - if (take_lock && logger_time_to_rotate(logfile)) - { - /* We have to rotate the log, change above read lock to write lock */ - mysql_prlock_unlock(&lock_operations); - mysql_prlock_wrlock(&lock_operations); - allow_rotate= 1; - } - if (!(is_active= (logger_write_r(logfile, allow_rotate, message, len) == - (int) len))) + if (!(is_active= (logger_write(logfile, message, len) == (int) len)))
nice, rotation is indeed the logger's headache, not the caller's
{ ++log_write_failures; result= 1; @@ -2899,6 +2906,36 @@ static void update_file_rotations(MYSQL_THD thd __attribute__((unused)), }
+static void update_file_buffer_size(MYSQL_THD thd __attribute__((unused)), + struct st_mysql_sys_var *var __attribute__((unused)), + void *var_ptr __attribute__((unused)), const void *save) +{ + file_buffer_size= *(unsigned int *) save; + + error_header(); + fprintf(stderr, "Log file buffer size was changed to '%d'.\n", file_buffer_size); + + if (!logging || output_type != OUTPUT_FILE) + return; + + ADD_ATOMIC(internal_stop_logging, 1); + if (!maria_55_started || !debug_server_started) + mysql_prlock_wrlock(&lock_operations); + + stop_logging(); + if (start_logging())
this could be an API call in the logger. Like "reinit(new params)" and it'll close, change params, open - all under a log mutex, which doesn't need to be destroyed and reinitialized.
+ { + error_header(); + fprintf(stderr, "Logging was disabled..\n"); + CLIENT_ERROR(1, "Logging was disabled.", MYF(ME_WARNING)); + } + + if (!maria_55_started || !debug_server_started) + mysql_prlock_unlock(&lock_operations); + ADD_ATOMIC(internal_stop_logging, -1); +} + + static void update_file_rotate_size(MYSQL_THD thd __attribute__((unused)), struct st_mysql_sys_var *var __attribute__((unused)), void *var_ptr __attribute__((unused)), const void *save)
Regards, Sergei Chief Architect, MariaDB Server and security@mariadb.org
I've submitted the IO_CACHE version for your review. Below are the relievant answers.
+int logger_sync(LOGGER_HANDLE *log) Why did you introduce an explicit sync API? I added it mostly for the testing. If the log is in the buffer, i'm not sure how to add it to the result file. The customer usage is also possible - if the administrator wants to take a look the most recent log records and nobody works with the server.
this could be an API call in the logger. Like "reinit(new params)" and it'll close, change params, open - all under a log mutex, which doesn't need to be destroyed and reinitialized.
Probably. But for now i like the two calls better. Best regards. HF On Sat, Mar 8, 2025 at 9:26 PM Sergei Golubchik <serg@mariadb.org> wrote:
Hi, Alexey,
See few comments below.
But the main question, could you have used FILE or IO_CACHE instead of a custom implementation?
On Mar 08, Alexey Botchkov wrote:
revision-id: b7dbe187b1a (mariadb-11.8.1-8-gb7dbe187b1a) parent(s): 6f1161aa34c author: Alexey Botchkov committer: Alexey Botchkov timestamp: 2025-03-02 16:27:23 +0400 message:
MDEV-34680 Asynchronous and Buffered Logging for Audit Plugin.
Buffering added to the file logger. Two buffers are created so writing to the file doesn't block other threads from logging. Operations isolated with two mutexes.
diff --git a/include/mysql/service_logger.h b/include/mysql/service_logger.h index 35c2eb1e3a9..adce7bc9038 100644 --- a/include/mysql/service_logger.h +++ b/include/mysql/service_logger.h @@ -64,41 +64,44 @@ extern struct logger_service_st { void (*logger_init_mutexes)(); LOGGER_HANDLE* (*open)(const char *path, unsigned long long size_limit, - unsigned int rotations); + unsigned int rotations, size_t buffer_size);
incompatible API change. MUST change the major service version.
int (*close)(LOGGER_HANDLE *log); int (*vprintf)(LOGGER_HANDLE *log, const char *fmt, va_list argptr) ATTRIBUTE_FORMAT_FPTR(printf, 2, 0); int (*printf)(LOGGER_HANDLE *log, const char *fmt, ...) ATTRIBUTE_FORMAT_FPTR(printf, 2, 3); - int (*write)(LOGGER_HANDLE *log, const char *buffer, size_t size); + int (*write)(LOGGER_HANDLE *log, const void *data, size_t size); int (*rotate)(LOGGER_HANDLE *log); + int (*sync)(LOGGER_HANDLE *log); } *logger_service;
#ifdef MYSQL_DYNAMIC_PLUGIN
#define logger_init_mutexes logger_service->logger_init_mutexes -#define logger_open(path, size_limit, rotations) \ - (logger_service->open(path, size_limit, rotations)) +#define logger_open(path, size_limit, rotations, buffer_size) \ + (logger_service->open(path, size_limit, rotations, buffer_size)) #define logger_close(log) (logger_service->close(log)) #define logger_rotate(log) (logger_service->rotate(log)) +#define logger_rsync(log) (logger_service->sync(log)) #define logger_vprintf(log, fmt, argptr) (logger_service->\ vprintf(log, fmt, argptr)) #define logger_printf (*logger_service->printf) -#define logger_write(log, buffer, size) \ - (logger_service->write(log, buffer, size)) +#define logger_write(log, data, size) \ + (logger_service->write(log, data, size)) #else
void logger_init_mutexes(); LOGGER_HANDLE *logger_open(const char *path, unsigned long long size_limit, - unsigned int rotations); + unsigned int rotations, size_t buffer_size); int logger_close(LOGGER_HANDLE *log); int logger_vprintf(LOGGER_HANDLE *log, const char *fmt, va_list argptr) ATTRIBUTE_FORMAT(printf, 2, 0); int logger_printf(LOGGER_HANDLE *log, const char *fmt, ...) ATTRIBUTE_FORMAT(printf, 2, 3); - int logger_write(LOGGER_HANDLE *log, const char *buffer, size_t size); + int logger_write(LOGGER_HANDLE *log, const void *data, size_t size); int logger_rotate(LOGGER_HANDLE *log); + int logger_sync(LOGGER_HANDLE *log); #endif
diff --git a/mysys/file_logger.c b/mysys/file_logger.c index a753c049f68..5464e43eddf 100644 --- a/mysys/file_logger.c +++ b/mysys/file_logger.c @@ -145,85 +230,108 @@ static int do_rotate(LOGGER_HANDLE *log) namebuf[log->path_len]= 0; result= my_rename(namebuf, logname(log, log->path, 1), MYF(0)); log->file= my_open(namebuf, LOG_FLAGS, MYF(0)); + log->in_file= 0; exit: errno= my_errno; return log->file < 0 || result; }
-/* - Return 1 if we should rotate the log -*/ - -my_bool logger_time_to_rotate(LOGGER_HANDLE *log) -{ - my_off_t filesize; - if (log->rotations > 0 && - (filesize= my_tell(log->file, MYF(0))) != (my_off_t) -1 && - ((ulonglong) filesize >= log->size_limit)) - return 1; - return 0; -} - - int logger_vprintf(LOGGER_HANDLE *log, const char* fmt, va_list ap) { - int result; char cvtbuf[1024]; size_t n_bytes;
- flogger_mutex_lock(&log->lock); - if (logger_time_to_rotate(log) && do_rotate(log)) - { - result= -1; - errno= my_errno; - goto exit; /* Log rotation needed but failed */ - } - n_bytes= my_vsnprintf(cvtbuf, sizeof(cvtbuf), fmt, ap); if (n_bytes >= sizeof(cvtbuf)) n_bytes= sizeof(cvtbuf) - 1;
- result= (int)my_write(log->file, (uchar *) cvtbuf, n_bytes, MYF(0)); - -exit: - flogger_mutex_unlock(&log->lock); - return result; + return logger_write(log, cvtbuf, n_bytes); }
-static int logger_write_r(LOGGER_HANDLE *log, my_bool allow_rotations, - const char *buffer, size_t size) +int logger_write(LOGGER_HANDLE *log, const void *data, size_t size) { int result; + size_t in_buffer; + + mysql_mutex_lock(&log->lock);
- flogger_mutex_lock(&log->lock); - if (allow_rotations && logger_time_to_rotate(log) && do_rotate(log)) + if (log->buffer_left >= size) + { + memcpy(log->buffer_pos, data, size); + log->buffer_pos+= size; + log->buffer_left-= size; + mysql_mutex_unlock(&log->lock); + return size; + } + + mysql_mutex_lock(&log->lock_buffer); + + in_buffer= log->buffer_pos - log->buffer; + + { /* swap buffers. */ + uchar *tmp_buf= log->buffer; + log->buffer= log->idle_buffer; + log->idle_buffer= tmp_buf; + } + + set_buffer_pos_and_left(log); + + /* Now other threads can write to the new buffer. */ + mysql_mutex_unlock(&log->lock); + + if ((in_buffer && + my_write(log->file, log->idle_buffer, in_buffer, MYF(0)) != in_buffer)|| + my_write(log->file, (uchar *) data, size, MYF(0)) != size) { result= -1; errno= my_errno; - goto exit; /* Log rotation needed but failed */ + goto exit_buf; } + else + result= 0;
- result= (int)my_write(log->file, (uchar *) buffer, size, MYF(0)); + log->in_file+= in_buffer + size; + if (log->rotations > 0 && log->in_file >= log->size_limit) + { + if (do_rotate(log)) + { + result= -1; + errno= my_errno; + goto exit_buf; /* Log rotation needed but failed */ + } + }
-exit: - flogger_mutex_unlock(&log->lock); +exit_buf: + mysql_mutex_unlock(&log->lock_buffer); return result; }
-int logger_write(LOGGER_HANDLE *log, const char *buffer, size_t size) -{ - return logger_write_r(log, TRUE, buffer, size); -} - int logger_rotate(LOGGER_HANDLE *log) { int result; - flogger_mutex_lock(&log->lock); - result= do_rotate(log); - flogger_mutex_unlock(&log->lock); + mysql_mutex_lock(&log->lock); + mysql_mutex_lock(&log->lock_buffer); + result= flush_buffer(log) || do_rotate(log);
I'd though you can switch buffers here too and flush/rotate only under the lock_buffer mutex
+ mysql_mutex_unlock(&log->lock_buffer); + mysql_mutex_unlock(&log->lock); + return result; +} + + +int logger_sync(LOGGER_HANDLE *log)
Why did you introduce an explicit sync API?
+{ + int result; + mysql_mutex_lock(&log->lock); + mysql_mutex_lock(&log->lock_buffer); + if ((result= flush_buffer(log))) + { + result= fsync(log->file); + } + mysql_mutex_unlock(&log->lock_buffer); + mysql_mutex_unlock(&log->lock); return result; }
diff --git a/plugin/server_audit/server_audit.c b/plugin/server_audit/server_audit.c index 5fc0e3373f3..e51df7ab6b5 100644 --- a/plugin/server_audit/server_audit.c +++ b/plugin/server_audit/server_audit.c @@ -1393,26 +1401,15 @@ static void change_connection(struct connection_info *cn, static int write_log(const char *message, size_t len, int take_lock) { int result= 0; + if (take_lock) - { - /* Start by taking a read lock */ mysql_prlock_rdlock(&lock_operations); - }
if (output_type == OUTPUT_FILE) { if (logfile) { - my_bool allow_rotate= !take_lock; /* Allow rotate if caller write lock */ - if (take_lock && logger_time_to_rotate(logfile)) - { - /* We have to rotate the log, change above read lock to write lock */ - mysql_prlock_unlock(&lock_operations); - mysql_prlock_wrlock(&lock_operations); - allow_rotate= 1; - } - if (!(is_active= (logger_write_r(logfile, allow_rotate, message, len) == - (int) len))) + if (!(is_active= (logger_write(logfile, message, len) == (int) len)))
nice, rotation is indeed the logger's headache, not the caller's
{ ++log_write_failures; result= 1; @@ -2899,6 +2906,36 @@ static void update_file_rotations(MYSQL_THD thd
__attribute__((unused)),
}
+static void update_file_buffer_size(MYSQL_THD thd __attribute__((unused)), + struct st_mysql_sys_var *var __attribute__((unused)), + void *var_ptr __attribute__((unused)), const void *save) +{ + file_buffer_size= *(unsigned int *) save; + + error_header(); + fprintf(stderr, "Log file buffer size was changed to '%d'.\n", file_buffer_size); + + if (!logging || output_type != OUTPUT_FILE) + return; + + ADD_ATOMIC(internal_stop_logging, 1); + if (!maria_55_started || !debug_server_started) + mysql_prlock_wrlock(&lock_operations); + + stop_logging(); + if (start_logging())
this could be an API call in the logger. Like "reinit(new params)" and it'll close, change params, open - all under a log mutex, which doesn't need to be destroyed and reinitialized.
+ { + error_header(); + fprintf(stderr, "Logging was disabled..\n"); + CLIENT_ERROR(1, "Logging was disabled.", MYF(ME_WARNING)); + } + + if (!maria_55_started || !debug_server_started) + mysql_prlock_unlock(&lock_operations); + ADD_ATOMIC(internal_stop_logging, -1); +} + + static void update_file_rotate_size(MYSQL_THD thd __attribute__((unused)), struct st_mysql_sys_var *var __attribute__((unused)), void *var_ptr __attribute__((unused)), const void *save)
Regards, Sergei Chief Architect, MariaDB Server and security@mariadb.org
participants (2)
-
Alexey Botchkov -
Sergei Golubchik