links: allow to log processing statistics

cmd/camera-streamer/opts.c

@@ -124,6 +124,7 @@ option_t all_options[] = {
 
   DEFINE_OPTION_DEFAULT(log, debug, bool, "1", "Enable debug logging."),
   DEFINE_OPTION_DEFAULT(log, verbose, bool, "1", "Enable verbose logging."),
+  DEFINE_OPTION_DEFAULT(log, stats, uint, "1", "Print statistics every duration."),
   DEFINE_OPTION_PTR(log, filter, list, "Enable debug logging from the given files. Ex.: `-log-filter=buffer.cc`"),
 
   {}

device/buffer_list.h

@@ -22,6 +22,10 @@ typedef struct buffer_format_s {
   buffer_type_t type;
 } buffer_format_t;
 
+typedef struct buffer_stats_s {
+  int frames, dropped;
+} buffer_stats_t;
+
 typedef struct buffer_list_s {
   char *name;
   char *path;
@@ -40,8 +44,9 @@ typedef struct buffer_list_s {
   };
 
   uint64_t last_enqueued_us, last_dequeued_us;
+  int last_capture_time_us, last_in_queue_time_us;
   bool streaming;
-  int frames;
+  buffer_stats_t stats, stats_last;
 } buffer_list_t;
 
 buffer_list_t *buffer_list_open(const char *name, int index, struct device_s *dev, const char *path, buffer_format_t fmt, bool do_capture, bool do_mmap);

device/buffer_queue.c

@@ -172,6 +172,8 @@ buffer_t *buffer_list_dequeue(buffer_list_t *buf_list)
   }
 
   buf_list->last_dequeued_us = get_monotonic_time_us(NULL, NULL);
+  buf_list->last_capture_time_us = buf_list->last_dequeued_us - buf->captured_time_us;
+  buf_list->last_in_queue_time_us = buf_list->last_dequeued_us - buf->enqueue_time_us;
 
   if (buf->mmap_reflinks > 0) {
     LOG_PERROR(buf, "Buffer appears to be enqueued? (links=%d)", buf->mmap_reflinks);
@@ -184,7 +186,7 @@ buffer_t *buffer_list_dequeue(buffer_list_t *buf_list)
     buf->index,
     buf->length,
     buf->used,
-    buf_list->frames,
+    buf_list->stats.frames,
     buf->dma_source ? buf->dma_source->name : NULL);
 
   if (buf->dma_source) {
@@ -197,7 +199,7 @@ buffer_t *buffer_list_dequeue(buffer_list_t *buf_list)
     buffer_update_h264_key_frame(buf);
   }
 
-  buf_list->frames++;
+  buf_list->stats.frames++;
   return buf;
 
 error:

device/links.c

@@ -155,14 +155,21 @@ int links_enqueue_from_capture_list(buffer_list_t *buf_list, link_t *link)
     }
   }
 
+  bool dropped = false;
+
   for (int j = 0; link->output_lists[j]; j++) {
     if (link->output_lists[j]->dev->paused) {
       continue;
     }
-    if (!links_sink_can_enqueue(link->output_lists[j])) {
+    if (links_sink_can_enqueue(link->output_lists[j])) {
-      continue;
-    }
       buffer_list_enqueue(link->output_lists[j], buf);
+    } else {
+      dropped = true;
+    }
+  }
+
+  if (dropped) {
+    buf_list->stats.dropped++;
   }
 
   for (int j = 0; j < link->n_callbacks; j++) {
@@ -227,7 +234,8 @@ static int links_step(link_t *all_links, int timeout_now_ms, int *timeout_next_m
     buffer_list_t *buf_list = pool.buf_lists[i];
     link_t *link = pool.links[i];
 
-    LOG_DEBUG(buf_list, "pool event=%s%s%s%s%s%08x streaming=%d enqueued=%d/%d paused=%d",
+    LOG_DEBUG(buf_list, "pool event=%08x revent=%s%s%s%s%s%08x streaming=%d enqueued=%d/%d paused=%d",
+      pool.fds[i].events,
       !pool.fds[i].revents ? "NONE/" : "",
       pool.fds[i].revents & POLLIN ? "IN/" : "",
       pool.fds[i].revents & POLLOUT ? "OUT/" : "",
@@ -325,6 +333,50 @@ error:
   return -1;
 }
 
+static void links_refresh_stats(link_t *all_links, uint64_t *last_refresh_us)
+{
+  uint64_t now_us = get_monotonic_time_us(NULL, NULL);
+
+  if (now_us - *last_refresh_us < 1000*1000)
+    return;
+
+  *last_refresh_us = now_us;
+
+  if (log_options.stats) {
+    printf("Statistics:");
+
+    for (int i = 0; all_links[i].capture_list; i++) {
+      buffer_list_t *capture_list = all_links[i].capture_list;
+      buffer_stats_t *now = &capture_list->stats;
+      buffer_stats_t *prev = &capture_list->stats_last;
+
+      printf(" [%8s %2d FPS/%2d D/%3dms/%3dms/%c/O%d:C%d]",
+        capture_list->dev->name,
+        (now->frames - prev->frames) / log_options.stats,
+        (now->dropped - prev->dropped) / log_options.stats,
+        capture_list->last_capture_time_us > 0 ? capture_list->last_capture_time_us / 1000 : -1,
+        capture_list->last_in_queue_time_us > 0 ? capture_list->last_in_queue_time_us / 1000 : -1,
+        capture_list->streaming ? (capture_list->dev->paused ? 'P' : 'S') : 'X',
+        capture_list->dev->output_list ? buffer_list_count_enqueued(capture_list->dev->output_list) : 0,
+        buffer_list_count_enqueued(capture_list)
+      );
+    }
+
+    printf("\n");
+    fflush(stdout);
+  }
+
+  for (int i = 0; all_links[i].capture_list; i++) {
+    buffer_list_t *capture_list = all_links[i].capture_list;
+    capture_list->stats_last = capture_list->stats;
+
+    if (now_us - capture_list->last_dequeued_us > 1000) {
+      capture_list->last_capture_time_us = 0;
+      capture_list->last_in_queue_time_us = 0;
+    }
+  }
+}
+
 int links_loop(link_t *all_links, bool *running)
 {
   *running = true;
@@ -334,19 +386,19 @@ int links_loop(link_t *all_links, bool *running)
   }
 
   int timeout_ms = LINKS_LOOP_INTERVAL;
+  uint64_t last_refresh_us = get_monotonic_time_us(NULL, NULL);
+  int ret = 0;
 
-  while(*running) {
+  while(*running && ret == 0) {
     int timeout_now_ms = timeout_ms;
     timeout_ms = LINKS_LOOP_INTERVAL;
 
-    if (links_step(all_links, timeout_now_ms, &timeout_ms) < 0) {
+    ret = links_step(all_links, timeout_now_ms, &timeout_ms);
-      links_stream(all_links, false);
+    links_refresh_stats(all_links, &last_refresh_us);
-      return -1;
-    }
   }
 
   links_stream(all_links, false);
-  return 0;
+  return ret;
 }
 
 static void links_dump_buf_list(char *output, buffer_list_t *buf_list)

util/opts/log.h

@@ -26,6 +26,7 @@
 typedef struct log_options_s {
   bool debug;
   bool verbose;
+	unsigned stats;
   char filter[256];
 } log_options_t;