Merge pull request #192 from elboulangero/mr/extract-time-stats

casync extract: Add time statistics

Author: poettering

src/cadecoder.c

@@ -29,6 +29,7 @@
 #include "reflink.h"
 #include "rm-rf.h"
 #include "siphash24.h"
+#include "time-util.h"
 #include "util.h"
 
 /* #undef EINVAL */

src/caencoder.c

@@ -39,6 +39,7 @@
 #include "quota-projid.h"
 #include "realloc-buffer.h"
 #include "siphash24.h"
+#include "time-util.h"
 #include "util.h"
 
 /* #undef EINVAL */

src/cafuse.c

@@ -11,6 +11,7 @@
 #include "cafuse.h"
 #include "notify.h"
 #include "signal-handler.h"
+#include "time-util.h"
 #include "util.h"
 
 static CaSync *instance = NULL;

src/calocation.c

@@ -6,6 +6,7 @@
 #include <sys/stat.h>
 
 #include "calocation.h"
+#include "time-util.h"
 #include "util.h"
 #include "realloc-buffer.h"
 

src/canbd.c

@@ -16,6 +16,7 @@
 #include <unistd.h>
 
 #include "canbd.h"
+#include "time-util.h"
 #include "util.h"
 
 #define NBD_MAX 1024

src/caremote.c

@@ -15,6 +15,7 @@
 #include "def.h"
 #include "realloc-buffer.h"
 #include "rm-rf.h"
+#include "time-util.h"
 #include "util.h"
 
 /* #undef EBADMSG */

src/caseed.c

@@ -14,6 +14,7 @@
 #include "def.h"
 #include "realloc-buffer.h"
 #include "rm-rf.h"
+#include "time-util.h"
 #include "util.h"
 
 /* #undef EINVAL */
