delay

src/capture.c

@@ -34,23 +34,30 @@ void capture_loop(struct device_t *dev, sig_atomic_t *volatile global_stop) {
 	LOG_INFO("Using JPEG quality: %d%%", dev->jpeg_quality);
 
 	while (_capture_init_loop(dev, &pool, global_stop) == 0) {
-		int frames_count = 0;
+		unsigned frames_count = 0;
+		long double grab_after = 0;
+		unsigned fluency_passed = 0;
+		unsigned fps = 0;
+		long long fps_second = 0;
 
 		while (!*global_stop) {
 			SEP_DEBUG('-');
 
-			fd_set read_fds;
+			LOG_DEBUG("Waiting for workers ...");
-			fd_set write_fds;
+			A_PTHREAD_M_LOCK(&pool.has_free_workers_mutex);
-			fd_set error_fds;
+			A_PTHREAD_C_WAIT_TRUE(pool.has_free_workers, &pool.has_free_workers_cond, &pool.has_free_workers_mutex);
+			A_PTHREAD_M_UNLOCK(&pool.has_free_workers_mutex);
 
-			FD_ZERO(&read_fds);
+			if (*global_stop) {
-			FD_SET(dev->run->fd, &read_fds);
+				break;
+			}
 
-			FD_ZERO(&write_fds);
+#	define INIT_FD_SET(_set) \
-			FD_SET(dev->run->fd, &write_fds);
+		fd_set _set; FD_ZERO(&_set); FD_SET(dev->run->fd, &_set);
-
+			INIT_FD_SET(read_fds);
-			FD_ZERO(&error_fds);
+			INIT_FD_SET(write_fds);
-			FD_SET(dev->run->fd, &error_fds);
+			INIT_FD_SET(error_fds);
+#	undef INIT_FD_SET
 
 			struct timeval timeout;
 			timeout.tv_sec = dev->timeout;
@@ -72,11 +79,7 @@ void capture_loop(struct device_t *dev, sig_atomic_t *volatile global_stop) {
 
 			} else {
 				if (FD_ISSET(dev->run->fd, &read_fds)) {
-					LOG_DEBUG("Frame is ready, waiting for workers ...");
+					LOG_DEBUG("Frame is ready");
-
-					A_PTHREAD_M_LOCK(&pool.has_free_workers_mutex);
-					A_PTHREAD_C_WAIT_TRUE(pool.has_free_workers, &pool.has_free_workers_cond, &pool.has_free_workers_mutex);
-					A_PTHREAD_M_UNLOCK(&pool.has_free_workers_mutex);
 
 					struct v4l2_buffer buf_info;
 
@@ -85,13 +88,12 @@ void capture_loop(struct device_t *dev, sig_atomic_t *volatile global_stop) {
 					}
 
 					if (dev->every_frame) {
-						if (frames_count < (int)dev->every_frame - 1) {
+						if (frames_count < dev->every_frame - 1) {
 							LOG_DEBUG("Dropping frame %d for option --every-frame=%d", frames_count + 1, dev->every_frame);
 							++frames_count;
 							goto pass_frame;
-						} else {
-							frames_count = 0;
 						}
+						frames_count = 0;
 					}
 
 					// Workaround for broken, corrupted frames:
@@ -104,6 +106,38 @@ void capture_loop(struct device_t *dev, sig_atomic_t *volatile global_stop) {
 						goto pass_frame;
 					}
 
+					{
+						long double now = now_ms_ld();
+
+						if (now < grab_after) {
+							fluency_passed += 1;
+							LOG_PERF("Passed %u frames for fluency: now=%.03Lf; grab_after=%.03Lf", fluency_passed, now, grab_after);
+							goto pass_frame;
+						}
+
+						fluency_passed = 0;
+						if (log_level >= LOG_LEVEL_VERBOSE) {
+							if ((long long)now != fps_second) {
+								LOG_VERBOSE("Current FPS = %u", fps);
+								fps = 0;
+								fps_second = (long long)now;
+							}
+							++fps;
+						}
+
+						long double delay = 0;
+						for (unsigned index = 0; index < dev->run->n_buffers; ++index) {
+							A_PTHREAD_M_LOCK(&pool.workers[index].last_comp_time_mutex);
+							if (pool.workers[index].last_comp_time > 0) {
+								delay += pool.workers[index].last_comp_time;
+							}
+							A_PTHREAD_M_UNLOCK(&pool.workers[index].last_comp_time_mutex);
+						}
+						delay = delay / dev->run->n_buffers / dev->run->n_buffers;
+						grab_after = now + delay;
+						LOG_PERF("Fluency delay=%.03Lf; grab_after=%.03Lf", delay, grab_after);
+					}
+
 					LOG_DEBUG("Grabbed a new frame to buffer %d", buf_info.index);
 					pool.workers[buf_info.index].ctx.buf_info = buf_info;
 
@@ -257,7 +291,7 @@ static void *_capture_worker_thread(void *v_ctx_ptr) {
 			*ctx->last_comp_time = last_comp_time;
 			A_PTHREAD_M_UNLOCK(ctx->last_comp_time_mutex);
 
-			LOG_PERF("Compressed JPEG size=%ld; time=%LG (worker %d)", compressed, last_comp_time, ctx->index); // FIXME
+			LOG_PERF("Compressed JPEG size=%ld; time=%0.3Lf (worker %d)", compressed, last_comp_time, ctx->index); // FIXME
 		}
 	}
 

src/main.c

@@ -33,7 +33,7 @@ static const struct option _long_opts[] = {
 	{"v4l2-timeout",		required_argument,	NULL,	1002},
 	{"v4l2-error-timeout",	required_argument,	NULL,	1003},
 	{"debug",				no_argument,		NULL,	5000},
-	{"perf",				no_argument,		NULL,	5001},
+	{"log-level",			required_argument,	NULL,	5001},
 	{NULL, 0, NULL, 0},
 };
 
@@ -63,8 +63,7 @@ static void _parse_options(int argc, char *argv[], struct device_t *dev) {
 	int index;
 	int ch;
 
-	log_debug = false;
+	log_level = LOG_LEVEL_INFO;
-	log_perf = false;
 	while ((ch = getopt_long(argc, argv, _short_opts, _long_opts, &index)) >= 0) {
 		switch (ch) {
 			case 0:		break;
@@ -74,7 +73,7 @@ static void _parse_options(int argc, char *argv[], struct device_t *dev) {
 			case 'f':	OPT_PARSE(dev->format, device_parse_format, FORMAT_UNKNOWN, "pixel format");
 #			pragma GCC diagnostic pop
 			case 's':	OPT_PARSE(dev->standard, device_parse_standard, STANDARD_UNKNOWN, "TV standard");
-			case 'e':	OPT_UNSIGNED(dev->every_frame, "--every-frame", 0);
+			case 'e':	OPT_UNSIGNED(dev->every_frame, "--every-frame", 1);
 			case 'z':	OPT_UNSIGNED(dev->min_frame_size, "--min-frame-size", 0);
 			case 't':	OPT_TRUE(dev->dv_timings);
 			case 'n':	OPT_UNSIGNED(dev->n_buffers, "--buffers", 1);
@@ -83,12 +82,17 @@ static void _parse_options(int argc, char *argv[], struct device_t *dev) {
 			case 1001:	OPT_UNSIGNED(dev->height, "--height", 180);
 			case 1002:	OPT_UNSIGNED(dev->timeout, "--timeout", 1);
 			case 1003:	OPT_UNSIGNED(dev->error_timeout, "--error-timeout", 1);
-			case 5000:	OPT_TRUE(log_debug);
+			case 5000:	log_level = LOG_LEVEL_DEBUG; break;
-			case 5001:	OPT_TRUE(log_perf);
+			case 5001:	OPT_UNSIGNED(log_level, "--log-level", 0);
 			case 'h':	_help(EXIT_SUCCESS); break;
 			default:	_help(EXIT_FAILURE); break;
 		}
 	}
+
+#	undef OPT_PARSE
+#	undef OPT_UNSIGNED
+#	undef OPT_TRUE
+#	undef OPT_ARG
 }
 
 struct threads_context {

src/tools.h

@@ -2,7 +2,6 @@
 
 #include <stdio.h>
 #include <stdlib.h>
-#include <stdbool.h>
 #include <string.h>
 #include <unistd.h>
 #include <errno.h>
@@ -15,42 +14,41 @@
 #include <sys/syscall.h>
 
 
-bool log_debug;
+unsigned log_level;
-bool log_perf;
 
 
+#define LOG_LEVEL_INFO		0
+#define LOG_LEVEL_VERBOSE	1
+#define LOG_LEVEL_PERF		2
+#define LOG_LEVEL_DEBUG		3
+
 #define SEP_INFO(_x_ch) \
 	{ for (int _i = 0; _i < 80; ++_i) putchar(_x_ch); putchar('\n'); }
 
-#define INNER_LOG_MK_PARAMS \
-	time_t _sec; long _msec; now_ms(&_sec, &_msec); pid_t _tid = syscall(SYS_gettid);
-
-#define INNER_LOG_PARAMS _sec, _msec, _tid
-
-#define INNER_LOG_PL "[%ld.%03ld tid=%d]"
-
-#define LOG_INFO(_x_msg, ...) \
-	{ INNER_LOG_MK_PARAMS; \
-	printf("-- INFO  " INNER_LOG_PL " -- " _x_msg "\n", INNER_LOG_PARAMS, ##__VA_ARGS__); }
-
-#define LOG_DEBUG(_x_msg, ...) \
-	{ if (log_debug) { INNER_LOG_MK_PARAMS; \
-	printf("-- DEBUG " INNER_LOG_PL " -- " _x_msg "\n", INNER_LOG_PARAMS, ##__VA_ARGS__); } }
-
-#define LOG_PERF(_x_msg, ...) \
-	{ if (log_debug || log_perf) { INNER_LOG_MK_PARAMS; \
-	printf("-- PERF  " INNER_LOG_PL " -- " _x_msg "\n", INNER_LOG_PARAMS, ##__VA_ARGS__); } }
-
 #define SEP_DEBUG(_x_ch) \
-	{ if (log_debug) { SEP_INFO(_x_ch); } }
+	{ if (log_level >= LOG_LEVEL_DEBUG) { SEP_INFO(_x_ch); } }
 
 #define LOG_ERROR(_x_msg, ...) \
-	{ INNER_LOG_MK_PARAMS; \
+	printf("-- ERROR [%.03Lf tid=%ld] -- " _x_msg "\n", now_ms_ld(), syscall(SYS_gettid), ##__VA_ARGS__)
-	printf("-- ERROR " INNER_LOG_PL " -- " _x_msg "\n", INNER_LOG_PARAMS, ##__VA_ARGS__); }
 
 #define LOG_PERROR(_x_msg, ...) \
-	{ INNER_LOG_MK_PARAMS; char _buf[1024]; strerror_r(errno, _buf, 1024); \
+	{ char _buf[1024]; strerror_r(errno, _buf, 1024); \
-	printf("-- ERROR " INNER_LOG_PL " -- " _x_msg ": %s\n", INNER_LOG_PARAMS, ##__VA_ARGS__, _buf); }
+	printf("-- ERROR [%.03Lf tid=%ld] -- " _x_msg ": %s\n", now_ms_ld(), syscall(SYS_gettid), ##__VA_ARGS__, _buf); }
+
+#define LOG_INFO(_x_msg, ...) \
+	printf("-- INFO  [%.03Lf tid=%ld] -- " _x_msg "\n", now_ms_ld(), syscall(SYS_gettid), ##__VA_ARGS__)
+
+#define LOG_VERBOSE(_x_msg, ...) \
+	{ if (log_level >= LOG_LEVEL_VERBOSE) \
+	printf("-- VERB  [%.03Lf tid=%ld] -- " _x_msg "\n", now_ms_ld(), syscall(SYS_gettid), ##__VA_ARGS__); }
+
+#define LOG_PERF(_x_msg, ...) \
+	{ if (log_level >= LOG_LEVEL_PERF) \
+	printf("-- PERF  [%.03Lf tid=%ld] -- " _x_msg "\n", now_ms_ld(), syscall(SYS_gettid), ##__VA_ARGS__); }
+
+#define LOG_DEBUG(_x_msg, ...) \
+	{ if (log_level >= LOG_LEVEL_DEBUG) \
+	printf("-- DEBUG [%.03Lf tid=%ld] -- " _x_msg "\n", now_ms_ld(), syscall(SYS_gettid), ##__VA_ARGS__); }
 
 
 #define A_PTHREAD_CREATE(_tid, _func, _arg)	assert(!pthread_create(_tid, NULL, _func, _arg))
@@ -81,7 +79,7 @@ bool log_perf;
 INLINE void now_ms(time_t *sec, long *msec) {
 	struct timespec spec;
 
-	assert(!clock_gettime(CLOCK_REALTIME, &spec));
+	assert(!clock_gettime(CLOCK_MONOTONIC_RAW, &spec));
 	*sec = spec.tv_sec;
 	*msec = round(spec.tv_nsec / 1.0e6);
 
@@ -91,6 +89,14 @@ INLINE void now_ms(time_t *sec, long *msec) {
 	}
 }
 
+INLINE long double now_ms_ld(void) {
+	time_t sec;
+	long msec;
+
+	now_ms(&sec, &msec);
+	return (long double)sec + ((long double)msec) / 1000;
+}
+
 INLINE int xioctl(const int fd, const int request, void *arg) {
 	int retries = XIOCTL_RETRIES;
 	int retval = -1;