Improve LOGS and time

hw/buffer.h

@@ -17,6 +17,7 @@ typedef struct buffer_s {
   int mmap_reflinks;
   struct buffer_s *mmap_source;
   bool enqueued;
+  uint64_t enqueued_time_us;
 } buffer_t;
 
 buffer_t *buffer_open(const char *name, struct buffer_list_s *buf_list, int buffer);

hw/buffer_lock.c

@@ -46,7 +46,7 @@ void buffer_lock_capture(buffer_lock_t *buf_lock, buffer_t *buf)
   buf_lock->buf = buf;
   buf_lock->counter++;
   gettimeofday(&buf_lock->buf_time, NULL);
-  E_LOG_DEBUG(buf_lock, "Captured HTTP snapshot: %d", buf_lock->counter);
+  E_LOG_DEBUG(buf_lock, "Captured buffer: %d", buf_lock->counter);
   pthread_cond_broadcast(&buf_lock->cond_wait);
   pthread_mutex_unlock(&buf_lock->lock);
 }

hw/buffer_queue.c

@@ -44,18 +44,8 @@ bool buffer_consumed(buffer_t *buf)
       buf->v4l2_buffer.bytesused = buf->used;
     }
 
-#if 0
-    uint64_t now = get_now_monotonic_u64();
-    struct timeval ts = {
-      .tv_sec = now / 1000000,
-      .tv_usec = now % 1000000,
-    };
-
-    buf->v4l2_buffer.timestamp.tv_sec = ts.tv_sec;
-    buf->v4l2_buffer.timestamp.tv_usec = ts.tv_usec;
-#endif
-
     E_LOG_DEBUG(buf, "Queuing buffer... used=%zu length=%zu (linked=%s)", buf->used, buf->length, buf->mmap_source ? buf->mmap_source->name : NULL);
+    buf->enqueued_time_us = get_monotonic_time_us(NULL, &buf->v4l2_buffer.timestamp);
     E_XIOCTL(buf, buf->buf_list->device->fd, VIDIOC_QBUF, &buf->v4l2_buffer, "Can't queue buffer.");
     buf->enqueued = true;
   }
@@ -123,14 +113,12 @@ int buffer_list_enqueue(buffer_list_t *buf_list, buffer_t *dma_buf)
         dma_buf->name, dma_buf->used, buf->length);
     }
 
-    struct timespec before, after;
+    uint64_t before = get_monotonic_time_us(NULL, NULL);
-    clock_gettime(CLOCK_MONOTONIC, &before);
     memcpy(buf->start, dma_buf->start, dma_buf->used);
-    clock_gettime(CLOCK_MONOTONIC, &after);
+    uint64_t after = get_monotonic_time_us(NULL, NULL);
-    uint64_t time_diff = after.tv_sec * 1000000LL + after.tv_nsec / 1000 - before.tv_sec * 1000000LL - before.tv_nsec / 1000;
 
     E_LOG_DEBUG(buf, "mmap copy: dest=%p, src=%p (%s), size=%zu, space=%zu, time=%dllus",
-      buf->start, dma_buf->start, dma_buf->name, dma_buf->used, buf->length, time_diff);
+      buf->start, dma_buf->start, dma_buf->name, dma_buf->used, buf->length, after-before);
   } else {
     if (buf_list->do_mplanes) {
       buf->v4l2_plane.m.fd = dma_buf->dma_fd;
@@ -178,9 +166,15 @@ buffer_t *buffer_list_dequeue(buffer_list_t *buf_list)
 
   buf->enqueued = false;
   buf->mmap_reflinks = 1;
+  uint64_t enqueued_time_us = get_monotonic_time_us(NULL, NULL) - buf->enqueued_time_us;
 
-	E_LOG_DEBUG(buf_list, "Grabbed mmap buffer=%u, bytes=%d, used=%d, frame=%d, linked=%s",
+	E_LOG_DEBUG(buf_list, "Grabbed mmap buffer=%u, bytes=%d, used=%d, frame=%d, linked=%s, enqueued_time_us=%lluus",
-    buf->index, buf->length, buf->used, buf_list->frames, buf->mmap_source ? buf->mmap_source->name : NULL);
+    buf->index,
+    buf->length,
+    buf->used,
+    buf_list->frames,
+    buf->mmap_source ? buf->mmap_source->name : NULL,
+    enqueued_time_us);
 
   if (buf->mmap_source) {
     buf->mmap_source->used = 0;

hw/links.c

@@ -79,8 +79,6 @@ int links_step(link_t *all_links, int timeout)
     return errno;
   }
 
-  printf("links_step n=%d, ret=%d\n", n, ret);
-
   for (int i = 0; i < n; i++) {
     buffer_list_t *buf_list = buf_lists[i];
     link_t *link = links[i];
@@ -220,7 +218,6 @@ int links_loop(link_t *all_links, bool *running)
       links_stream(all_links, false);
       return -1;
     }
-    //usleep(100*1000);
   }
 
   links_stream(all_links, false);

hw/v4l2.c

@@ -74,3 +74,17 @@ unsigned fourcc_to_stride(unsigned width, unsigned format)
 			E_LOG_PERROR(NULL, "Unknown format: %s", fourcc_to_string(format).buf);
 	}
 }
