From 5d1afde9279882d7609b5c97a0628ab8bf9d4265 Mon Sep 17 00:00:00 2001
From: Martin Mares <mj@ucw.cz>
Date: Sat, 17 Feb 2007 22:18:46 +0100
Subject: [PATCH] Cleaned up sorter timings and added a final timing statistic.

---
 lib/sorter/common.h     |  3 ++-
 lib/sorter/govern.c     | 25 ++++++++++---------------
 lib/sorter/s-fixint.h   |  3 +++
 lib/sorter/s-internal.h |  3 +++
 4 files changed, 18 insertions(+), 16 deletions(-)

diff --git a/lib/sorter/common.h b/lib/sorter/common.h
index 504afda1..19862689 100644
--- 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 2a8bea0b..087720e1 100644
--- 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 bb555fb9..37d6ef22 100644
--- 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 45d6541b..4b9c46f9 100644
--- 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)
-- 
2.39.2