From 86ba37d8f17faf7f8a0149d98732d59699ae369c Mon Sep 17 00:00:00 2001 From: Maria Matejka Date: Sun, 28 Jan 2024 21:42:39 +0100 Subject: [PATCH] Logging: uses writev instead of in-buffer magic --- lib/birdlib.h | 12 ++++- sysdep/unix/config.Y | 2 +- sysdep/unix/io.c | 84 ++++++++++++++++++++++++++------- sysdep/unix/log.c | 109 +++++++++++++++++++++++++++---------------- sysdep/unix/unix.h | 4 +- 5 files changed, 150 insertions(+), 61 deletions(-) diff --git a/lib/birdlib.h b/lib/birdlib.h index 9004704c..214b49bf 100644 --- a/lib/birdlib.h +++ b/lib/birdlib.h @@ -163,10 +163,18 @@ typedef struct buffer { #define LOG_BUFFER_SIZE 2560 +enum log_buffer_pos { + LBP_TIMESTAMP = 0, + LBP_THREAD_ID, + LBP_CLASS, + LBP_MSG, + LBP__MAX, + LBPP_TERMINAL, +}; + typedef struct log_buffer { struct buffer buf; - byte *tm_pos; - byte *msg_pos; + byte *pos[LBP__MAX+1]; int class; char block[LOG_BUFFER_SIZE]; } log_buffer; diff --git a/sysdep/unix/config.Y b/sysdep/unix/config.Y index a4aed847..ee58b21b 100644 --- a/sysdep/unix/config.Y +++ b/sysdep/unix/config.Y @@ -66,7 +66,7 @@ log_file: this_log->filename = $2; } | SYSLOG syslog_name { this_log->rf = NULL; new_config->syslog_name = $2; } - | STDERR { this_log->rf = &rf_stderr; } + | STDERR { this_log->rf = &rf_stderr; this_log->terminal_flag = 1; } ; log_mask: diff --git a/sysdep/unix/io.c b/sysdep/unix/io.c index ce5a3d63..f2f99fdd 100644 --- a/sysdep/unix/io.c +++ b/sysdep/unix/io.c @@ -192,36 +192,88 @@ rf_same(struct rfile *a, struct rfile *b) (a->stat.st_ino == b->stat.st_ino); } -int -rf_write(struct rfile *r, const void *buf, size_t _count) +void +rf_write_crude(struct rfile *r, const char *buf, int sz) { - off_t count = _count; + if (r->mapping) + memcpy(r->mapping, buf, sz); + else + write(r->fd, buf, sz); +} + + +int +rf_writev(struct rfile *r, struct iovec *iov, int iov_count) +{ + off_t size = 0; + for (int i = 0; i < iov_count; i++) + size += iov[i].iov_len; if (r->mapping) { /* Update the pointer */ - off_t target = atomic_fetch_add_explicit(&r->pos, count, memory_order_relaxed) % r->limit; - - /* Take care of wrapping */ - if (target + count > r->limit) - { - memcpy(r->mapping, buf + (r->limit - target), target + count - r->limit); - count = r->limit - target; - } + off_t target = atomic_fetch_add_explicit(&r->pos, size, memory_order_relaxed) % r->limit; /* Write the line */ - memcpy(r->mapping + target, buf, count); + for (int i = 0; i < iov_count; i++) + { + /* Take care of wrapping; this should really happen only once */ + off_t rsz; + while ((rsz = r->limit - target) < (off_t) iov[i].iov_len) + { + memcpy(r->mapping + target, iov[i].iov_base, rsz); + iov[i].iov_base += rsz; + iov[i].iov_len -= rsz; + target = 0; + } + + memcpy(r->mapping + target, iov[i].iov_base, iov[i].iov_len); + target += iov[i].iov_len; + } return 1; } - else if (r->limit && (atomic_fetch_add_explicit(&r->pos, count, memory_order_relaxed) + count > r->limit)) + else if (r->limit && (atomic_fetch_add_explicit(&r->pos, size, memory_order_relaxed) + size > r->limit)) { - atomic_fetch_sub_explicit(&r->pos, count, memory_order_relaxed); + atomic_fetch_sub_explicit(&r->pos, size, memory_order_relaxed); return 0; } else { - while ((write(r->fd, buf, count) < 0) && (errno == EINTR)) - ; + while (size > 0) + { + /* Try to write */ + ssize_t e = writev(r->fd, iov, iov_count); + if (e < 0) + if (errno == EINTR) + continue; + else + return 1; /* FIXME: What should we do when we suddenly can't write? */ + + /* It is expected that we always write the whole bunch at once */ + if (e == size) + return 1; + + /* Block split should not happen (we write small enough messages) + * but if it happens, let's try to write the rest of the log */ + size -= e; + while (e > 0) + { + if ((ssize_t) iov[0].iov_len > e) + { + /* Some bytes are remaining in the first chunk */ + iov[0].iov_len -= e; + iov[0].iov_base += e; + break; + } + + /* First chunk written completely, get rid of it */ + e -= iov[0].iov_len; + iov++; + iov_count--; + ASSERT_DIE(iov_count > 0); + } + } + return 1; } } diff --git a/sysdep/unix/log.c b/sysdep/unix/log.c index bbe1bd8e..6119b952 100644 --- a/sysdep/unix/log.c +++ b/sysdep/unix/log.c @@ -48,8 +48,6 @@ static DOMAIN(logging) log_domain; static struct log_channel * _Atomic global_logs; /* Logging flags to validly prepare logging messages */ -#define LOGGING_TO_TERMINAL 0x1 -#define LOGGING_TO_FILE 0x2 static _Atomic uint logging_flags; static _Atomic uint logging_mask; @@ -92,7 +90,7 @@ struct log_channel { off_t limit; /* Log size limit */ _Atomic uint mask; /* Classes to log */ uint new_mask; /* Pending new mask */ - uint terminal:1; /* Is terminal */ + uint prepare; /* Which message parts to prepare */ }; struct log_thread_syncer { @@ -174,6 +172,10 @@ log_rotate(struct log_channel *lc) void log_commit(log_buffer *buf) { + /* Store the last pointer */ + buf->pos[LBP__MAX] = buf->buf.pos; + + /* Append the too-long message if too long */ if (buf->buf.pos == buf->buf.end) #define TOO_LONG " ... " memcpy(buf->buf.end - sizeof TOO_LONG, TOO_LONG, sizeof TOO_LONG); @@ -190,18 +192,44 @@ log_commit(log_buffer *buf) continue; struct rfile *rf = atomic_load_explicit(&l->rf, memory_order_acquire); - if (rf && buf->tm_pos) + if (rf) { - *buf->buf.pos = '\n'; - byte *begin = l->terminal ? buf->buf.start : buf->tm_pos; - off_t msg_len = buf->buf.pos - begin + 1; + /* Construct the iovec */ + static char terminal_prefix[] = "bird: ", + newline[] = "\n"; + STATIC_ASSERT(sizeof newline == 2); + + struct iovec iov[LBP__MAX+2]; + uint iov_count = 0; + if (BIT32_TEST(&l->prepare, LBPP_TERMINAL)) + iov[iov_count++] = (struct iovec) { + .iov_base = terminal_prefix, + .iov_len = sizeof terminal_prefix - 1, + }; + + for (uint p = 0; p < LBP__MAX; p++) + if (BIT32_TEST(&l->prepare, p)) + { + off_t sz = buf->pos[p+1] - buf->pos[p]; + if (sz > 0) + iov[iov_count++] = (struct iovec) { + .iov_base = buf->pos[p], + .iov_len = sz, + }; + } + + iov[iov_count++] = (struct iovec) { + .iov_base = newline, + .iov_len = sizeof newline - 1, + }; + do { - if (rf_write(rf, begin, msg_len)) + if (rf_writev(rf, iov, iov_count)) break; log_lock(); rf = atomic_load_explicit(&l->rf, memory_order_acquire); - if (rf_write(rf, begin, msg_len)) + if (rf_writev(rf, iov, iov_count)) { log_unlock(); break; @@ -211,18 +239,15 @@ log_commit(log_buffer *buf) log_unlock(); rf = atomic_load_explicit(&l->rf, memory_order_relaxed); - } while (!rf_write(rf, begin, msg_len)); + } while (!rf_writev(rf, iov, iov_count)); } #ifdef HAVE_SYSLOG_H else { - *buf->buf.pos = '\0'; - syslog(syslog_priorities[buf->class], "%s", buf->msg_pos); + syslog(syslog_priorities[buf->class], "%s", buf->pos[LBP_MSG]); } #endif } - - buf->msg_pos = buf->tm_pos = NULL; } int buffer_vprint(buffer *buf, const char *fmt, va_list args); @@ -230,31 +255,35 @@ int buffer_vprint(buffer *buf, const char *fmt, va_list args); void log_prepare(log_buffer *buf, int class) { + buf->class = class; + buf->buf.start = buf->buf.pos = buf->block; buf->buf.end = buf->block + sizeof buf->block; int lf = atomic_load_explicit(&logging_flags, memory_order_acquire); - if (lf & LOGGING_TO_TERMINAL) - buffer_puts(&buf->buf, "bird: "); - if (lf & LOGGING_TO_FILE) + buf->pos[LBP_TIMESTAMP] = buf->buf.pos; + if (BIT32_TEST(&lf, LBP_TIMESTAMP)) { const char *fmt = config ? config->tf_log.fmt1 : "%F %T.%3f"; - - buf->tm_pos = buf->buf.pos; int t = tm_format_real_time(buf->buf.pos, buf->buf.end - buf->buf.pos, fmt, current_real_time()); if (t) buf->buf.pos += t; else buffer_puts(&buf->buf, "