+
+uint64_t get_monotonic_time_us(struct timespec *ts, struct timeval *tv)
+{
+	struct timespec now;
+	clock_gettime(CLOCK_MONOTONIC, &now);
+	if (ts) {
+		*ts = now;
+	}
+	if (tv) {
+		tv->tv_sec = now.tv_sec;
+		tv->tv_usec = now.tv_nsec / 1000;
+	}
+	return now.tv_sec * 1000000LL + now.tv_nsec / 1000;
+}

hw/v4l2.h

@@ -23,13 +23,15 @@
 #endif
 #define XIOCTL_RETRIES ((unsigned)(CFG_XIOCTL_RETRIES))
 
+#define __FILENAME__ (strrchr(__FILE__, '/') ? strrchr(__FILE__, '/') + 1 : __FILE__)
+
 // assumes that name is first item
 #define dev_name(dev) (dev ? *(const char**)dev : "?")
-#define E_LOG_ERROR(dev, _msg, ...)		do { fprintf(stderr, "%s: " _msg "\n", dev_name(dev), ##__VA_ARGS__); goto error; } while(0)
+#define E_LOG_ERROR(dev, _msg, ...)		do { fprintf(stderr, "%s: %s: " _msg "\n", __FILENAME__, dev_name(dev), ##__VA_ARGS__); goto error; } while(0)
-#define E_LOG_PERROR(dev, _msg, ...)		do { fprintf(stderr, "%s: " _msg "\n", dev_name(dev), ##__VA_ARGS__); exit(-1); } while(0)
+#define E_LOG_PERROR(dev, _msg, ...)		do { fprintf(stderr, "%s: %s: " _msg "\n", __FILENAME__, dev_name(dev), ##__VA_ARGS__); exit(-1); } while(0)
-#define E_LOG_INFO(dev, _msg, ...)		fprintf(stderr, "%s: " _msg "\n", dev_name(dev), ##__VA_ARGS__)
+#define E_LOG_INFO(dev, _msg, ...)		fprintf(stderr, "%s: %s: " _msg "\n", __FILENAME__, dev_name(dev), ##__VA_ARGS__)
-#define E_LOG_VERBOSE(dev, _msg, ...)	fprintf(stderr, "%s: " _msg "\n", dev_name(dev), ##__VA_ARGS__)
+#define E_LOG_VERBOSE(dev, _msg, ...)	fprintf(stderr, "%s: %s: " _msg "\n", __FILENAME__, dev_name(dev), ##__VA_ARGS__)
-#define E_LOG_DEBUG(dev, _msg, ...)		fprintf(stderr, "%s: " _msg "\n", dev_name(dev), ##__VA_ARGS__)
+#define E_LOG_DEBUG(dev, _msg, ...)		fprintf(stderr, "%s: %s: " _msg "\n", __FILENAME__, dev_name(dev), ##__VA_ARGS__)
 
 typedef struct {
 	char buf[10];
@@ -38,6 +40,7 @@ typedef struct {
 fourcc_string fourcc_to_string(unsigned format);
 unsigned fourcc_to_stride(unsigned width, unsigned format);
 int xioctl(const char *name, int fd, int request, void *arg);
+uint64_t get_monotonic_time_us(struct timespec *ts, struct timeval *tv);
 
 #define E_XIOCTL(dev, _fd, _request, _value, _msg, ...) do { \
 		int ret; \