video compress: print duration with usec precision

src/tv.h

@@ -74,6 +74,7 @@ uint32_t get_std_audio_local_mediatime(double samples, int rate);
 uint32_t get_std_video_local_mediatime(void);
 
 typedef long long time_ns_t;
+#define MS_IN_NS_DBL 1000000.0
 #define MS_IN_SEC 1000
 #define MS_IN_SEC_DBL 1000.0
 #define US_IN_SEC 1000000LL

src/types.h

@@ -294,8 +294,8 @@ struct video_frame {
                 uint32_t timecode; ///< BCD timecode (hrs, min, sec, frm num)
                 uint32_t duration;
         };
-        uint64_t compress_start; ///< in ms from epoch
-        uint64_t compress_end; ///< in ms from epoch
+        int64_t compress_start; ///< in ns from epoch
+        int64_t compress_end;   ///< in ns from epoch
         unsigned int paused_play:1;
 #define VF_METADATA_END tile_count
 

src/utils/vf_split.cpp

@@ -165,7 +165,8 @@ shared_ptr<video_frame> vf_merge_tiles(std::vector<shared_ptr<video_frame>> cons
                                 vf_free(frame);
                         });
 
-        uint64_t t0 = UINT64_MAX, t1 = 0;
+        int64_t t0 = INT64_MAX;
+        int64_t t1 = 0;
         for (unsigned int i = 0; i < tiles.size(); ++i) {
                 ret->tiles[i].data = tiles[i]->tiles[0].data;
                 ret->tiles[i].data_len = tiles[i]->tiles[0].data_len;

src/video_compress.cpp

@@ -43,6 +43,7 @@
 #include "config_win32.h"
 #endif // HAVE_CONFIG_H
 
+#include <cassert>
 #include <cinttypes>
 #include <memory>
 #include <stdio.h>
@@ -51,9 +52,9 @@
 #include <thread>
 #include <vector>
 
-#include "compat/platform_time.h"
 #include "messaging.h"
 #include "module.h"
+#include "tv.h"
 #include "utils/synchronized_queue.h"
 #include "utils/thread.h"
 #include "utils/vf_split.h"
@@ -335,8 +336,6 @@ void compress_frame(struct compress_state *proxy, shared_ptr<video_frame> frame)
         if (!proxy)
                 abort();
 
-        uint64_t t0 = time_since_epoch_in_ms();
-
         struct msg_change_compress_data *msg = NULL;
         while ((msg = (struct msg_change_compress_data *) check_message(&proxy->mod))) {
                 compress_process_message(proxy, msg);
@@ -347,12 +346,12 @@ void compress_frame(struct compress_state *proxy, shared_ptr<video_frame> frame)
         if (!frame) {
                 proxy->poisoned = true;
         }
+        if (frame) {
+                frame->compress_start = get_time_in_ns();
+        }
 
         if (s->funcs->compress_frame_async_push_func) {
                 assert(s->funcs->compress_frame_async_pop_func);
-                if (frame) {
-                        frame->compress_start = t0;
-                }
                 s->funcs->compress_frame_async_push_func(s->state[0], frame);
         } else if (s->funcs->compress_tile_async_push_func) {
                 assert(s->funcs->compress_tile_async_pop_func);
@@ -361,8 +360,6 @@ void compress_frame(struct compress_state *proxy, shared_ptr<video_frame> frame)
                         return;
                 }
 
-                frame->compress_start = t0;
-
                 if(!check_state_count(frame->tile_count, proxy)){
                         return;
                 }
@@ -396,8 +393,7 @@ void compress_frame(struct compress_state *proxy, shared_ptr<video_frame> frame)
                         return;
                 }
 
-                sync_api_frame->compress_start = t0;
-                sync_api_frame->compress_end = time_since_epoch_in_ms();
+                sync_api_frame->compress_end = get_time_in_ns();
 
                 proxy->queue.push(sync_api_frame);
         }
@@ -601,7 +597,10 @@ shared_ptr<video_frame> compress_pop(struct compress_state *proxy)
 
         auto f = proxy->queue.pop();
         if (f) {
-                log_msg(LOG_LEVEL_DEBUG, "Compressed frame size: %8u; duration: %3" PRIu64 " ms\n", vf_get_data_len(f.get()), f->compress_end - f->compress_start);
+                log_msg(LOG_LEVEL_DEBUG,
+                        "Compressed frame size: %8u; duration: %7.3f ms\n",
+                        vf_get_data_len(f.get()),
+                        (f->compress_end - f->compress_start) / MS_IN_NS_DBL);
         }
         return f;
 }

src/video_compress/cineform.cpp

@@ -46,12 +46,12 @@
 #include "config_win32.h"
 #endif // HAVE_CONFIG_H
 
-#include "compat/platform_time.h"
 #include "debug.h"
 #include "host.h"
-#include "video_compress.h"
-#include "module.h"
 #include "lib_common.h"
+#include "module.h"
+#include "tv.h"
+#include "video_compress.h"
 
 #include <CFHDTypes.h>
 #include <CFHDEncoder.h>
@@ -507,7 +507,7 @@ static std::shared_ptr<video_frame> cineform_compress_pop(struct module *state)
         }
         s->frame_queue.pop();
 
-        out->compress_end = time_since_epoch_in_ms();
+        out->compress_end = get_time_in_ns();
 
         return out;
 }

src/video_compress/gpujpeg.cpp

@@ -41,12 +41,12 @@
 #include "config_win32.h"
 #endif // HAVE_CONFIG_H
 
-#include "compat/platform_time.h"
 #include "debug.h"
 #include "host.h"
 #include "video_compress.h"
 #include "module.h"
 #include "lib_common.h"
+#include "tv.h"
 #include "utils/color_out.h"
 #include "utils/synchronized_queue.h"
 #include "utils/video_frame_pool.h"
@@ -171,7 +171,7 @@ void encoder_state::compress(shared_ptr<video_frame> frame)
                 auto out = compress_step(std::move(frame));
                 if (out) {
                         vf_restore_metadata(out.get(), vf_metadata);
-                        out->compress_end = time_since_epoch_in_ms();
+                        out->compress_end = get_time_in_ns();
                 } else {
                         log_msg(LOG_LEVEL_WARNING, MOD_NAME "Failed to encode frame!\n");
                         out = shared_ptr<video_frame>(vf_alloc(1), vf_free);