@@ -48,6 +49,9 @@ struct CaSeed {
 
         uint64_t n_requests;
         uint64_t n_request_bytes;
+
+        uint64_t first_step_nsec;
+        uint64_t last_step_nsec;
 };
 
 CaSeed *ca_seed_new(void) {
@@ -471,10 +475,16 @@ int ca_seed_step(CaSeed *s) {
                 return -EALREADY;
 
         if (!s->cache_chunks && !s->cache_hardlink) {
+                if (s->last_step_nsec == 0)
+                        s->last_step_nsec = now(CLOCK_MONOTONIC);
+
                 s->ready = true;
                 return CA_SEED_READY;
         }
 
+        if (s->first_step_nsec == 0)
+                s->first_step_nsec = now(CLOCK_MONOTONIC);
+
         r = ca_seed_open(s);
         if (r < 0)
                 return r;
@@ -494,6 +504,9 @@ int ca_seed_step(CaSeed *s) {
                         if (r < 0)
                                 return r;
 
+                        if (s->last_step_nsec == 0)
+                                s->last_step_nsec = now(CLOCK_MONOTONIC);
+
                         s->ready = true;
                         return CA_SEED_READY;
 
@@ -925,3 +938,21 @@ int ca_seed_get_request_bytes(CaSeed *s, uint64_t *ret) {
         *ret = s->n_request_bytes;
         return 0;
 }
+
+int ca_seed_get_seeding_time_nsec(CaSeed *s, uint64_t *ret) {
+        if (!s)
+                return -EINVAL;
+        if (!ret)
+                return -EINVAL;
+
+        if (!s->cache_chunks)
+                return -ENOTTY;
+
+        if (s->first_step_nsec == 0 || s->last_step_nsec == 0)
+                return -ENODATA;
+        if (s->first_step_nsec > s->last_step_nsec)
+                return -ENODATA;
+
+        *ret = s->last_step_nsec - s->first_step_nsec;
+        return 0;
+}

src/caseed.h

@@ -47,5 +47,6 @@ int ca_seed_get_file_root(CaSeed *s, CaFileRoot **ret);
 
 int ca_seed_get_requests(CaSeed *s, uint64_t *ret);
 int ca_seed_get_request_bytes(CaSeed *s, uint64_t *ret);
+int ca_seed_get_seeding_time_nsec(CaSeed *s, uint64_t *ret);
 
 #endif

src/casync-tool.c

@@ -28,6 +28,7 @@
 #include "notify.h"
 #include "parse-util.h"
 #include "signal-handler.h"
+#include "time-util.h"
 #include "util.h"
 
 #if HAVE_UDEV
@@ -997,6 +998,7 @@ static int verbose_print_done_extract(CaSync *s) {
         uint64_t n_local_requests = UINT64_MAX, n_seed_requests = UINT64_MAX, n_remote_requests = UINT64_MAX;
         uint64_t n_local_bytes = UINT64_MAX, n_seed_bytes = UINT64_MAX, n_remote_bytes = UINT64_MAX;
         uint64_t total_requests = 0, total_bytes = 0;
+        uint64_t nsec = 0, runtime_nsec = 0;
         int r;
 
         if (!arg_verbose)
@@ -1105,6 +1107,34 @@ static int verbose_print_done_extract(CaSync *s) {
                          format_bytes(buffer, sizeof(buffer), n_remote_bytes),
                          total_bytes > 0 ? n_remote_bytes * 100U / total_bytes : 0);
 
+        r = ca_sync_get_runtime_nsec(s, &runtime_nsec);
+        if (!IN_SET(r, -ENODATA)) {
+                if (r < 0)
+                        return log_error_errno(r, "Failed to determine runtime: %m");
+        }
+
+        r = ca_sync_get_seed_seeding_time_nsec(s, &nsec);
+        if (!IN_SET(r, -ENODATA, -ENOTTY)) {
+                if (r < 0)
+                        return log_error_errno(r, "Failed to determine seeding time: %m");
+
+                log_info("Time spent seeding: %s (%" PRIu64 "%%)",
+                         format_timespan(buffer, sizeof(buffer), nsec, NSEC_PER_MSEC),
+                         runtime_nsec > 0 ? nsec * 100U / runtime_nsec : 0);
+        }
+
+        r = ca_sync_get_decoding_time_nsec(s, &nsec);
+        if (!IN_SET(r, -ENODATA, -ENOTTY)) {
+                if (r < 0)
+                        return log_error_errno(r, "Failed to determine decoding time: %m");
+
+                log_info("Time spent decoding: %s (%" PRIu64 "%%)",
+                         format_timespan(buffer, sizeof(buffer), nsec, NSEC_PER_MSEC),
+                         runtime_nsec > 0 ? nsec * 100U / runtime_nsec : 0);
+         }
+
+        log_info("Total extract time: %s", format_timespan(buffer, sizeof(buffer), runtime_nsec, NSEC_PER_MSEC));
+
         return 1;
 }
 

src/casync.c

@@ -19,6 +19,7 @@
 #include "casync.h"
 #include "def.h"
 #include "realloc-buffer.h"
+#include "time-util.h"
 #include "util.h"
 
 /* #undef EINVAL */
@@ -47,7 +48,7 @@ typedef enum CaCacheState {
 
 struct CaSync {
         CaDirection direction;
-        bool started;
+        uint64_t start_nsec;
 
         CaEncoder *encoder;
         CaDecoder *decoder;
@@ -148,8 +149,13 @@ struct CaSync {
         uint64_t chunk_size_max;
 
         CaCompressionType compression_type;
+
+        uint64_t first_chunk_request_nsec;
+        uint64_t last_chunk_request_nsec;
 };
 
+#define CA_SYNC_IS_STARTED(s) ((s)->start_nsec != 0)
+
 static CaSync *ca_sync_new(void) {
         CaSync *s;
 
@@ -1281,7 +1287,7 @@ static int ca_sync_start(CaSync *s) {
 
         assert(s);
 
-        if (s->started)
+        if (CA_SYNC_IS_STARTED(s))
                 return 0;
 
         if (s->direction == CA_SYNC_ENCODE && s->archive_path && s->archive_fd < 0) {
@@ -1587,7 +1593,7 @@ static int ca_sync_start(CaSync *s) {
         }
 
         s->cache_state = ca_sync_use_cache(s) ? CA_SYNC_CACHE_CHECK : CA_SYNC_CACHE_OFF;
-        s->started = true;
+        s->start_nsec = now(CLOCK_MONOTONIC);
 
         return 1;
 }
@@ -2327,6 +2333,9 @@ static int ca_sync_process_decoder_request(CaSync *s) {
                                 if (r < 0)
                                         return log_debug_errno(r, "Failed to put decoder EOF: %m");
 
+                                if (s->last_chunk_request_nsec == 0)
+                                        s->last_chunk_request_nsec = now(CLOCK_MONOTONIC);
+
                                 return CA_SYNC_STEP;
                         }
 
@@ -2345,6 +2354,9 @@ static int ca_sync_process_decoder_request(CaSync *s) {
                 if (!ca_sync_seed_ready(s))
                         return CA_SYNC_POLL;
 
+                if (s->first_chunk_request_nsec == 0)
+                        s->first_chunk_request_nsec = now(CLOCK_MONOTONIC);
+
                 r = ca_sync_get(s, &s->next_chunk, CA_CHUNK_UNCOMPRESSED, &p, &chunk_size, NULL, &origin);
                 if (r == -EAGAIN) /* Don't have this right now, but requested it now */
                         return CA_SYNC_STEP;
@@ -4252,6 +4264,31 @@ int ca_sync_get_seed_request_bytes(CaSync *s, uint64_t *ret) {
         return 0;
 }
 
+int ca_sync_get_seed_seeding_time_nsec(CaSync *s, uint64_t *ret) {
+        uint64_t sum = 0;
+        size_t i;
+        int r;
+
+        if (!s)
+                return -EINVAL;
+        if (!ret)
+                return -EINVAL;
+
+        /* We can sum seeding times since seeds are processed one after another */
+        for (i = 0; i < s->n_seeds; i++) {
+                uint64_t x;
+
+                r = ca_seed_get_seeding_time_nsec(s->seeds[i], &x);
+                if (r < 0)
+                        return r;
+
+                sum += x;
+        }
+
+        *ret = sum;
+        return 0;
+}
+
 int ca_sync_get_local_requests(CaSync *s, uint64_t *ret) {
         uint64_t sum;
         size_t i;
@@ -4376,14 +4413,42 @@ int ca_sync_get_remote_request_bytes(CaSync *s, uint64_t *ret) {
         return 0;
 }
 
+int ca_sync_get_decoding_time_nsec(CaSync *s, uint64_t *ret) {
+        if (!s)
+                return -EINVAL;
+        if (!ret)
+                return -EINVAL;
+
+        if (s->first_chunk_request_nsec == 0 || s->last_chunk_request_nsec == 0)
+                return -ENODATA;
+        if (s->first_chunk_request_nsec > s->last_chunk_request_nsec)
+                return -ENODATA;
+
+        *ret = s->last_chunk_request_nsec - s->first_chunk_request_nsec;
+        return 0;
+}
+
+int ca_sync_get_runtime_nsec(CaSync *s, uint64_t *ret) {
+        if (!s)
+                return -EINVAL;
+        if (!ret)
+                return -EINVAL;
+
+        if (s->start_nsec == 0)
+                return -ENODATA;
+
+        *ret = now(CLOCK_MONOTONIC) - s->start_nsec;
+        return 0;
+}
+
 int ca_sync_set_compression_type(CaSync *s, CaCompressionType compression) {
         if (!s)
                 return -EINVAL;
         if (compression < 0)
                 return -EINVAL;
         if (compression >= _CA_COMPRESSION_TYPE_MAX)
                 return -EOPNOTSUPP;
-        if (s->started)
+        if (CA_SYNC_IS_STARTED(s))
                 return -EBUSY;
 
         s->compression_type = compression;