From f176f3c80e56517bedc17611fbb55e925d5e2cb4 Mon Sep 17 00:00:00 2001 From: Mateusz Majewski Date: Tue, 24 Mar 2020 16:00:13 +0100 Subject: [PATCH] libdlogutil: refactor mainloop to work on single logs The main worker function now calls the callback on a single log. Backward compatibility is maintained through a wrapper. Change-Id: Iaacc48977c360b12bba3b06ab0a51fe2ba18bf3f Signed-off-by: Michal Bloch --- src/libdlogutil/logretrieve.c | 121 +++++++++++++++++++++++++++--------------- src/tests/logutil.c | 28 ++++------ 2 files changed, 87 insertions(+), 62 deletions(-) diff --git a/src/libdlogutil/logretrieve.c b/src/libdlogutil/logretrieve.c index 038a75b..866418f 100644 --- a/src/libdlogutil/logretrieve.c +++ b/src/libdlogutil/logretrieve.c @@ -122,31 +122,32 @@ struct fd_info *find_earliest_log(struct fd_info **data_fds, int fd_count, dlogu return best_fdi; } -int put_logs_into_vector(struct fd_info **data_fds, int fd_count, struct sort_vector *logs, dlogutil_entry_cb callback, void *userdata, dlogutil_filter_options_s *filter) +enum { + ALL_BUFFERS_EMPTY = 1, + BUFFER_NEWLY_DRAINED = 2, +}; +int put_logs_into_vector(struct fd_info **data_fds, int fd_count, struct sort_vector *logs, dlogutil_filter_options_s *filter, dlogutil_entry_s **entry_out) { assert(data_fds); assert(logs); assert(filter); + assert(entry_out); + *entry_out = NULL; struct fd_info *best_fdi; do { best_fdi = find_earliest_log(data_fds, fd_count, logs->sort_by); if (!best_fdi) - return 1; + return ALL_BUFFERS_EMPTY; - dlogutil_entry_s *entry; - int r = fdi_push_log(best_fdi, logs, &entry, filter); + int r = fdi_push_log(best_fdi, logs, entry_out, filter); if (r) return r; - - if (entry) { - r = callback(entry, userdata); - if (r) - return r; - } + if (*entry_out) + return best_fdi->ops->has_log(best_fdi) ? 0 : BUFFER_NEWLY_DRAINED; } while (best_fdi->ops->has_log(best_fdi)); // if a buffer got drained, break to give them all a chance to refill - return 0; + return BUFFER_NEWLY_DRAINED; } int dlogutil_state_init(dlogutil_state_s *state, struct fd_info ***data_fds_ptr, int fd_count, unsigned int mode, bool monitor, dlogutil_entry_cb callback, void *userdata, @@ -234,8 +235,9 @@ int dlogutil_state_init(dlogutil_state_s *state, struct fd_info ***data_fds_ptr, * @param[in] l_file File output metadata * @return int 0 if successful, a negative value on error, callback's return value if it isn't 0 */ -int do_print(dlogutil_state_s *state) +int do_print_once(dlogutil_state_s *state, dlogutil_entry_s **out) { + *out = NULL; while (state->epoll_cnt > 0) { if (state->flush_target < LONG_MAX) { if (!sort_vector_empty(&state->logs)) { @@ -244,38 +246,44 @@ int do_print(dlogutil_state_s *state) struct timespec log_ts; if (dlogutil_entry_get_timestamp(e, state->logs.sort_by, &log_ts) // flush timestampless logs immediately since waiting won't help || log_ts.tv_sec * 1000 + log_ts.tv_nsec / 1000000 <= state->flush_target) { - int r = state->callback(e, state->userdata); - if (r != 0) - return r; - - sort_vector_pop(&state->logs); - continue; + *out = sort_vector_pop_ret(&state->logs); + return 0; } } state->flush_target = LONG_MAX; } - int r = put_logs_into_vector(state->data_fds, state->fd_count, &state->logs, state->callback, state->userdata, state->filter_object); - bool const buffers_emptied = (r == 1); - if (r != 0 && r != 1) + int r = put_logs_into_vector(state->data_fds, state->fd_count, &state->logs, state->filter_object, out); + if (r < 0) return r; - int nfds = TEMP_FAILURE_RETRY(epoll_wait(state->epollfd, state->evs, state->epoll_cnt, 100)); - if (nfds < 0) - return -errno; - - for (int i = 0; i < nfds; ++i) { - struct fd_info *fdi = state->evs[i].data.ptr; - int r = fdi->ops->read(fdi); - if (r < 0) { - if (r == -EAGAIN) - continue; - else - break; + if (r == BUFFER_NEWLY_DRAINED + || r == ALL_BUFFERS_EMPTY) { + int const nfds = TEMP_FAILURE_RETRY(epoll_wait(state->epollfd, state->evs, state->epoll_cnt, 100)); + if (nfds < 0) + return -errno; + + for (int i = 0; i < nfds; ++i) { + struct fd_info *const fdi = state->evs[i].data.ptr; + int const rd = fdi->ops->read(fdi); + if (rd < 0) { + if (rd == -EAGAIN) + continue; + else + break; + } } } + if (*out) { + if (state->logs.dump == DLOGUTIL_MODE_CONTINUOUS + || state->logs.dump == DLOGUTIL_MAX_DUMP_SIZE) + return 0; + free(*out); + *out = NULL; + } + /* The oldest log can be so fresh as to be from the future * (i.e. has a negative age). This can happen when somebody * changes the realtime clock backwards. In that case let @@ -285,7 +293,7 @@ int do_print(dlogutil_state_s *state) * the clock reaches its old value again. */ const long last_log_age = sort_vector_time_span(&state->logs); const bool is_from_future = (last_log_age < 0); - if (state->logs.dump == DLOGUTIL_MODE_CONTINUOUS && (buffers_emptied || (state->logs.old_logs_dumped == 1 && (last_log_age > state->logs.timeout || is_from_future)))) { + if (state->logs.dump == DLOGUTIL_MODE_CONTINUOUS && (r == ALL_BUFFERS_EMPTY || (state->logs.old_logs_dumped == 1 && (last_log_age > state->logs.timeout || is_from_future)))) { if (is_from_future) state->flush_target = -1; else { @@ -308,22 +316,47 @@ int do_print(dlogutil_state_s *state) } } - int r; - do - r = put_logs_into_vector(state->data_fds, state->fd_count, &state->logs, state->callback, state->userdata, state->filter_object); - while (r == 0); - if (r != 1) - return r; + while (true) { + int r = put_logs_into_vector(state->data_fds, state->fd_count, &state->logs, state->filter_object, out); + if (r == 1) + break; + if (r < 0) + return r; + if (!*out) + break; + + if (state->logs.dump == DLOGUTIL_MODE_CONTINUOUS + || state->logs.dump == DLOGUTIL_MAX_DUMP_SIZE) + return 0; + free(*out); + *out = NULL; + } if (state->logs.dump != DLOGUTIL_MODE_CONTINUOUS && state->logs.dump != DLOGUTIL_MAX_DUMP_SIZE) while (sort_vector_used_size(&state->logs) > state->logs.dump) sort_vector_pop(&state->logs); - while (!sort_vector_empty(&state->logs)) { - r = state->callback(sort_vector_pop_ret(&state->logs), state->userdata); - if (r != 0) - return r; + if (!sort_vector_empty(&state->logs)) { + *out = sort_vector_pop_ret(&state->logs); + return 0; } return 0; } + +int do_print(dlogutil_state_s *state) +{ + while (true) { + dlogutil_entry_s *out; + int r = do_print_once(state, &out); + if (r != 0) + return r; + + if (!out) + return 0; + r = state->callback(out, state->userdata); + free(out); + if (r != 0) + return r; + } +} diff --git a/src/tests/logutil.c b/src/tests/logutil.c index 21fdf65..66d20db 100644 --- a/src/tests/logutil.c +++ b/src/tests/logutil.c @@ -6,22 +6,9 @@ #include #include -bool process_log(const dlogutil_entry_s *e, struct timespec reference_ts, dlogutil_sorting_order_e stamp_type, dlogutil_entry_cb callback, void *userdata, long timeout, int *callback_ret); +bool process_log(const dlogutil_entry_s *e, struct timespec reference_ts, dlogutil_sorting_order_e stamp_type, long timeout, int *callback_ret); struct fd_info *find_earliest_log(struct fd_info **data_fds, int fd_count, dlogutil_sorting_order_e sort_by); -int put_logs_into_vector(struct fd_info **data_fds, int fd_count, struct sort_vector *logs, dlogutil_entry_cb callback, void *userdata, dlogutil_filter_options_s *filter); - -int written_logs = 0; -bool free_entries = false; -int callback_ret = 0; -int callback(const dlogutil_entry_s *entry, void *userdata) -{ - assert(userdata == (void *)0xDDD); - - if (free_entries) - free((void *)entry); // We shouldn't do this due to const, but there's no easy way around - ++written_logs; - return callback_ret; -} +int put_logs_into_vector(struct fd_info **data_fds, int fd_count, struct sort_vector *logs, dlogutil_filter_options_s *filter, dlogutil_entry_s **entry_out); int __wrap_clock_gettime(clockid_t clk_id, struct timespec *tp) { @@ -67,6 +54,7 @@ int __wrap_fdi_push_log(struct fd_info *fdi, struct sort_vector *logs, dlogutil_ struct fdi_internal *ii = fdi->priv_data; ii->has_log = false; + *entry_out = NULL; if (sort_vector_full(logs)) { if (logs->dump == DLOGUTIL_MODE_CONTINUOUS || logs->dump == DLOGUTIL_MAX_DUMP_SIZE) *entry_out = sort_vector_pop_ret(logs); @@ -155,13 +143,17 @@ int main() while (!sort_vector_empty(&sv)) sort_vector_pop(&sv); - assert(put_logs_into_vector(fds, 0, &sv, callback, (void *)0xDDD, (dlogutil_filter_options_s *)0xEEE) == 1); + dlogutil_entry_s *vector_overflown; + assert(put_logs_into_vector(fds, 0, &sv, (dlogutil_filter_options_s *)0xEEE, &vector_overflown) == 1); + assert(!vector_overflown); fdi_push_log_ret = -EIO; - assert(put_logs_into_vector(fds, 10, &sv, callback, (void *)0xDDD, (dlogutil_filter_options_s *)0xEEE) == -EIO); + assert(put_logs_into_vector(fds, 10, &sv, (dlogutil_filter_options_s *)0xEEE, &vector_overflown) == -EIO); + assert(!vector_overflown); fdi_push_log_ret = 0; - assert(put_logs_into_vector(fds, 10, &sv, callback, (void *)0xDDD, (dlogutil_filter_options_s *)0xEEE) == 0); + assert(put_logs_into_vector(fds, 10, &sv, (dlogutil_filter_options_s *)0xEEE, &vector_overflown) == 2); + assert(!vector_overflown); assert(sort_vector_used_size(&sv) == 1); sort_vector_free(&sv); -- 2.7.4