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.

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;

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)
 {

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);

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,

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;

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;
+}

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,

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 ();

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);