Merge in

 * bradley's benchmarking changes, and
 * the big speedup in the sort-and-write-rows (slowness caused the lock in fidx2file).
Refs #2571. [t:2571]
{{{
svn merge -r 19909:20027 https://svn.tokutek.com/tokudb/toku/tokudb.2571
}}}
.


git-svn-id: file:///svn/toku/tokudb@20029 c7de825b-a66e-492c-adef-691d508d4ae1

newbrt/Makefile

@@ -103,6 +103,7 @@ endif
 
 NEWBRT_O_FILES += brtloader.$(OEXT)
 
+brtloader.$(OEXT): $(DEPEND_COMPILE)
 ifeq ($(BRTLOADER),cilk)
 brtloader.$(OEXT): brtloader.c
 	$(CILKPP) -DTOKU_ALLOW_DEPRECATED $(CILKFLAGS) -c $< 

newbrt/brtloader-internal.h

@@ -37,6 +37,7 @@ typedef struct fidx { int idx; } FIDX;
 static const FIDX FIDX_NULL __attribute__((__unused__)) = {-1};
 static int fidx_is_null (const FIDX f) __attribute__((__unused__));
 static int fidx_is_null (const FIDX f) { return f.idx==-1; }
+FILE *toku_bl_fidx2file (BRTLOADER bl, FIDX i);
 
 int brtloader_open_temp_file (BRTLOADER bl, FIDX*file_idx);
 
@@ -56,7 +57,7 @@ int init_rowset (struct rowset *rows);
 void destroy_rowset (struct rowset *rows);
 void add_row (struct rowset *rows, DBT *key, DBT *val);
 
