Bump version: 0.13 → 0.14

.bumpversion.cfg

@@ -1,7 +1,7 @@
 [bumpversion]
 commit = True
 tag = True
-current_version = 0.12
+current_version = 0.14
 parse = (?P<major>\d+)\.(?P<minor>\d+)(\.(?P<patch>\d+)(\-(?P<release>[a-z]+))?)?
 serialize = 
 	{major}.{minor}

PKGBUILD

@@ -3,7 +3,7 @@
 
 
 pkgname=ustreamer
-pkgver=0.12
+pkgver=0.14
 pkgrel=1
 pkgdesc="Lightweight and fast MJPG-HTTP streamer"
 url="https://github.com/pi-kvm/ustreamer"

src/config.h

@@ -21,4 +21,4 @@
 
 #pragma once
 
-#define VERSION "0.12"
+#define VERSION "0.14"

src/device.c

@@ -250,7 +250,7 @@ static int _device_apply_dv_timings(struct device_t *dev) {
 	LOG_DEBUG("Calling ioctl(VIDIOC_QUERY_DV_TIMINGS) ...");
 	if (xioctl(dev->run->fd, VIDIOC_QUERY_DV_TIMINGS, &dv_timings) == 0) {
 		LOG_INFO(
-			"Got new DV timings: resolution=%dx%d; pixclk=%llu\n",
+			"Got new DV timings: resolution=%dx%d; pixclk=%llu",
 			dv_timings.bt.width,
 			dv_timings.bt.height,
 			dv_timings.bt.pixelclock

src/device.h

@@ -44,6 +44,9 @@ struct picture_t {
 	unsigned char	*data;
 	unsigned long	size;
 	unsigned long	allocated;
+	long double		grab_time;
+	long double		encode_begin_time;
+	long double		encode_end_time;
 };
 
 struct device_runtime_t {

src/encoder.c

@@ -131,6 +131,8 @@ void encoder_prepare_for_device(struct encoder_t *encoder, struct device_t *dev)
 int encoder_compress_buffer(struct encoder_t *encoder, struct device_t *dev, const unsigned index) {
 	assert(encoder->type != ENCODER_TYPE_UNKNOWN);
 
+	dev->run->pictures[index].encode_begin_time = now_monotonic_ms();
+
 	if (encoder->type == ENCODER_TYPE_CPU) {
 		jpeg_encoder_compress_buffer(dev, index, encoder->quality);
 	}
@@ -142,6 +144,8 @@ int encoder_compress_buffer(struct encoder_t *encoder, struct device_t *dev, con
 	}
 #	endif
 
+	dev->run->pictures[index].encode_end_time = now_monotonic_ms();
+
 	return 0;
 
 #	pragma GCC diagnostic ignored "-Wunused-label"

src/http.c

@@ -22,7 +22,6 @@
 #include <stdlib.h>
 #include <stdbool.h>
 #include <string.h>
-#include <time.h>
 #include <assert.h>
 
 #include <event2/event.h>
@@ -86,7 +85,7 @@ struct http_server_t *http_server_init(struct stream_t *stream) {
 
 	assert(!evhttp_set_cb(run->http, "/", _http_callback_root, NULL));
 	assert(!evhttp_set_cb(run->http, "/ping", _http_callback_ping, (void *)server));
-	assert(!evhttp_set_cb(run->http, "/snapshot", _http_callback_snapshot, (void *)exposed));
+	assert(!evhttp_set_cb(run->http, "/snapshot", _http_callback_snapshot, (void *)server));
 	assert(!evhttp_set_cb(run->http, "/stream", _http_callback_stream, (void *)server));
 
 	refresh_interval.tv_sec = 0;
@@ -185,33 +184,45 @@ static void _http_callback_ping(struct evhttp_request *request, void *v_server)
 	evbuffer_free(buf);
 }
 
-static void _http_callback_snapshot(struct evhttp_request *request, void *v_exposed) {
-	struct exposed_t *exposed = (struct exposed_t *)v_exposed;
+static void _http_callback_snapshot(struct evhttp_request *request, void *v_server) {
+	struct http_server_t *server = (struct http_server_t *)v_server;
 	struct evbuffer *buf;
-	struct timespec x_timestamp_spec;
-	char x_timestamp_buf[64];
+	char time_buf[64];
 
 	PROCESS_HEAD_REQUEST;
 
-	assert((buf = evbuffer_new()));
-	assert(!evbuffer_add(buf, (const void *)exposed->picture.data, exposed->picture.size));
+#	define EXPOSED(_next) server->run->exposed->_next
 
-	assert(!clock_gettime(CLOCK_REALTIME, &x_timestamp_spec));
-	sprintf(
-		x_timestamp_buf, "%u.%06u",
-		(unsigned)x_timestamp_spec.tv_sec,
-		(unsigned)(x_timestamp_spec.tv_nsec / 1000) // TODO: round?
-	);
+	assert((buf = evbuffer_new()));
+	assert(!evbuffer_add(buf, (const void *)EXPOSED(picture.data), EXPOSED(picture.size)));
 
 	ADD_HEADER("Access-Control-Allow-Origin:", "*");
 	ADD_HEADER("Cache-Control", "no-store, no-cache, must-revalidate, pre-check=0, post-check=0, max-age=0");
 	ADD_HEADER("Pragma", "no-cache");
 	ADD_HEADER("Expires", "Mon, 3 Jan 2000 12:34:56 GMT");
-	ADD_HEADER("X-Timestamp", x_timestamp_buf);
+
+#	define ADD_TIME_HEADER(_key, _value) \
+		{ sprintf(time_buf, "%.06Lf", _value); ADD_HEADER(_key, time_buf); }
+
+	ADD_TIME_HEADER("X-Timestamp", now_real_ms());
+
+	if (server->add_x_timings) {
+		ADD_TIME_HEADER("X-UStreamer-Grab-Time",			EXPOSED(picture.grab_time));
+		ADD_TIME_HEADER("X-UStreamer-Encode-Begin-Time",	EXPOSED(picture.encode_begin_time));
+		ADD_TIME_HEADER("X-UStreamer-Encode-End-Time",		EXPOSED(picture.encode_end_time));
+		ADD_TIME_HEADER("X-UStreamer-Expose-Begin-Time",	EXPOSED(expose_begin_time));
+		ADD_TIME_HEADER("X-UStreamer-Expose-End-Time",		EXPOSED(expose_end_time));
+		ADD_TIME_HEADER("X-UStreamer-Send-Time",			now_monotonic_ms());
+	}
+
+#	undef ADD_TIME_HEADER
+
 	ADD_HEADER("Content-Type", "image/jpeg");
 
 	evhttp_send_reply(request, HTTP_OK, "OK", buf);
 	evbuffer_free(buf);
+
+#	undef EXPOSED
 }
 
 #undef ADD_HEADER
@@ -227,6 +238,8 @@ static void _http_callback_stream(struct evhttp_request *request, void *v_server
 	struct evhttp_connection *conn;
 	struct bufferevent *buf_event;
 	struct stream_client_t *client;
+	char *client_addr;
+	unsigned short client_port;
 
 	PROCESS_HEAD_REQUEST;
 
@@ -247,6 +260,13 @@ static void _http_callback_stream(struct evhttp_request *request, void *v_server
 			client->prev = last;
 			last->next = client;
 		}
+		server->run->stream_clients_count += 1;
+
+		evhttp_connection_get_peer(conn, &client_addr, &client_port);
+		LOG_INFO(
+			"HTTP: Registered the new stream client: [%s]:%u; clients now: %u",
+			client_addr, client_port, server->run->stream_clients_count
+		);
 
 		buf_event = evhttp_connection_get_bufferevent(conn);
 		bufferevent_setcb(buf_event, NULL, NULL, _http_callback_stream_error, (void *)client);
@@ -258,16 +278,14 @@ static void _http_callback_stream(struct evhttp_request *request, void *v_server
 
 #undef PROCESS_HEAD_REQUEST
 
-#define BOUNDARY "boundarydonotcross"
-#define RN "\r\n"
-
 static void _http_callback_stream_write(struct bufferevent *buf_event, void *v_client) {
+#	define BOUNDARY "boundarydonotcross"
+#	define RN "\r\n"
+
 	struct stream_client_t *client = (struct stream_client_t *)v_client;
 	struct evbuffer *buf;
-	struct timespec x_timestamp_spec;
 
 	assert((buf = evbuffer_new()));
-	assert(!clock_gettime(CLOCK_REALTIME, &x_timestamp_spec));
 
 	if (client->need_initial) {
 		assert(evbuffer_add_printf(buf,
@@ -284,18 +302,37 @@ static void _http_callback_stream_write(struct bufferevent *buf_event, void *v_c
 		client->need_initial = false;
 	}
 
+#	define EXPOSED(_next) client->server->run->exposed->_next
+
 	assert(evbuffer_add_printf(buf,
 		"Content-Type: image/jpeg" RN
 		"Content-Length: %lu" RN
-		"X-Timestamp: %u.%06u" RN
-		RN,
-		client->server->run->exposed->picture.size * sizeof(*client->server->run->exposed->picture.data),
-		(unsigned)x_timestamp_spec.tv_sec,
-		(unsigned)(x_timestamp_spec.tv_nsec / 1000) // TODO: round?
+		"X-Timestamp: %.06Lf" RN
+		"%s",
+		EXPOSED(picture.size) * sizeof(*EXPOSED(picture.data)),
+		now_real_ms(), (client->server->add_x_timings ? "" : RN)
 	));
+	if (client->server->add_x_timings) {
+		assert(evbuffer_add_printf(buf,
+			"X-UStreamer-Grab-Time: %.06Lf" RN
+			"X-UStreamer-Encode-Begin-Time: %.06Lf" RN
+			"X-UStreamer-Encode-End-Time: %.06Lf" RN
+			"X-UStreamer-Expose-Begin-Time: %.06Lf" RN
+			"X-UStreamer-Expose-End-Time: %.06Lf" RN
+			"X-UStreamer-Send-Time: %.06Lf" RN
+			RN,
+			EXPOSED(picture.grab_time),
+			EXPOSED(picture.encode_begin_time),
+			EXPOSED(picture.encode_end_time),
+			EXPOSED(expose_begin_time),
+			EXPOSED(expose_end_time),
+			now_monotonic_ms()
+		));
+	}
+
 	assert(!evbuffer_add(buf,
-		(void *)client->server->run->exposed->picture.data,
-		client->server->run->exposed->picture.size * sizeof(*client->server->run->exposed->picture.data)
+		(void *)EXPOSED(picture.data),
+		EXPOSED(picture.size) * sizeof(*EXPOSED(picture.data))
 	));
 	assert(evbuffer_add_printf(buf, RN "--" BOUNDARY RN));
 
@@ -304,16 +341,28 @@ static void _http_callback_stream_write(struct bufferevent *buf_event, void *v_c
 
 	bufferevent_setcb(buf_event, NULL, NULL, _http_callback_stream_error, (void *)client);
 	bufferevent_enable(buf_event, EV_READ);
-}
 
-#undef BOUNDARY
-#undef RN
+#	undef BOUNDARY
+#	undef RN
+#	undef EXPOSED
+}
 
 static void _http_callback_stream_error(UNUSED struct bufferevent *buf_event, UNUSED short what, void *v_client) {
 	struct stream_client_t *client = (struct stream_client_t *)v_client;
 	struct evhttp_connection *conn;
+	char *client_addr = "???";
+	unsigned short client_port = 0;
+
+	client->server->run->stream_clients_count -= 1;
 
 	conn = evhttp_request_get_connection(client->request);
+	if (conn != NULL) {
+		evhttp_connection_get_peer(conn, &client_addr, &client_port);
+	}
+	LOG_INFO(
+		"HTTP: Disconnected the stream client: [%s]:%u; clients now: %u",
+		client_addr, client_port, client->server->run->stream_clients_count
+	);
 	if (conn != NULL) {
 		evhttp_connection_free(conn);
 	}
@@ -382,70 +431,97 @@ static void _http_exposed_refresh(UNUSED int fd, UNUSED short what, void *v_serv
 }
 
 static bool _expose_new_picture(struct http_server_t *server) {
-	assert(server->run->stream->picture.size > 0);
-	server->run->exposed->fps = server->run->stream->fps;
+#	define STREAM(_next) server->run->stream->_next
+#	define EXPOSED(_next) server->run->exposed->_next
+
+	assert(STREAM(picture.size) > 0);
+	EXPOSED(fps) = STREAM(fps);
+	EXPOSED(expose_begin_time) = now_monotonic_ms();
 
 #	define MEM_STREAM_TO_EXPOSED \
-		server->run->exposed->picture.data, server->run->stream->picture.data, \
-		server->run->stream->picture.size * sizeof(*server->run->exposed->picture.data)
+		EXPOSED(picture.data), STREAM(picture.data), \
+		STREAM(picture.size) * sizeof(*STREAM(picture.data))
 
 	if (server->drop_same_frames) {
 		if (
-			server->run->exposed->online
-			&& server->run->exposed->dropped < server->drop_same_frames
-			&& server->run->exposed->picture.size == server->run->stream->picture.size
+			EXPOSED(online)
+			&& EXPOSED(dropped) < server->drop_same_frames
+			&& EXPOSED(picture.size) == STREAM(picture.size)
 			&& !memcmp(MEM_STREAM_TO_EXPOSED)
 		) {
-			LOG_PERF("HTTP: dropped same frame number %u", server->run->exposed->dropped);
-			++server->run->exposed->dropped;
+			LOG_PERF("HTTP: dropped same frame number %u", EXPOSED(dropped));
+			EXPOSED(dropped) += 1;
+			EXPOSED(expose_end_time) = now_monotonic_ms();
 			return false; // Not updated
 		}
 	}
 
-	if (server->run->exposed->picture.allocated < server->run->stream->picture.allocated) {
-		A_REALLOC(server->run->exposed->picture.data, server->run->stream->picture.allocated);
-		server->run->exposed->picture.allocated = server->run->stream->picture.allocated;
+	if (EXPOSED(picture.allocated) < STREAM(picture.allocated)) {
+		A_REALLOC(EXPOSED(picture.data), STREAM(picture.allocated));
+		EXPOSED(picture.allocated) = STREAM(picture.allocated);
 	}
 
 	memcpy(MEM_STREAM_TO_EXPOSED);
 
 #	undef MEM_STREAM_TO_EXPOSED
 
-	server->run->exposed->picture.size = server->run->stream->picture.size;
-	server->run->exposed->width = server->run->stream->width;
-	server->run->exposed->height = server->run->stream->height;
-	server->run->exposed->online = true;
-	server->run->exposed->dropped = 0;
+	EXPOSED(picture.size) = STREAM(picture.size);
+
+	EXPOSED(picture.grab_time) = STREAM(picture.grab_time);
+	EXPOSED(picture.encode_begin_time) = STREAM(picture.encode_begin_time);
+	EXPOSED(picture.encode_end_time) = STREAM(picture.encode_end_time);
+
+	EXPOSED(width) = STREAM(width);
+	EXPOSED(height) = STREAM(height);
+	EXPOSED(online) = true;
+	EXPOSED(dropped) = 0;
+	EXPOSED(expose_end_time) = now_monotonic_ms();
+
+#	undef STREAM
+#	undef EXPOSED
 	return true; // Updated
 }
 
 static bool _expose_blank_picture(struct http_server_t *server) {
-	if (server->run->exposed->online || server->run->exposed->picture.size == 0) {
-		if (server->run->exposed->picture.allocated < BLANK_JPG_SIZE) {
-			A_REALLOC(server->run->exposed->picture.data, BLANK_JPG_SIZE);
-			server->run->exposed->picture.allocated = BLANK_JPG_SIZE;
+#	define EXPOSED(_next) server->run->exposed->_next
+
+	EXPOSED(expose_begin_time) = now_monotonic_ms();
+
+	if (EXPOSED(online) || EXPOSED(picture.size) == 0) {
+		if (EXPOSED(picture.allocated) < BLANK_JPG_SIZE) {
+			A_REALLOC(EXPOSED(picture.data), BLANK_JPG_SIZE);
+			EXPOSED(picture.allocated) = BLANK_JPG_SIZE;
 		}
 
 		memcpy(
-			server->run->exposed->picture.data, BLANK_JPG_DATA,
-			BLANK_JPG_SIZE * sizeof(*server->run->exposed->picture.data)
+			EXPOSED(picture.data), BLANK_JPG_DATA,
+			BLANK_JPG_SIZE * sizeof(*EXPOSED(picture.data))
 		);
 
-		server->run->exposed->picture.size = BLANK_JPG_SIZE;
-		server->run->exposed->width = BLANK_JPG_WIDTH;
-		server->run->exposed->height = BLANK_JPG_HEIGHT;
-		server->run->exposed->fps = 0;
-		server->run->exposed->online = false;
+		EXPOSED(picture.size) = BLANK_JPG_SIZE;
+
+		EXPOSED(picture.grab_time) = 0;
+		EXPOSED(picture.encode_begin_time) = 0;
+		EXPOSED(picture.encode_end_time) = 0;
+
+		EXPOSED(width) = BLANK_JPG_WIDTH;
+		EXPOSED(height) = BLANK_JPG_HEIGHT;
+		EXPOSED(fps) = 0;
+		EXPOSED(online) = false;
 		goto updated;
 	}
 
-	if (server->run->exposed->dropped < server->run->drop_same_frames_blank) {
-		LOG_PERF("HTTP: dropped same frame (BLANK) number %u", server->run->exposed->dropped);
-		++server->run->exposed->dropped;
+	if (EXPOSED(dropped) < server->run->drop_same_frames_blank) {
+		LOG_PERF("HTTP: dropped same frame (BLANK) number %u", EXPOSED(dropped));
+		EXPOSED(dropped) += 1;
+		EXPOSED(expose_end_time) = now_monotonic_ms();
 		return false; // Not updated
 	}
 
 	updated:
-		server->run->exposed->dropped = 0;
+		EXPOSED(dropped) = 0;
+		EXPOSED(expose_end_time) = now_monotonic_ms();
 		return true; // Updated
+
+#	undef EXPOSED
 }

src/http.h

@@ -45,6 +45,8 @@ struct exposed_t {
 	unsigned			fps;
 	bool				online;
 	unsigned			dropped;
+	long double			expose_begin_time;
+	long double			expose_end_time;
 };
 
 struct http_server_runtime_t {
@@ -54,6 +56,7 @@ struct http_server_runtime_t {
 	struct stream_t			*stream;
 	struct exposed_t		*exposed;
 	struct stream_client_t	*stream_clients;
+	unsigned				stream_clients_count;
 	unsigned				drop_same_frames_blank;
 };
 
@@ -61,6 +64,7 @@ struct http_server_t {
 	char		*host;
 	unsigned	port;
 	unsigned	drop_same_frames;
+	bool		add_x_timings;
 	unsigned	fake_width;
 	unsigned	fake_height;
 	unsigned	timeout;

src/jpeg/encoder.c

@@ -137,7 +137,7 @@ static void _jpeg_write_scanlines_yuyv(struct jpeg_compress_struct *jpeg,
 	while (jpeg->next_scanline < height) {
 		unsigned char *ptr = line_buffer;
 
-		for (unsigned x = 0; x < width; x++) {
+		for (unsigned x = 0; x < width; ++x) {
 			int y = (!z ? data[0] << 8 : data[2] << 8);
 			int u = data[1] - 128;
 			int v = data[3] - 128;
@@ -171,7 +171,7 @@ static void _jpeg_write_scanlines_uyvy(struct jpeg_compress_struct *jpeg,
 	while(jpeg->next_scanline < height) {
 		unsigned char *ptr = line_buffer;
 
-		for(unsigned x = 0; x < width; x++) {
+		for(unsigned x = 0; x < width; ++x) {
 			int y = (!z ? data[1] << 8 : data[3] << 8);
 			int u = data[0] - 128;
 			int v = data[2] - 128;
@@ -204,7 +204,7 @@ static void _jpeg_write_scanlines_rgb565(struct jpeg_compress_struct *jpeg,
 	while(jpeg->next_scanline < height) {
 		unsigned char *ptr = line_buffer;
 
-		for(unsigned x = 0; x < width; x++) {
+		for(unsigned x = 0; x < width; ++x) {
 			unsigned int two_byte = (data[1] << 8) + data[0];
 
 			*(ptr++) = data[1] & 248;

src/logging.h

@@ -71,7 +71,7 @@ pthread_mutex_t log_mutex;
 
 #define LOG_ERROR(_x_msg, ...) { \
 		LOGGING_LOCK; \
-		printf("-- ERROR [%.03Lf tid=%ld] -- " _x_msg "\n", now_ms_ld(), syscall(SYS_gettid), ##__VA_ARGS__); \
+		printf("-- ERROR [%.03Lf tid=%ld] -- " _x_msg "\n", now_monotonic_ms(), syscall(SYS_gettid), ##__VA_ARGS__); \
 		LOGGING_UNLOCK; \
 	}
 
@@ -79,24 +79,24 @@ pthread_mutex_t log_mutex;
 		char _buf[1024] = ""; \
 		strerror_r(errno, _buf, 1024); \
 		LOGGING_LOCK; \
-		printf("-- ERROR [%.03Lf tid=%ld] -- " _x_msg ": %s\n", now_ms_ld(), syscall(SYS_gettid), ##__VA_ARGS__, _buf); \
+		printf("-- ERROR [%.03Lf tid=%ld] -- " _x_msg ": %s\n", now_monotonic_ms(), syscall(SYS_gettid), ##__VA_ARGS__, _buf); \
 		LOGGING_UNLOCK; \
 	}
 
 #define LOG_INFO(_x_msg, ...) { \
 		LOGGING_LOCK; \
-		printf("-- INFO  [%.03Lf tid=%ld] -- " _x_msg "\n", now_ms_ld(), syscall(SYS_gettid), ##__VA_ARGS__); \
+		printf("-- INFO  [%.03Lf tid=%ld] -- " _x_msg "\n", now_monotonic_ms(), syscall(SYS_gettid), ##__VA_ARGS__); \
 		LOGGING_UNLOCK; \
 	}
 
 #define LOG_INFO_NOLOCK(_x_msg, ...) { \
-		printf("-- INFO  [%.03Lf tid=%ld] -- " _x_msg "\n", now_ms_ld(), syscall(SYS_gettid), ##__VA_ARGS__); \
+		printf("-- INFO  [%.03Lf tid=%ld] -- " _x_msg "\n", now_monotonic_ms(), syscall(SYS_gettid), ##__VA_ARGS__); \
 	}
 
 #define LOG_PERF(_x_msg, ...) { \
 		if (log_level >= LOG_LEVEL_PERF) { \
 			LOGGING_LOCK; \
-			printf("-- PERF  [%.03Lf tid=%ld] -- " _x_msg "\n", now_ms_ld(), syscall(SYS_gettid), ##__VA_ARGS__); \
+			printf("-- PERF  [%.03Lf tid=%ld] -- " _x_msg "\n", now_monotonic_ms(), syscall(SYS_gettid), ##__VA_ARGS__); \
 			LOGGING_UNLOCK; \
 		} \
 	}
@@ -104,7 +104,7 @@ pthread_mutex_t log_mutex;
 #define LOG_VERBOSE(_x_msg, ...) { \
 		if (log_level >= LOG_LEVEL_VERBOSE) { \
 			LOGGING_LOCK; \
-			printf("-- VERB  [%.03Lf tid=%ld] -- " _x_msg "\n", now_ms_ld(), syscall(SYS_gettid), ##__VA_ARGS__); \
+			printf("-- VERB  [%.03Lf tid=%ld] -- " _x_msg "\n", now_monotonic_ms(), syscall(SYS_gettid), ##__VA_ARGS__); \
 			LOGGING_UNLOCK; \
 		} \
 	}
@@ -112,7 +112,7 @@ pthread_mutex_t log_mutex;
 #define LOG_DEBUG(_x_msg, ...) { \
 		if (log_level >= LOG_LEVEL_DEBUG) { \
 			LOGGING_LOCK; \
-			printf("-- DEBUG [%.03Lf tid=%ld] -- " _x_msg "\n", now_ms_ld(), syscall(SYS_gettid), ##__VA_ARGS__); \
+			printf("-- DEBUG [%.03Lf tid=%ld] -- " _x_msg "\n", now_monotonic_ms(), syscall(SYS_gettid), ##__VA_ARGS__); \
 			LOGGING_UNLOCK; \
 		} \
 	}

src/main.c

@@ -63,9 +63,10 @@ static const struct option _long_opts[] = {
 	{"host",					required_argument,	NULL,	's'},
 	{"port",					required_argument,	NULL,	'p'},
 	{"drop-same-frames",		required_argument,	NULL,	'r'},
-	{"fake-width",				required_argument,	NULL,	2000},
-	{"fake-height",				required_argument,	NULL,	2001},
-	{"server-timeout",			required_argument,	NULL,	2002},
+	{"add-x-timings",			no_argument,		NULL,	2000},
+	{"fake-width",				required_argument,	NULL,	2001},
+	{"fake-height",				required_argument,	NULL,	2002},
+	{"server-timeout",			required_argument,	NULL,	2003},
 
 	{"perf",					no_argument,		NULL,	5000},
 	{"verbose",					no_argument,		NULL,	5001},
@@ -116,6 +117,8 @@ static void _help(struct device_t *dev, struct encoder_t *encoder, struct http_s
 	printf("                                  It can significantly reduce the outgoing traffic, but will increase\n");
 	printf("                                  the CPU loading. Don't use this option with analog signal sources\n");
 	printf("                                  or webcams, it's useless. Default: disabled.\n\n");
+	printf("    --add-x-timings            -- Add X-UStreamer-*-Time headers to the /stream and /snapshot handles.\n");
+	printf("                                  Default: disabled.\n\n");
 	printf("    --fake-width <N>           -- Override image width for /ping. Default: disabled\n\n");
 	printf("    --fake-height <N>          -- Override image height for /ping. Default: disabled.\n\n");
 	printf("    --server-timeout <seconds> -- Timeout for client connections. Default: %d\n\n", server->timeout);
@@ -132,11 +135,8 @@ static void _help(struct device_t *dev, struct encoder_t *encoder, struct http_s
 }
 
 static int _parse_options(int argc, char *argv[], struct device_t *dev, struct encoder_t *encoder, struct http_server_t *server) {
-#	define OPT_ARG(_dest) \
-		{ _dest = optarg; break; }
-
-#	define OPT_TRUE(_dest) \
-		{ _dest = true; break; }
+#	define OPT_SET(_dest, _value) \
+		{ _dest = _value; break; }
 
 #	define OPT_UNSIGNED(_dest, _name, _min, _max) \
 		{ errno = 0; int _tmp = strtol(optarg, NULL, 0); \
@@ -155,7 +155,7 @@ static int _parse_options(int argc, char *argv[], struct device_t *dev, struct e
 	log_level = LOG_LEVEL_INFO;
 	while ((ch = getopt_long(argc, argv, _short_opts, _long_opts, &index)) >= 0) {
 		switch (ch) {
-			case 'd':	OPT_ARG(dev->path);
+			case 'd':	OPT_SET(dev->path, optarg);
 			case 'x':	OPT_UNSIGNED(dev->width, "--width", 320, 1920);
 			case 'y':	OPT_UNSIGNED(dev->height, "--height", 180, 1200);
 #			pragma GCC diagnostic ignored "-Wsign-compare"
@@ -165,37 +165,37 @@ static int _parse_options(int argc, char *argv[], struct device_t *dev, struct e
 			case 'a':	OPT_PARSE(dev->standard, device_parse_standard, STANDARD_UNKNOWN, "TV standard");
 			case 'e':	OPT_UNSIGNED(dev->every_frame, "--every-frame", 1, 30);
 			case 'z':	OPT_UNSIGNED(dev->min_frame_size, "--min-frame-size", 0, 8192);
-			case 't':	OPT_TRUE(dev->dv_timings);
+			case 't':	OPT_SET(dev->dv_timings, true);
 			case 'b':	OPT_UNSIGNED(dev->n_buffers, "--buffers", 1, 32);
 			case 'w':	OPT_UNSIGNED(dev->n_workers, "--workers", 1, 32);
 			case 'q':	OPT_UNSIGNED(encoder->quality, "--quality", 1, 100);
 			case 'c':	OPT_PARSE(encoder->type, encoder_parse_type, ENCODER_TYPE_UNKNOWN, "encoder type");
 #			ifdef OMX_ENCODER
-			case 500:	encoder->omx_use_ijg = true; break;
+			case 500:	OPT_SET(encoder->omx_use_ijg, true);
 #			endif
 			case 1000:	OPT_UNSIGNED(dev->timeout, "--timeout", 1, 60);
 			case 1001:	OPT_UNSIGNED(dev->error_timeout, "--error-timeout", 1, 60);
 
-			case 's':	server->host = optarg; break;
+			case 's':	OPT_SET(server->host, optarg);
 			case 'p':	OPT_UNSIGNED(server->port, "--port", 1, 65535);
 			case 'r':	OPT_UNSIGNED(server->drop_same_frames, "--drop-same-frames", 0, 30);
-			case 2000:	OPT_UNSIGNED(server->fake_width, "--fake-width", 0, 1920);
-			case 2001:	OPT_UNSIGNED(server->fake_height, "--fake-height", 0, 1200);
-			case 2002:	OPT_UNSIGNED(server->timeout, "--server-timeout", 1, 60);
+			case 2000:	OPT_SET(server->add_x_timings, true);
+			case 2001:	OPT_UNSIGNED(server->fake_width, "--fake-width", 0, 1920);
+			case 2002:	OPT_UNSIGNED(server->fake_height, "--fake-height", 0, 1200);
+			case 2003:	OPT_UNSIGNED(server->timeout, "--server-timeout", 1, 60);
 
-			case 5000:	log_level = LOG_LEVEL_PERF; break;
-			case 5001:	log_level = LOG_LEVEL_VERBOSE; break;
-			case 5002:	log_level = LOG_LEVEL_DEBUG; break;
+			case 5000:	OPT_SET(log_level, LOG_LEVEL_PERF);
+			case 5001:	OPT_SET(log_level, LOG_LEVEL_VERBOSE);
+			case 5002:	OPT_SET(log_level, LOG_LEVEL_DEBUG);
 			case 5010:	OPT_UNSIGNED(log_level, "--log-level", 0, 3);
 			case 0:		break;
 			case 'h':	default: _help(dev, encoder, server); return -1;
 		}
 	}
 
-#	undef OPT_PARSE
+#	undef OPT_SET
 #	undef OPT_UNSIGNED
-#	undef OPT_TRUE
-#	undef OPT_ARG
+#	undef OPT_PARSE
 	return 0;
 }
 

src/omx/formatters.h

@@ -35,7 +35,7 @@
 
 #define LOG_OMX_ERROR(_error, _msg, ...) { \
 		LOGGING_LOCK; \
-		printf("-- ERROR [%.03Lf tid=%ld] -- " _msg ": %s\n", now_ms_ld(), \
+		printf("-- ERROR [%.03Lf tid=%ld] -- " _msg ": %s\n", now_monotonic_ms(), \
 			syscall(SYS_gettid), ##__VA_ARGS__, omx_error_to_string(_error)); \
 		LOGGING_UNLOCK; \
 	}

src/stream.c

@@ -162,15 +162,17 @@ void stream_loop(struct stream_t *stream) {
 					LOG_DEBUG("Frame is ready");
 
 					struct v4l2_buffer buf_info;
+					long double now = now_monotonic_ms();
 
 					if (_stream_grab_buffer(stream->dev, &buf_info) < 0) {
 						break;
 					}
+					stream->dev->run->pictures[buf_info.index].grab_time = now;
 
 					if (stream->dev->every_frame) {
 						if (frames_count < stream->dev->every_frame - 1) {
-							LOG_DEBUG("Dropping frame %d for option --every-frame=%d", frames_count + 1, stream->dev->every_frame);
-							++frames_count;
+							frames_count += 1;
+							LOG_DEBUG("Dropping frame %d for option --every-frame=%d", frames_count, stream->dev->every_frame);
 							goto pass_frame;
 						}
 						frames_count = 0;
@@ -187,8 +189,6 @@ void stream_loop(struct stream_t *stream) {
 					}
 
 					{
-						long double now = now_ms_ld();
-
 						if (now < grab_after) {
 							fluency_passed += 1;
 							LOG_VERBOSE("Passed %u frames for fluency: now=%.03Lf; grab_after=%.03Lf", fluency_passed, now, grab_after);
@@ -202,7 +202,7 @@ void stream_loop(struct stream_t *stream) {
 							fps = 0;
 							fps_second = (long long)now;
 						}
-						++fps;
+						fps += 1;
 
 						long double fluency_delay = _stream_get_fluency_delay(stream->dev, &pool);
 
@@ -283,20 +283,27 @@ void stream_loop_break(struct stream_t *stream) {
 }
 
 static void _stream_expose_picture(struct stream_t *stream, unsigned buf_index) {
+#	define PICTURE(_next) stream->dev->run->pictures[buf_index]._next
+
 	A_PTHREAD_M_LOCK(&stream->mutex);
 
-	stream->picture.size = stream->dev->run->pictures[buf_index].size;
-	stream->picture.allocated = stream->dev->run->pictures[buf_index].allocated;
+	stream->picture.size = PICTURE(size);
+	stream->picture.allocated = PICTURE(allocated);
 	memcpy(
-		stream->picture.data, stream->dev->run->pictures[buf_index].data,
+		stream->picture.data, PICTURE(data),
 		stream->picture.size * sizeof(*stream->picture.data)
 	);
+	stream->picture.grab_time = PICTURE(grab_time);
+	stream->picture.encode_begin_time = PICTURE(encode_begin_time);
+	stream->picture.encode_end_time = PICTURE(encode_end_time);
 
 	stream->width = stream->dev->run->width;
 	stream->height = stream->dev->run->height;
 	stream->updated = true;
 
 	A_PTHREAD_M_UNLOCK(&stream->mutex);
+
+#	undef PICTURE
 }
 
 static long double _stream_get_fluency_delay(struct device_t *dev, struct workers_pool_t *pool) {
@@ -368,25 +375,29 @@ static void _stream_init_workers(struct device_t *dev, struct workers_pool_t *po
 		A_PTHREAD_M_INIT(&pool->workers[number].has_job_mutex);
 		A_PTHREAD_C_INIT(&pool->workers[number].has_job_cond);
 
-		pool->workers[number].ctx.number = number;
-		pool->workers[number].ctx.dev = dev;
-		pool->workers[number].ctx.dev_stop = (sig_atomic_t *volatile)&dev->stop;
-		pool->workers[number].ctx.workers_stop = pool->workers_stop;
+#	define CTX(_next) pool->workers[number].ctx._next
 
-		pool->workers[number].ctx.encoder = pool->encoder;
+		CTX(number)			= number;
+		CTX(dev)			= dev;
+		CTX(dev_stop)		= (sig_atomic_t *volatile)&dev->stop;
+		CTX(workers_stop)	= pool->workers_stop;
 
-		pool->workers[number].ctx.last_comp_time_mutex = &pool->workers[number].last_comp_time_mutex;
-		pool->workers[number].ctx.last_comp_time = &pool->workers[number].last_comp_time;
+		CTX(encoder) = pool->encoder;
 
-		pool->workers[number].ctx.has_job_mutex = &pool->workers[number].has_job_mutex;
-		pool->workers[number].ctx.has_job = &pool->workers[number].has_job;
-		pool->workers[number].ctx.job_failed = &pool->workers[number].job_failed;
-		pool->workers[number].ctx.job_start_time = &pool->workers[number].job_start_time;
-		pool->workers[number].ctx.has_job_cond = &pool->workers[number].has_job_cond;
+		CTX(last_comp_time_mutex)	= &pool->workers[number].last_comp_time_mutex;
+		CTX(last_comp_time)			= &pool->workers[number].last_comp_time;
 
-		pool->workers[number].ctx.free_workers_mutex = &pool->free_workers_mutex;
-		pool->workers[number].ctx.free_workers = &pool->free_workers;
-		pool->workers[number].ctx.free_workers_cond = &pool->free_workers_cond;
+		CTX(has_job_mutex)	= &pool->workers[number].has_job_mutex;
+		CTX(has_job)		= &pool->workers[number].has_job;
+		CTX(job_failed)		= &pool->workers[number].job_failed;
+		CTX(job_start_time)	= &pool->workers[number].job_start_time;
+		CTX(has_job_cond)	= &pool->workers[number].has_job_cond;
+
+		CTX(free_workers_mutex)	= &pool->free_workers_mutex;
+		CTX(free_workers)		= &pool->free_workers;
+		CTX(free_workers_cond)	= &pool->free_workers_cond;
+
+#	undef CTX
 
 		A_PTHREAD_CREATE(&pool->workers[number].tid, _stream_worker_thread, (void *)&pool->workers[number].ctx);
 	}
@@ -404,11 +415,6 @@ static void *_stream_worker_thread(void *v_ctx) {
 		A_PTHREAD_M_UNLOCK(ctx->has_job_mutex);
 
 		if (!*ctx->workers_stop) {
-			long double start_time;
-			long double last_comp_time;
-
-			start_time = now_ms_ld();
-
 			LOG_DEBUG("Worker %u compressing JPEG from buffer %d ...", ctx->number, ctx->buf_index);
 
 			if (encoder_compress_buffer(ctx->encoder, ctx->dev, ctx->buf_index) < 0) {
@@ -416,10 +422,10 @@ static void *_stream_worker_thread(void *v_ctx) {
 			}
 
 			if (_stream_release_buffer(ctx->dev, &ctx->buf_info) == 0) {
-				*ctx->job_start_time = start_time;
+				*ctx->job_start_time = ctx->dev->run->pictures[ctx->buf_index].encode_begin_time;
 				*ctx->has_job = false;
 
-				last_comp_time = now_ms_ld() - start_time;
+				long double last_comp_time = ctx->dev->run->pictures[ctx->buf_index].encode_end_time - *ctx->job_start_time;
 
 				A_PTHREAD_M_LOCK(ctx->last_comp_time_mutex);
 				*ctx->last_comp_time = last_comp_time;

src/tools.h

@@ -61,10 +61,10 @@ INLINE unsigned max_u(unsigned a, unsigned b) {
 	return (a > b ? a : b);
 }
 
-INLINE void now_ms(time_t *sec, long *msec) {
+INLINE void now_ms(clockid_t clk_id, time_t *sec, long *msec) {
 	struct timespec spec;
 
-	assert(!clock_gettime(CLOCK_MONOTONIC_RAW, &spec));
+	assert(!clock_gettime(clk_id, &spec));
 	*sec = spec.tv_sec;
 	*msec = round(spec.tv_nsec / 1.0e6);
 
@@ -74,10 +74,18 @@ INLINE void now_ms(time_t *sec, long *msec) {
 	}
 }
 
-INLINE long double now_ms_ld(void) {
+INLINE long double now_monotonic_ms(void) {
 	time_t sec;
 	long msec;
 
-	now_ms(&sec, &msec);
+	now_ms(CLOCK_MONOTONIC_RAW, &sec, &msec);
+	return (long double)sec + ((long double)msec) / 1000;
+}
+
+INLINE long double now_real_ms(void) {
+	time_t sec;
+	long msec;
+
+	now_ms(CLOCK_REALTIME, &sec, &msec);
 	return (long double)sec + ((long double)msec) / 1000;
 }