From cc415c9140381953cfcb2420357198780e225070 Mon Sep 17 00:00:00 2001 From: Christian Hergert Date: Sat, 25 May 2019 19:03:48 -0700 Subject: [PATCH] libsysprof-capture: add log frame type This is useful to interleave logs with the capture so that we can have correlation without interjecting them into mark fields. --- .../sysprof-capture-cursor.c | 4 ++ .../sysprof-capture-reader.c | 53 ++++++++++++++++++ .../sysprof-capture-reader.h | 2 + .../sysprof-capture-types.h | 14 +++++ .../sysprof-capture-writer-cat.c | 17 ++++++ .../sysprof-capture-writer.c | 45 +++++++++++++++ .../sysprof-capture-writer.h | 8 +++ src/tests/test-capture.c | 55 +++++++++++++++++++ src/tools/sysprof-dump.c | 15 +++++ 9 files changed, 213 insertions(+) diff --git a/src/libsysprof-capture/sysprof-capture-cursor.c b/src/libsysprof-capture/sysprof-capture-cursor.c index 9cb1e31b..d3ae153b 100644 --- a/src/libsysprof-capture/sysprof-capture-cursor.c +++ b/src/libsysprof-capture/sysprof-capture-cursor.c @@ -127,6 +127,10 @@ sysprof_capture_cursor_foreach (SysprofCaptureCursor *self, delegate = READ_DELEGATE (sysprof_capture_reader_read_sample); break; + case SYSPROF_CAPTURE_FRAME_LOG: + delegate = READ_DELEGATE (sysprof_capture_reader_read_log); + break; + case SYSPROF_CAPTURE_FRAME_MAP: delegate = READ_DELEGATE (sysprof_capture_reader_read_map); break; diff --git a/src/libsysprof-capture/sysprof-capture-reader.c b/src/libsysprof-capture/sysprof-capture-reader.c index c3ef7c3e..19f471df 100644 --- a/src/libsysprof-capture/sysprof-capture-reader.c +++ b/src/libsysprof-capture/sysprof-capture-reader.c @@ -232,6 +232,17 @@ sysprof_capture_reader_bswap_frame (SysprofCaptureReader *self, } } +static inline void +sysprof_capture_reader_bswap_log (SysprofCaptureReader *self, + SysprofCaptureLog *log) +{ + g_assert (self != NULL); + g_assert (log != NULL); + + if (G_UNLIKELY (self->endian != G_BYTE_ORDER)) + log->severity = GUINT16_SWAP_LE_BE (log->severity); +} + static inline void sysprof_capture_reader_bswap_map (SysprofCaptureReader *self, SysprofCaptureMap *map) @@ -487,6 +498,48 @@ sysprof_capture_reader_read_map (SysprofCaptureReader *self) return map; } +const SysprofCaptureLog * +sysprof_capture_reader_read_log (SysprofCaptureReader *self) +{ + SysprofCaptureLog *log; + + g_assert (self != NULL); + g_assert ((self->pos % SYSPROF_CAPTURE_ALIGN) == 0); + g_assert (self->pos <= self->bufsz); + + if (!sysprof_capture_reader_ensure_space_for (self, sizeof *log)) + return NULL; + + log = (SysprofCaptureLog *)(gpointer)&self->buf[self->pos]; + + sysprof_capture_reader_bswap_frame (self, &log->frame); + + if (log->frame.type != SYSPROF_CAPTURE_FRAME_LOG) + return NULL; + + if (log->frame.len < (sizeof *log + 1)) + return NULL; + + if (!sysprof_capture_reader_ensure_space_for (self, log->frame.len)) + return NULL; + + log = (SysprofCaptureLog *)(gpointer)&self->buf[self->pos]; + + sysprof_capture_reader_bswap_log (self, log); + + self->pos += log->frame.len; + + if ((self->pos % SYSPROF_CAPTURE_ALIGN) != 0) + return NULL; + + /* Ensure trailing \0 in domain and message */ + log->domain[sizeof log->domain - 1] = 0; + if (log->frame.len > sizeof *log) + ((gchar *)log)[log->frame.len - 1] = 0; + + return log; +} + const SysprofCaptureMark * sysprof_capture_reader_read_mark (SysprofCaptureReader *self) { diff --git a/src/libsysprof-capture/sysprof-capture-reader.h b/src/libsysprof-capture/sysprof-capture-reader.h index 944daf1e..cbddc565 100644 --- a/src/libsysprof-capture/sysprof-capture-reader.h +++ b/src/libsysprof-capture/sysprof-capture-reader.h @@ -56,6 +56,8 @@ SYSPROF_AVAILABLE_IN_ALL gboolean sysprof_capture_reader_peek_frame (SysprofCaptureReader *self, SysprofCaptureFrame *frame); SYSPROF_AVAILABLE_IN_ALL +const SysprofCaptureLog *sysprof_capture_reader_read_log (SysprofCaptureReader *self); +SYSPROF_AVAILABLE_IN_ALL const SysprofCaptureMap *sysprof_capture_reader_read_map (SysprofCaptureReader *self); SYSPROF_AVAILABLE_IN_ALL const SysprofCaptureMark *sysprof_capture_reader_read_mark (SysprofCaptureReader *self); diff --git a/src/libsysprof-capture/sysprof-capture-types.h b/src/libsysprof-capture/sysprof-capture-types.h index 1aa179a1..42817860 100644 --- a/src/libsysprof-capture/sysprof-capture-types.h +++ b/src/libsysprof-capture/sysprof-capture-types.h @@ -90,6 +90,7 @@ typedef enum SYSPROF_CAPTURE_FRAME_CTRSET = 9, SYSPROF_CAPTURE_FRAME_MARK = 10, SYSPROF_CAPTURE_FRAME_METADATA = 11, + SYSPROF_CAPTURE_FRAME_LOG = 12, } SysprofCaptureFrameType; SYSPROF_ALIGNED_BEGIN(1) @@ -249,6 +250,18 @@ typedef struct } SysprofCaptureMetadata SYSPROF_ALIGNED_END(1); +SYSPROF_ALIGNED_BEGIN(1) +typedef struct +{ + SysprofCaptureFrame frame; + guint32 severity : 16; + guint32 padding1 : 16; + guint32 padding2 : 32; + gchar domain[32]; + gchar message[0]; +} SysprofCaptureLog +SYSPROF_ALIGNED_END(1); + G_STATIC_ASSERT (sizeof (SysprofCaptureFileHeader) == 256); G_STATIC_ASSERT (sizeof (SysprofCaptureFrame) == 24); G_STATIC_ASSERT (sizeof (SysprofCaptureMap) == 56); @@ -264,6 +277,7 @@ G_STATIC_ASSERT (sizeof (SysprofCaptureCounterDefine) == 32); G_STATIC_ASSERT (sizeof (SysprofCaptureCounterSet) == 32); G_STATIC_ASSERT (sizeof (SysprofCaptureMark) == 96); G_STATIC_ASSERT (sizeof (SysprofCaptureMetadata) == 64); +G_STATIC_ASSERT (sizeof (SysprofCaptureLog) == 64); static inline gint sysprof_capture_address_compare (SysprofCaptureAddress a, diff --git a/src/libsysprof-capture/sysprof-capture-writer-cat.c b/src/libsysprof-capture/sysprof-capture-writer-cat.c index 7e7f4e6e..36e066f8 100644 --- a/src/libsysprof-capture/sysprof-capture-writer-cat.c +++ b/src/libsysprof-capture/sysprof-capture-writer-cat.c @@ -151,6 +151,23 @@ sysprof_capture_writer_cat (SysprofCaptureWriter *self, break; } + case SYSPROF_CAPTURE_FRAME_LOG: + { + const SysprofCaptureLog *frame; + + if (!(frame = sysprof_capture_reader_read_log (reader))) + goto panic; + + sysprof_capture_writer_add_log (self, + frame->frame.time, + frame->frame.cpu, + frame->frame.pid, + frame->severity, + frame->domain, + frame->message); + break; + } + case SYSPROF_CAPTURE_FRAME_MAP: { const SysprofCaptureMap *frame; diff --git a/src/libsysprof-capture/sysprof-capture-writer.c b/src/libsysprof-capture/sysprof-capture-writer.c index 8eefda25..17925915 100644 --- a/src/libsysprof-capture/sysprof-capture-writer.c +++ b/src/libsysprof-capture/sysprof-capture-writer.c @@ -1304,3 +1304,48 @@ sysprof_capture_writer_get_buffer_size (SysprofCaptureWriter *self) return self->len; } + +gboolean +sysprof_capture_writer_add_log (SysprofCaptureWriter *self, + gint64 time, + gint cpu, + gint32 pid, + GLogLevelFlags severity, + const gchar *domain, + const gchar *message) +{ + SysprofCaptureLog *ev; + gsize message_len; + gsize len; + + g_assert (self != NULL); + + if (domain == NULL) + domain = ""; + + if (message == NULL) + message = ""; + message_len = strlen (message) + 1; + + len = sizeof *ev + message_len; + ev = (SysprofCaptureLog *)sysprof_capture_writer_allocate (self, &len); + if (!ev) + return FALSE; + + sysprof_capture_writer_frame_init (&ev->frame, + len, + cpu, + pid, + time, + SYSPROF_CAPTURE_FRAME_LOG); + + ev->severity = severity & 0xFFFF; + ev->padding1 = 0; + ev->padding2 = 0; + g_strlcpy (ev->domain, domain, sizeof ev->domain); + memcpy (ev->message, message, message_len); + + self->stat.frame_count[SYSPROF_CAPTURE_FRAME_LOG]++; + + return TRUE; +} diff --git a/src/libsysprof-capture/sysprof-capture-writer.h b/src/libsysprof-capture/sysprof-capture-writer.h index 9e4f025d..4aa94493 100644 --- a/src/libsysprof-capture/sysprof-capture-writer.h +++ b/src/libsysprof-capture/sysprof-capture-writer.h @@ -120,6 +120,14 @@ gboolean sysprof_capture_writer_set_counters (SysprofCaptureWrit const SysprofCaptureCounterValue *values, guint n_counters); SYSPROF_AVAILABLE_IN_ALL +gboolean sysprof_capture_writer_add_log (SysprofCaptureWriter *self, + gint64 time, + gint cpu, + gint32 pid, + GLogLevelFlags severity, + const gchar *domain, + const gchar *message); +SYSPROF_AVAILABLE_IN_ALL gboolean sysprof_capture_writer_flush (SysprofCaptureWriter *self); SYSPROF_AVAILABLE_IN_ALL gboolean sysprof_capture_writer_save_as (SysprofCaptureWriter *self, diff --git a/src/tests/test-capture.c b/src/tests/test-capture.c index 52421799..ef65d21e 100644 --- a/src/tests/test-capture.c +++ b/src/tests/test-capture.c @@ -561,6 +561,60 @@ test_reader_splice (void) g_unlink ("writer3.syscap"); } +static void +test_reader_writer_log (void) +{ + SysprofCaptureWriter *writer; + SysprofCaptureReader *reader; + const SysprofCaptureLog *log; + SysprofCaptureFrameType type; + GError *error = NULL; + gint r; + + writer = sysprof_capture_writer_new ("log1.syscap", 0); + + sysprof_capture_writer_add_log (writer, SYSPROF_CAPTURE_CURRENT_TIME, -1, -1, G_LOG_LEVEL_DEBUG, "my-domain-1", "log message 1"); + sysprof_capture_writer_add_log (writer, SYSPROF_CAPTURE_CURRENT_TIME, -1, -1, G_LOG_LEVEL_DEBUG, "my-domain-2", "log message 2"); + sysprof_capture_writer_add_log (writer, SYSPROF_CAPTURE_CURRENT_TIME, -1, -1, G_LOG_LEVEL_DEBUG, "my-domain-3", "log message 3"); + + g_clear_pointer (&writer, sysprof_capture_writer_unref); + + reader = sysprof_capture_reader_new ("log1.syscap", &error); + g_assert_no_error (error); + g_assert (reader != NULL); + + log = sysprof_capture_reader_read_log (reader); + g_assert_nonnull (log); + g_assert_cmpstr (log->domain, ==, "my-domain-1"); + g_assert_cmpint (log->severity, ==, G_LOG_LEVEL_DEBUG); + g_assert_cmpstr (log->message, ==, "log message 1"); + g_assert_cmpint (log->frame.time, >, 0); + g_assert_cmpint (log->frame.cpu, ==, -1); + + log = sysprof_capture_reader_read_log (reader); + g_assert_nonnull (log); + g_assert_cmpstr (log->domain, ==, "my-domain-2"); + g_assert_cmpint (log->severity, ==, G_LOG_LEVEL_DEBUG); + g_assert_cmpstr (log->message, ==, "log message 2"); + g_assert_cmpint (log->frame.time, >, 0); + g_assert_cmpint (log->frame.cpu, ==, -1); + + log = sysprof_capture_reader_read_log (reader); + g_assert_nonnull (log); + g_assert_cmpstr (log->domain, ==, "my-domain-3"); + g_assert_cmpint (log->severity, ==, G_LOG_LEVEL_DEBUG); + g_assert_cmpstr (log->message, ==, "log message 3"); + g_assert_cmpint (log->frame.time, >, 0); + g_assert_cmpint (log->frame.cpu, ==, -1); + + r = sysprof_capture_reader_peek_type (reader, &type); + g_assert_cmpint (r, ==, FALSE); + + g_clear_pointer (&reader, sysprof_capture_reader_unref); + + g_unlink ("log1.syscap"); +} + static void test_reader_writer_mark (void) { @@ -663,6 +717,7 @@ main (int argc, g_test_add_func ("/SysprofCapture/ReaderWriter", test_reader_basic); g_test_add_func ("/SysprofCapture/Writer/splice", test_writer_splice); g_test_add_func ("/SysprofCapture/Reader/splice", test_reader_splice); + g_test_add_func ("/SysprofCapture/ReaderWriter/log", test_reader_writer_log); g_test_add_func ("/SysprofCapture/ReaderWriter/mark", test_reader_writer_mark); g_test_add_func ("/SysprofCapture/ReaderWriter/metadata", test_reader_writer_metadata); return g_test_run (); diff --git a/src/tools/sysprof-dump.c b/src/tools/sysprof-dump.c index 1ad98177..77ec7c37 100644 --- a/src/tools/sysprof-dump.c +++ b/src/tools/sysprof-dump.c @@ -108,6 +108,21 @@ main (gint argc, break; } + case SYSPROF_CAPTURE_FRAME_LOG: + { + const SysprofCaptureLog *log = sysprof_capture_reader_read_log (reader); + gdouble ptime = (log->frame.time - begin_time) / (gdouble)NSEC_PER_SEC; + + g_print ("LOG: pid=%d time=%"G_GINT64_FORMAT" (%lf)\n" + " severity = %d\n" + " domain = %s\n" + " message = %s\n", + log->frame.pid, log->frame.time, ptime, + log->severity, log->domain, log->message); + + break; + } + case SYSPROF_CAPTURE_FRAME_MAP: { const SysprofCaptureMap *map = sysprof_capture_reader_read_map (reader);