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 <s...@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 secur...@mariadb.org
>
_______________________________________________
developers mailing list -- developers@lists.mariadb.org
To unsubscribe send an email to developers-le...@lists.mariadb.org
