diff --git a/src/capture.c b/src/capture.c index c06a38c..513035e 100644 --- a/src/capture.c +++ b/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; - fd_set write_fds; - fd_set error_fds; + LOG_DEBUG("Waiting for workers ..."); + 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); - FD_ZERO(&read_fds); - FD_SET(dev->run->fd, &read_fds); + if (*global_stop) { + break; + } - FD_ZERO(&write_fds); - FD_SET(dev->run->fd, &write_fds); - - FD_ZERO(&error_fds); - FD_SET(dev->run->fd, &error_fds); +# define INIT_FD_SET(_set) \ + fd_set _set; FD_ZERO(&_set); FD_SET(dev->run->fd, &_set); + INIT_FD_SET(read_fds); + INIT_FD_SET(write_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 ..."); - - 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); + LOG_DEBUG("Frame is ready"); 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 } } diff --git a/src/main.c b/src/main.c index e15c2e4..68003fe 100644 --- a/src/main.c +++ b/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_perf = false; + log_level = LOG_LEVEL_INFO; 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 5001: OPT_TRUE(log_perf); + case 5000: log_level = LOG_LEVEL_DEBUG; break; + 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 { diff --git a/src/tools.h b/src/tools.h index ce0a22e..48f82fc 100644 --- a/src/tools.h +++ b/src/tools.h @@ -2,7 +2,6 @@ #include #include -#include #include #include #include @@ -15,42 +14,41 @@ #include -bool log_debug; -bool log_perf; +unsigned log_level; +#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 " INNER_LOG_PL " -- " _x_msg "\n", INNER_LOG_PARAMS, ##__VA_ARGS__); } + printf("-- ERROR [%.03Lf tid=%ld] -- " _x_msg "\n", now_ms_ld(), syscall(SYS_gettid), ##__VA_ARGS__) #define LOG_PERROR(_x_msg, ...) \ - { INNER_LOG_MK_PARAMS; char _buf[1024]; strerror_r(errno, _buf, 1024); \ - printf("-- ERROR " INNER_LOG_PL " -- " _x_msg ": %s\n", INNER_LOG_PARAMS, ##__VA_ARGS__, _buf); } + { char _buf[1024]; strerror_r(errno, _buf, 1024); \ + 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;