Cleaned up sorter timings and added a final timing statistic.

diff --git a/lib/sorter/common.h b/lib/sorter/common.h
index 504afda19090884f685cb699658c3199bb3cf790..198626899c993ee34c006b55a6298a0a01a75be0 100644 (file)
--- a/lib/sorter/common.h
+++ b/lib/sorter/common.h
@@ -61,7 +61,8 @@ struct sort_context {
   int more_keys;
 
   // Timing
-  u64 start_time;
+  timestamp_t start_time;
+  uns total_int_time, total_pre_time, total_ext_time;
 };
 
 void sorter_run(struct sort_context *ctx);

diff --git a/lib/sorter/govern.c b/lib/sorter/govern.c
index 2a8bea0b27da7330c18f7b4f65d91fadcb96bc53..087720e125e17d6adc267c5017989fa41ac4494f 100644 (file)
--- a/lib/sorter/govern.c
+++ b/lib/sorter/govern.c
@@ -19,28 +19,21 @@
 
 #define F_BSIZE(b) stk_fsize(sbuck_size(b))
 
-static u64
-sorter_clock(void)
-{
-  struct timeval tv;
-  gettimeofday(&tv, NULL);
-  return (u64)tv.tv_sec * 1000 + tv.tv_usec / 1000;
-}
-
 static void
 sorter_start_timer(struct sort_context *ctx)
 {
-  ctx->start_time = sorter_clock();
+  ctx->start_time = get_timestamp();
 }
 
 static uns
-sorter_speed(struct sort_context *ctx, u64 size)
+sorter_speed(struct sort_context *ctx, u64 size, uns *account_to)
 {
-  u64 stop_time = sorter_clock();
+  timestamp_t stop_time = get_timestamp();
   if (!size)
     return 0;
   if (stop_time <= ctx->start_time)
     return -1;
+  *account_to += stop_time - ctx->start_time;
   return (uns)((double)size / (1<<20) * 1000 / (stop_time-ctx->start_time));
 }
 
@@ -123,7 +116,7 @@ sorter_twoway(struct sort_context *ctx, struct sort_bucket *b)
       SORT_TRACE("Presorting pass (%d+%d runs, %s+%s, %dMB/s)",
                 ins[0]->runs, ins[1]->runs,
                 F_BSIZE(ins[0]), F_BSIZE(ins[1]),
-                sorter_speed(ctx, sbuck_size(ins[0]) + sbuck_size(ins[1])));
+                sorter_speed(ctx, sbuck_size(ins[0]) + sbuck_size(ins[1]), &ctx->total_pre_time));
     }
   else
     {
@@ -146,7 +139,7 @@ sorter_twoway(struct sort_context *ctx, struct sort_bucket *b)
        ASSERT(join->runs == 2);
        join->runs--;
        join_size = sbuck_size(join) - join_size;
-       SORT_TRACE("Mergesort pass %d (final run, %s, %dMB/s)", pass, stk_fsize(join_size), sorter_speed(ctx, join_size));
+       SORT_TRACE("Mergesort pass %d (final run, %s, %dMB/s)", pass, stk_fsize(join_size), sorter_speed(ctx, join_size, &ctx->total_ext_time));
        sbuck_drop(ins[0]);
        sbuck_drop(ins[1]);
        return;
@@ -158,7 +151,7 @@ sorter_twoway(struct sort_context *ctx, struct sort_bucket *b)
     SORT_TRACE("Mergesort pass %d (%d+%d runs, %s+%s, %dMB/s)", pass,
               outs[0]->runs, outs[1]->runs,
               F_BSIZE(outs[0]), F_BSIZE(outs[1]),
-              sorter_speed(ctx, sbuck_size(outs[0]) + sbuck_size(outs[1])));
+              sorter_speed(ctx, sbuck_size(outs[0]) + sbuck_size(outs[1]), &ctx->total_ext_time));
     sbuck_drop(ins[0]);
     sbuck_drop(ins[1]);
     memcpy(ins, outs, 3*sizeof(struct sort_bucket *));
@@ -218,7 +211,7 @@ sorter_radix(struct sort_context *ctx, struct sort_bucket *b, uns bits)
     }
 
   SORT_TRACE("Radix split (%d buckets, %s min, %s max, %s avg, %dMB/s)", nbuck,
-            stk_fsize(min), stk_fsize(max), stk_fsize(sum / nbuck), sorter_speed(ctx, sum));
+            stk_fsize(min), stk_fsize(max), stk_fsize(sum / nbuck), sorter_speed(ctx, sum, &ctx->total_ext_time));
   sbuck_drop(b);
 }
 
@@ -269,5 +262,7 @@ sorter_run(struct sort_context *ctx)
   sorter_free_buf(ctx);
   sbuck_write(bout);           // Force empty bucket to a file
   SORT_XTRACE(2, "Final size: %s", F_BSIZE(bout));
+  SORT_XTRACE(2, "Final timings: %.3fs external sorting, %.3fs presorting, %.3fs internal sorting",
+             ctx->total_ext_time/1000., ctx->total_pre_time/1000., ctx->total_int_time/1000.);
   ctx->out_fb = sbuck_read(bout);
 }

diff --git a/lib/sorter/s-fixint.h b/lib/sorter/s-fixint.h
index bb555fb90c3b9d1e858e688a9231ad59a6ba29a2..37d6ef223122e5739172549d4ac35f3ffa65ea5b 100644 (file)
--- a/lib/sorter/s-fixint.h
+++ b/lib/sorter/s-fixint.h
@@ -44,7 +44,10 @@ static int P(internal)(struct sort_context *ctx, struct sort_bucket *bin, struct
     return 0;
 
   SORT_XTRACE(3, "s-fixint: Sorting %u items", n);
+  timestamp_t timer;
+  init_timer(&timer);
   P(array_sort)(n, buf);
+  ctx->total_int_time += get_timer(&timer);
 
   SORT_XTRACE(3, "s-fixint: Writing");
   struct fastbuf *out = sbuck_write((n < maxkeys) ? bout_only : bout);

diff --git a/lib/sorter/s-internal.h b/lib/sorter/s-internal.h
index 45d6541b1cab15e424fa6439f961f8c4f306c98e..4b9c46f9292b4516edae5d203f0c32a4ca5cb2bb 100644 (file)
--- a/lib/sorter/s-internal.h
+++ b/lib/sorter/s-internal.h
@@ -97,7 +97,10 @@ static int P(internal)(struct sort_context *ctx, struct sort_bucket *bin, struct
 
   uns count = last_item - item_array;
   SORT_XTRACE(3, "s-internal: Sorting %u items", count);
+  timestamp_t timer;
+  init_timer(&timer);
   P(array_sort)(count, item_array);
+  ctx->total_int_time += get_timer(&timer);
 
   SORT_XTRACE(3, "s-internal: Writing");
   if (!ctx->more_keys)