From c05f290f956c3045467ad75ff0a38be9bc37da87 Mon Sep 17 00:00:00 2001 From: Roman Gilg Date: Sat, 29 Feb 2020 02:04:26 +0100 Subject: [PATCH] feat: log continuous debug messages into per-device buffers Instead of exposing to consumers write streaming log data into a per-device buffer that gets created on request and destroyed after the buffer has been written to the log. Passing a NULL string to the internal continuous log function triggers a write of the buffer to the log. BREAKING CHANGE: continuous log function is moved from log header to private header. --- alloc.c | 52 +++++++++++++------------- device.c | 11 +++--- include/libliftoff.h | 2 +- include/log.h | 5 ++- include/private.h | 4 ++ log.c | 87 +++++++++++++++++++++++++++++++++++--------- plane.c | 27 ++++++++------ 7 files changed, 126 insertions(+), 62 deletions(-) diff --git a/alloc.c b/alloc.c index 78573a2..052837b 100644 --- a/alloc.c +++ b/alloc.c @@ -581,23 +581,21 @@ static void log_no_reuse(struct liftoff_output *output) } } -static void log_plane_type_change(uint32_t base, uint32_t cmp) +static void log_plane_type_change(struct liftoff_device *device, + uint32_t base, uint32_t cmp) { switch (base) { case DRM_PLANE_TYPE_PRIMARY: - liftoff_log_cnt(LIFTOFF_DEBUG, " " : "c>"); + debug_cnt(device, " " : "c>"); break; case DRM_PLANE_TYPE_CURSOR: - liftoff_log_cnt(LIFTOFF_DEBUG, " " : "o>"); + debug_cnt(device, " " : "o>"); break; case DRM_PLANE_TYPE_OVERLAY: - liftoff_log_cnt(LIFTOFF_DEBUG, " " : "c>"); + debug_cnt(device, " " : "c>"); break; } } @@ -615,12 +613,13 @@ static void log_planes(struct liftoff_device *device, return; } - liftoff_log_cnt(LIFTOFF_DEBUG, "\nAvailable planes"); + debug_cnt(device, "Available planes"); if (output) { - liftoff_log(LIFTOFF_DEBUG, " (on output %"PRIu32 "):", output->crtc_id); + debug_cnt(device, " (on output %"PRIu32 "):", output->crtc_id); } else { - liftoff_log(LIFTOFF_DEBUG, ":"); + debug_cnt(device, ":"); } + debug_cnt(device, NULL); liftoff_list_for_each(plane, &device->planes, link) { bool active = false; @@ -653,8 +652,8 @@ static void log_planes(struct liftoff_device *device, } } - liftoff_log_cnt(LIFTOFF_DEBUG, " Plane %"PRIu32 "%s", plane->id, - active ? ":" : " (inactive):"); + debug_cnt(device, " Plane %"PRIu32 "%s", plane->id, + active ? ":" : " (inactive):"); max_per_line = active ? 1 : 4; per_line = max_per_line - 1; @@ -663,21 +662,22 @@ static void log_planes(struct liftoff_device *device, char *name; if (++per_line == max_per_line) { - liftoff_log_cnt(LIFTOFF_DEBUG, "\n "); + debug_cnt(device, NULL); + debug_cnt(device, " "); per_line = 0; } drm_prop = drmModeGetProperty(device->drm_fd, drm_props->props[i]); if (drm_prop == NULL) { - liftoff_log_cnt(LIFTOFF_DEBUG, "ERR!"); + debug_cnt(device, "ERR!"); continue; } name = drm_prop->name; if (strcmp(name, "type") == 0) { - liftoff_log_cnt(LIFTOFF_DEBUG, " %s: %s", name, + debug_cnt(device, " %s: %s", name, value == DRM_PLANE_TYPE_PRIMARY ? "primary" : value == DRM_PLANE_TYPE_CURSOR ? "cursor" : "overlay"); continue; @@ -685,16 +685,16 @@ static void log_planes(struct liftoff_device *device, if (strcmp(name, "CRTC_X") == 0 || strcmp(name, "CRTC_Y") == 0 || strcmp(name, "IN_FENCE_FD") == 0) { - liftoff_log_cnt(LIFTOFF_DEBUG, " %s: %"PRIi32, name, (int32_t)value); + debug_cnt(device, " %s: %"PRIi32, name, (int32_t)value); continue; } if (strcmp(name, "SRC_W") == 0 || strcmp(name, "SRC_H") == 0) { value = value >> 16; } - liftoff_log_cnt(LIFTOFF_DEBUG, " %s: %"PRIu64, name, value); + debug_cnt(device, " %s: %"PRIu64, name, value); } - liftoff_log_cnt(LIFTOFF_DEBUG, "\n"); + debug_cnt(device, NULL); } } @@ -704,7 +704,7 @@ static bool reset_planes(struct liftoff_device *device, drmModeAtomicReq *req) uint32_t debug_type = DRM_PLANE_TYPE_PRIMARY; bool compatible; - liftoff_log_cnt(LIFTOFF_DEBUG, "\nReset planes:"); + debug_cnt(device, "\nReset planes:"); liftoff_list_for_each(plane, &device->planes, link) { if (plane->layer != NULL) { @@ -713,19 +713,21 @@ static bool reset_planes(struct liftoff_device *device, drmModeAtomicReq *req) if (log_has(LIFTOFF_DEBUG)) { if (plane->type != debug_type) { - log_plane_type_change(debug_type, plane->type); + log_plane_type_change(device, debug_type, plane->type); debug_type = plane->type; } - liftoff_log_cnt(LIFTOFF_DEBUG, " %"PRIu32, plane->id); + debug_cnt(device, " %"PRIu32, plane->id); } if (!plane_apply(plane, NULL, req, &compatible)) { + debug_cnt(device, "... Error resetting: %"PRIu32, plane->id); + debug_cnt(device, NULL); return false; } assert(compatible); } - liftoff_log(LIFTOFF_DEBUG, "\n"); + debug_cnt(device, NULL); return true; } diff --git a/device.c b/device.c index 298a8d1..f069297 100644 --- a/device.c +++ b/device.c @@ -13,14 +13,14 @@ struct liftoff_device *liftoff_device_create(int drm_fd) drmModePlaneRes *drm_plane_res; uint32_t i; - liftoff_log_cnt(LIFTOFF_DEBUG, "\nCreating device for fd %d. ", drm_fd); - device = calloc(1, sizeof(*device)); if (device == NULL) { liftoff_log_errno(LIFTOFF_ERROR, "calloc"); return NULL; } + liftoff_log(LIFTOFF_DEBUG, "\nCreating device for fd %d. ", drm_fd); + liftoff_list_init(&device->planes); liftoff_list_init(&device->outputs); @@ -63,9 +63,9 @@ struct liftoff_device *liftoff_device_create(int drm_fd) for (i = 0; i < drm_plane_res->count_planes; i++) { if (i < 9 && drm_plane_res->count_planes >= 9) { - liftoff_log_cnt(LIFTOFF_DEBUG, " "); + debug_cnt(device, " "); } - liftoff_log_cnt(LIFTOFF_DEBUG, "[%d] ", i + 1); + debug_cnt(device, "[%d] ", i + 1); if (plane_create(device, drm_plane_res->planes[i]) == NULL) { liftoff_device_destroy(device); return NULL; @@ -73,8 +73,6 @@ struct liftoff_device *liftoff_device_create(int drm_fd) } drmModeFreePlaneResources(drm_plane_res); - liftoff_log_cnt(LIFTOFF_DEBUG, "\n"); - return device; } @@ -91,6 +89,7 @@ void liftoff_device_destroy(struct liftoff_device *device) plane_destroy(plane); } free(device->crtcs); + free(device->log_buf); free(device); } diff --git a/include/libliftoff.h b/include/libliftoff.h index adb9e34..f3ec515 100644 --- a/include/libliftoff.h +++ b/include/libliftoff.h @@ -74,7 +74,7 @@ enum liftoff_log_importance { LIFTOFF_DEBUG, }; -typedef void (*liftoff_log_func)(enum liftoff_log_importance importance, bool newline, +typedef void (*liftoff_log_func)(enum liftoff_log_importance importance, const char *fmt, va_list args); void liftoff_log_init(enum liftoff_log_importance verbosity, diff --git a/include/log.h b/include/log.h index 219792b..21e93c3 100644 --- a/include/log.h +++ b/include/log.h @@ -13,8 +13,9 @@ bool log_has(enum liftoff_log_importance verbosity); void liftoff_log(enum liftoff_log_importance verbosity, const char *format, ...) _LIFTOFF_ATTRIB_PRINTF(2, 3); -void liftoff_log_cnt(enum liftoff_log_importance verbosity, - const char *format, ...) _LIFTOFF_ATTRIB_PRINTF(2, 3); void liftoff_log_errno(enum liftoff_log_importance verbosity, const char *msg); +void debug_cnt(struct liftoff_device *device, const char *format, ...) +_LIFTOFF_ATTRIB_PRINTF(2, 3); + #endif diff --git a/include/private.h b/include/private.h index 1a1dfdc..338e989 100644 --- a/include/private.h +++ b/include/private.h @@ -19,6 +19,10 @@ struct liftoff_device { size_t crtcs_len; int page_flip_counter; + + char *log_buf; + size_t log_buf_len; + size_t log_buf_index; }; struct liftoff_output { diff --git a/log.c b/log.c index 8a4fe3e..ce14044 100644 --- a/log.c +++ b/log.c @@ -1,17 +1,17 @@ #include #include +#include #include #include "log.h" +#include "private.h" static enum liftoff_log_importance log_importance = LIFTOFF_ERROR; -static void log_stderr(enum liftoff_log_importance verbosity, bool newline, const char *fmt, +static void log_stderr(enum liftoff_log_importance verbosity, const char *fmt, va_list args) { vfprintf(stderr, fmt, args); - if (newline) { - fprintf(stderr, "\n"); - } + fprintf(stderr, "\n"); } static liftoff_log_func log_callback = log_stderr; @@ -39,19 +39,7 @@ void liftoff_log(enum liftoff_log_importance verbosity, const char *fmt, ...) va_list args; va_start(args, fmt); - log_callback(verbosity, true, fmt, args); - va_end(args); -} - -void liftoff_log_cnt(enum liftoff_log_importance verbosity, const char *fmt, ...) -{ - if (!log_has(verbosity)) { - return; - } - - va_list args; - va_start(args, fmt); - log_callback(verbosity, false, fmt, args); + log_callback(verbosity, fmt, args); va_end(args); } @@ -59,3 +47,68 @@ void liftoff_log_errno(enum liftoff_log_importance verbosity, const char *msg) { liftoff_log(verbosity, "%s: %s", msg, strerror(errno)); } + + +void debug_cnt(struct liftoff_device *device, const char *fmt, ...) +{ + if (!log_has(LIFTOFF_DEBUG)) { + return; + } + + if (fmt == NULL) { + if (device->log_buf == 0) { + return; + } + liftoff_log(LIFTOFF_DEBUG, "%s", device->log_buf); + free(device->log_buf); + device->log_buf = NULL; + device->log_buf_index = 0; + device->log_buf_len = 0; + return; + } + + va_list args; + va_start(args, fmt); + + if (device->log_buf == NULL) { + device->log_buf = malloc(4096); + if (device->log_buf == NULL) { + liftoff_log_errno(LIFTOFF_ERROR, "malloc"); + goto cleanup_out; + } + device->log_buf_len = 4096 / sizeof(char); + } + + do { + size_t max_len = device->log_buf_len - device->log_buf_index; + int ret; + + ret = vsnprintf(device->log_buf + device->log_buf_index, + max_len, fmt, args); + if (ret < 0) { + goto cleanup_out; + } + + if (ret - (int)max_len > 0) { + device->log_buf_index = device->log_buf_len; + device->log_buf_len *= 2; + + if (realloc(device->log_buf, device->log_buf_len) == NULL) { + liftoff_log_errno(LIFTOFF_ERROR, "realloc"); + goto cleanup_out; + } + } else { + device->log_buf_index += ret; + goto final_out; + } + } while (1); + +cleanup_out: + free(device->log_buf); + device->log_buf = NULL; + device->log_buf_index = 0; + device->log_buf_len = 0; + +final_out: + va_end(args); +} diff --git a/plane.c b/plane.c index 1b76069..6511a1c 100644 --- a/plane.c +++ b/plane.c @@ -30,7 +30,8 @@ static int guess_plane_zpos_from_type(struct liftoff_device *device, return 0; } -static void log_plane(struct liftoff_plane *plane) +static void log_plane(struct liftoff_device *device, + struct liftoff_plane *plane) { size_t i; int per_line = 0; @@ -39,26 +40,29 @@ static void log_plane(struct liftoff_plane *plane) return; } - liftoff_log_cnt(LIFTOFF_DEBUG, " type: "); + debug_cnt(device, " type: "); if (plane->type == DRM_PLANE_TYPE_PRIMARY) { - liftoff_log(LIFTOFF_DEBUG, "Primary"); + debug_cnt(device, "Primary"); } else if (plane->type == DRM_PLANE_TYPE_CURSOR) { - liftoff_log(LIFTOFF_DEBUG, "Cursor"); + debug_cnt(device, "Cursor"); } else { - liftoff_log(LIFTOFF_DEBUG, "Overlay"); + debug_cnt(device, "Overlay"); } + debug_cnt(device, NULL); + liftoff_log(LIFTOFF_DEBUG, " zpos: %"PRIu32, plane->zpos); - liftoff_log_cnt(LIFTOFF_DEBUG, " props:"); + debug_cnt(device, " props:"); for (i = 0; i < plane->props_len; i++) { if (per_line == 5) { - liftoff_log_cnt(LIFTOFF_DEBUG, "\n "); + debug_cnt(device, NULL); + debug_cnt(device, " "); per_line = 0; } - liftoff_log_cnt(LIFTOFF_DEBUG, " %s", plane->props[i].name); + debug_cnt(device, " %s", plane->props[i].name); per_line++; } - liftoff_log_cnt(LIFTOFF_DEBUG, "\n"); + debug_cnt(device, NULL); } struct liftoff_plane *plane_create(struct liftoff_device *device, uint32_t id) @@ -72,7 +76,8 @@ struct liftoff_plane *plane_create(struct liftoff_device *device, uint32_t id) uint64_t value; bool has_type = false, has_zpos = false; - liftoff_log(LIFTOFF_DEBUG, "Plane %"PRIu32, id); + debug_cnt(device, "Plane %"PRIu32, id); + debug_cnt(device, NULL); plane = calloc(1, sizeof(*plane)); if (plane == NULL) { @@ -158,7 +163,7 @@ struct liftoff_plane *plane_create(struct liftoff_device *device, uint32_t id) } } - log_plane(plane); + log_plane(device, plane); return plane; }