-int loader_write_row(DBT *key, DBT *val, FIDX data, u_int64_t *dataoff, BRTLOADER bl);
+int loader_write_row(DBT *key, DBT *val, FIDX data, FILE*, u_int64_t *dataoff, BRTLOADER bl);
 int loader_read_row (FIDX f, DBT *key, DBT *val, BRTLOADER bl);
 
 struct merge_fileset {
@@ -183,7 +184,7 @@ int merge_files (struct merge_fileset *fs, BRTLOADER bl, int which_db, DB *dest_
 #if defined(__cilkplusplus)
 extern "Cilk++" {
 #endif
-int sort_and_write_rows (struct rowset *rows, struct merge_fileset *fs, BRTLOADER bl, int which_db, DB *dest_db, brt_compare_func,
+int sort_and_write_rows (struct rowset rows, struct merge_fileset *fs, BRTLOADER bl, int which_db, DB *dest_db, brt_compare_func,
 			 int progress_allocation);
 
 int mergesort_row_array (struct row rows[/*n*/], int n, int which_db, DB *dest_db, brt_compare_func, BRTLOADER, struct rowset *);

newbrt/tests/brtloader-test.c

@@ -185,7 +185,7 @@ static void test_read_write_rows (char *template) {
     for (int i=0; i<3; i++) {
 	DBT key = {.size=strlen(keystrings[i]), .data=keystrings[i]};
 	DBT val = {.size=strlen(valstrings[i]), .data=valstrings[i]};
-	r = loader_write_row(&key, &val, file, &dataoff, &bl);
+	r = loader_write_row(&key, &val, file, toku_bl_fidx2file(&bl, file), &dataoff, &bl);
 	CKERR(r);
 	actual_size+=key.size + val.size + 8;
     }

newbrt/trace_mem.c

@@ -9,6 +9,54 @@
 #include "rdtsc.h"
 #include "trace_mem.h"
 
+#if BL_DO_TRACE && BL_SIMPLE_TRACE
+
+static double saved_scale_factor = 1e-9; // approximate until we get the actual scale factor
+static unsigned long long first_time = 0;
+static __thread unsigned long long prev_time = 0;
+static unsigned long long trace_hist[BLT_LIMIT];
+
+unsigned long long bl_trace (const BL_TRACE_ENUM l, const int quiet) {
+    assert(l<BLT_LIMIT);
+    unsigned long long t = rdtsc();
+    if (first_time==0) {
+	first_time = t;
+    }
+    if (prev_time != 0) {
+	unsigned long long diff = t-prev_time;
+	if (l==blt_calibrate_done) {
+	    saved_scale_factor = 1/(double)diff;
+	}
+	if (!quiet)
+	    printf("-> %30s %21llu %21llu %13.6fs\n", blt_to_string(l), trace_hist[l], t, (t-first_time)*saved_scale_factor);
+	trace_hist[l] += diff;
+    }
+    prev_time = t;
+    return t;
+}
+
+bl_time_t bl_time_now(void) {
+    return rdtsc();
+}
+double bl_time_diff(const bl_time_t a, const bl_time_t b) {
+    return (a-b)*saved_scale_factor;
+}
+
+
+void bl_trace_end(void) {
+    double scale_factor = trace_hist[blt_calibrate_done];
+    unsigned long long total = 0;
+    for (BL_TRACE_ENUM i=0; i<BLT_LIMIT; i++) {
+	total+=trace_hist[i];
+    }
+    for (BL_TRACE_ENUM i=0; i<BLT_LIMIT; i++) {
+	printf("%25s %20lld %8.3fs %5.1f%%\n", blt_to_string(i), trace_hist[i], trace_hist[i]/scale_factor, 100.0*trace_hist[i]/(double)total);
+    }
+}
+
+
+#elif BL_DO_TRACE && !BL_SIMPLE_TRACE
+
 // customize this as required
 #define NTRACE 0
 #if NTRACE
@@ -94,6 +142,7 @@ void bl_trace(const char *func __attribute__((unused)),
 
 void bl_trace_end(void)
 {
+#error
 #if BL_DO_TRACE
     char bltracefile[128];
     sprintf(bltracefile, "brtloader_%d.trace", toku_os_getpid());;
@@ -113,3 +162,4 @@ void bl_trace_end(void)
 #endif
 }
 
+#endif

newbrt/trace_mem.h

@@ -9,6 +9,17 @@
 extern "C" {
 #endif
 
+// Define this even when traces are compiled out so we don't have to recompile things like scanscan.c
+// print the trace
+void toku_print_trace_mem(void) __attribute__((__visibility__("default")));
+
+#define BL_DO_TRACE 1
+// BL_SIMPLE_TRACE 1 is Bradley's in-memory trace analysis.
+// BL_SIMPLE_TRACE 0 is Dave's post-processing analysis.
+#define BL_SIMPLE_TRACE 1
+#define BL_TRACE_PRINT 0
+
+#if BL_DO_TRACE && !BL_SIMPLE_TRACE
 // a circular log of trace entries is maintained in memory. the trace
 // entry consists of a string pointer, an integer, and the processor
 // timestamp. there are functions to add an entry to the end of the
@@ -22,9 +33,6 @@ extern "C" {
 // pointer, a number, and the processor timestamp
 void toku_add_trace_mem(const char *str, int n) __attribute__((__visibility__("default")));
 
-// print the trace
-void toku_print_trace_mem(void) __attribute__((__visibility__("default")));
-
 //  some trace functions added for the bulk loader
 void bl_trace(const char *func __attribute__((unused)), 
               int         line __attribute__ ((unused)), 
@@ -32,15 +40,94 @@ void bl_trace(const char *func __attribute__((unused)),
     __attribute__((unused));
 void bl_trace_end(void) __attribute__((unused));
 
-#define BL_DO_TRACE 0
-#define BL_TRACE_PRINT 0
-
-#if BL_DO_TRACE    
-#define BL_TRACE(str) bl_trace(__FUNCTION__, __LINE__, str)
+#define BL_TRACE(sym) bl_trace(__FUNCTION__, __LINE__, #sym)
 #define BL_TRACE_END bl_trace_end()
+
+#elif BL_DO_TRACE && BL_SIMPLE_TRACE
+
+
+typedef enum bl_trace_enum {BLT_START,
+
+			    blt_calibrate_begin,
+			    blt_calibrate_done,
+
+			    blt_open,
+
+			    // Time spent in the extractor
+			    blt_extractor_init,
+			    blt_extractor,
+			    blt_extract_deq,
+			    blt_sort_and_write_rows,
+
+			    // Time spent by the main thread in parallel to the extractor
+			    blt_do_put,
+			    blt_extract_enq,
+			    blt_join_on_extractor,
+
+			    // Time spent in the fractal thread
+			    blt_fractal_thread,
+			    blt_fractal_deq,
+
+			    // Time spent by the main thread in parallel to the fractal thread
+			    blt_start_fractal_thread,
+			    blt_do_i,
+			    blt_read_row,
+			    blt_fractal_enq,
+			    blt_join_on_fractal,
+			    blt_close,
+
+			    //
+			    BLT_LIMIT}
+    BL_TRACE_ENUM;
+static const char * blt_to_string (BL_TRACE_ENUM) __attribute__((__unused__));
+#define BLSCASE(s) case s: return #s
+static const char * blt_to_string (BL_TRACE_ENUM i) {
+    switch(i) {
+	BLSCASE(BLT_START);
+	BLSCASE(blt_calibrate_begin);
+	BLSCASE(blt_calibrate_done);
+	BLSCASE(blt_close);
+	BLSCASE(blt_do_i);
+	BLSCASE(blt_do_put);
+	BLSCASE(blt_extract_deq);
+	BLSCASE(blt_extract_enq);
+	BLSCASE(blt_extractor);
+	BLSCASE(blt_extractor_init);
+	BLSCASE(blt_fractal_deq);
+	BLSCASE(blt_fractal_enq);
+	BLSCASE(blt_fractal_thread);
+	BLSCASE(blt_join_on_extractor);
+	BLSCASE(blt_join_on_fractal);
+	BLSCASE(blt_open);
+	BLSCASE(blt_read_row);
+	BLSCASE(blt_sort_and_write_rows);
+	BLSCASE(blt_start_fractal_thread);
+	BLSCASE(BLT_LIMIT);
+    }
+    return NULL;
+}
+typedef unsigned long long bl_time_t;
+bl_time_t bl_trace(const BL_TRACE_ENUM, const int quiet);
+bl_time_t bl_time_now(void);
+double bl_time_diff(const bl_time_t a, const bl_time_t b);
+void bl_trace_end(void);
+
+ #define BL_TRACE(sym) bl_trace(sym, 0)
+ #if 0
+  #define BL_TRACE_QUIET(sym) bl_trace(sym, 1)
+ #else
+  #define BL_TRACE_QUIET(sym)
+ #endif
+ #define BL_TRACE_END bl_trace_end()
+
 #else
-#define BL_TRACE(str)
+
+#define BL_TRACE(sym)
+#define BL_TRACE_FROM(sym,q,t)
+#define BL_TRACE_QUIET(sym)
+#define BL_TRACE_FROM_QUIET(sym,q,t)
 #define BL_TRACE_END
+
 #endif
 
 #if defined(__cplusplus) || defined(__cilkplusplus)

src/tests/loader-stress-test.c

@@ -257,9 +257,9 @@ static void test_loader(DB **dbs)
     poll_count=0;
 
     // close the loader
-    printf("%9.6fs closing", elapsed_time()); fflush(stdout);
+    printf("%9.6fs closing\n", elapsed_time());
     r = loader->close(loader);
-    printf(" done\n");
+    printf("%9.6fs done\n",    elapsed_time());
     CKERR2s(r,0,TOKUDB_CANCELED);
 
     if (r==0) {