From a7f71d6dbf4934ce82873521dd6cb6a7b369d172 Mon Sep 17 00:00:00 2001 From: Sears Russell Date: Tue, 30 Nov 2010 18:33:22 +0000 Subject: [PATCH] add convenience macros to latency profiler; turn on pread/pwrite profiling by default --- benchmarks/bufferManager.c | 34 ++++++++++++++++++++++------------ src/stasis/io/pfile.c | 26 +++++++++++++++++++++++--- stasis/util/histogram.h | 28 ++++++++++++++++++++++++---- 3 files changed, 69 insertions(+), 19 deletions(-) diff --git a/benchmarks/bufferManager.c b/benchmarks/bufferManager.c index 6b9695f..e75807e 100644 --- a/benchmarks/bufferManager.c +++ b/benchmarks/bufferManager.c @@ -18,6 +18,7 @@ DECLARE_HISTOGRAM_64(release_hist) struct thread_arg { unsigned int seed; unsigned long long num_ops; + double write_frac; stasis_histogram_64_t * load_hist; stasis_histogram_64_t * release_hist; pageid_t page_count; @@ -49,34 +50,42 @@ void * random_op_thread(void * argp) { struct thread_arg * a = argp; struct timeval start_time; gettimeofday(&start_time,0); + int xid = Tbegin(); + + stasis_log_t * l = stasis_log(); + lsn_t lsn = l->next_available_lsn(l); + for(int i = 0; i < a->num_ops; i++) { pageid_t pid = rand_r(&a->seed) % a->page_count; + int op = (rand_r(&a->seed) < (int)(a->write_frac * (double)RAND_MAX)); - struct timeval start, stop; + struct timeval start; gettimeofday(&start,0); - double elapsed = stasis_timeval_to_double(stasis_subtract_timeval(start, start_time)); + while(a->target_ops && - elapsed < ((double)i) / (double)a->target_ops) { + elapsed < ((double)i) / (double)a->target_ops) { struct timespec ts = stasis_double_to_timespec(0.001); nanosleep(&ts, 0); gettimeofday(&start,0); elapsed = stasis_timeval_to_double(stasis_subtract_timeval(start, start_time)); } - Page * p = loadPage(-1, pid); - gettimeofday(&stop,0); - stasis_histogram_insert_log_timeval(a->load_hist, stasis_subtract_timeval(stop, start)); - - gettimeofday(&start,0); + stasis_histogram_tick(a->load_hist); + Page * p = loadPage(xid, pid); + stasis_histogram_tock(a->load_hist); + if(op) { // Do write + stasis_page_lsn_write(xid, p, lsn); + } + stasis_histogram_tick(a->release_hist); releasePage(p); - gettimeofday(&stop,0); - stasis_histogram_insert_log_timeval(a->release_hist, stasis_subtract_timeval(stop, start)); + stasis_histogram_tock(a->release_hist); } + Tcommit(xid); free(argp); return 0; } -int do_operations(pageid_t page_count, int num_threads, unsigned long long num_ops, int target_ops) { +int do_operations(pageid_t page_count, int num_threads, unsigned long long num_ops, double write_frac, int target_ops) { unsigned long long ops_per_thread = ceil(((double)num_ops) / (double)num_threads); unsigned long long ops_remaining = num_ops; pthread_t * threads = malloc(sizeof(threads[0]) * num_threads); @@ -90,6 +99,7 @@ int do_operations(pageid_t page_count, int num_threads, unsigned long long num_o struct thread_arg *a = malloc(sizeof(*a)); a->seed = base_seed + i; a->num_ops = ops_remaining < ops_per_thread ? ops_remaining : ops_per_thread; + a->write_frac = write_frac; a->load_hist = &load_hist; a->release_hist = &release_hist; a->page_count = page_count; @@ -156,7 +166,7 @@ int main(int argc, char * argv[]) { } if(num_ops) { printf("Performing %lld uniform random operations\n", num_ops); - do_operations(file_size, threads, num_ops, target_ops); + do_operations(file_size, threads, num_ops, write_frac, target_ops); } printf("Calling Tdeinit().\n"); Tdeinit(); diff --git a/src/stasis/io/pfile.c b/src/stasis/io/pfile.c index 6d4cc00..9b6dbb6 100644 --- a/src/stasis/io/pfile.c +++ b/src/stasis/io/pfile.c @@ -1,11 +1,26 @@ #include #include +#include #include #include #include +#define PFILE_LATENCY_PROF + +#ifdef PFILE_LATENCY_PROF +DECLARE_HISTOGRAM_64(read_hist) +DECLARE_HISTOGRAM_64(write_hist) +DECLARE_HISTOGRAM_64(force_hist) +DECLARE_HISTOGRAM_64(force_range_hist) +#define TICK(hist) stasis_histogram_tick(&hist) +#define TOCK(hist) stasis_histogram_tock(&hist) +#else +#define TICK(hist) +#define TOCK(hist) +#endif + /** @file @@ -105,7 +120,7 @@ inline static int pfile_write_unlocked(int fd, lsn_t off, const byte *dat, lsn_t len) { int error = 0; ssize_t bytes_written = 0; - + TICK(write_hist); while (bytes_written < len) { ssize_t count = pwrite(fd, @@ -132,6 +147,7 @@ inline static int pfile_write_unlocked(int fd, lsn_t off, const byte *dat, DEBUG("pwrite spinning\n"); } } + TOCK(write_hist); return error; } @@ -154,8 +170,8 @@ static int pfile_read(stasis_handle_t *h, lsn_t off, byte *buf, lsn_t len) { error = EDOM; } else { ssize_t bytes_read = 0; + TICK(read_hist); while (bytes_read < len) { - ssize_t count = pread(impl->fd, buf + bytes_read, len - bytes_read, @@ -182,6 +198,7 @@ static int pfile_read(stasis_handle_t *h, lsn_t off, byte *buf, lsn_t len) { DEBUG("pread spinning\n"); } } + TOCK(read_hist); assert(bytes_read == len); } return error; @@ -371,6 +388,7 @@ static int pfile_release_read_buffer(stasis_read_buffer_t *r) { return 0; } static int pfile_force(stasis_handle_t *h) { + TICK(force_hist); pfile_impl *impl = h->impl; if(!(impl->file_flags & O_SYNC)) { #ifdef HAVE_FDATASYNC @@ -387,10 +405,11 @@ static int pfile_force(stasis_handle_t *h) { int err = posix_fadvise(impl->fd, 0, 0, POSIX_FADV_DONTNEED); if(err) perror("Attempt to pass POSIX_FADV_SEQUENTIAL to kernel failed"); } - + TOCK(force_hist); return 0; } static int pfile_force_range(stasis_handle_t *h, lsn_t start, lsn_t stop) { + TICK(force_range_hist); pfile_impl * impl = h->impl; #ifdef HAVE_SYNC_FILE_RANGE if(!stop) stop = impl->end_pos; @@ -422,6 +441,7 @@ static int pfile_force_range(stasis_handle_t *h, lsn_t start, lsn_t stop) { int err = posix_fadvise(impl->fd, start-impl->start_pos, stop-start, POSIX_FADV_DONTNEED); if(err) perror("Attempt to pass POSIX_FADV_SEQUENTIAL (for a range of a file) to kernel failed"); } + TOCK(force_range_hist); return ret; } static int pfile_truncate_start(stasis_handle_t *h, lsn_t new_start) { diff --git a/stasis/util/histogram.h b/stasis/util/histogram.h index 6119152..f253ba6 100644 --- a/stasis/util/histogram.h +++ b/stasis/util/histogram.h @@ -8,15 +8,20 @@ #define HISTOGRAM_H_ #include +#include #include #include #include +/** @todo move to a .c */ +static inline void stasis_histogram_thread_destroy(void * p) { free (p); } + #define DECLARE_HISTOGRAM_64(x) \ stasis_histogram_64_t x; \ extern void stasis_histogram_ctor_##x() __attribute__((constructor)); \ void stasis_histogram_ctor_##x(void) { stasis_histogram_64_clear(&x); \ + pthread_key_create(&(x.tls), stasis_histogram_thread_destroy); \ stasis_auto_histogram_count++; \ stasis_auto_histograms = realloc(stasis_auto_histograms, sizeof(void*)*stasis_auto_histogram_count); \ stasis_auto_histogram_names = realloc(stasis_auto_histogram_names, sizeof(void*)*stasis_auto_histogram_count); \ @@ -30,6 +35,7 @@ typedef struct { uint64_t buckets[64]; + pthread_key_t tls; } stasis_histogram_64_t; extern stasis_histogram_64_t**stasis_auto_histograms; @@ -38,6 +44,7 @@ extern int stasis_auto_histogram_count; typedef struct { uint64_t buckets[32]; + pthread_key_t tls; } stasis_histogram_32_t; static inline void stasis_histogram_64_clear(stasis_histogram_64_t * hist) { @@ -57,6 +64,19 @@ static inline void stasis_histogram_insert_log_timeval(stasis_histogram_64_t* hi hist->buckets[stasis_log_2_timeval(val)]++; } +static inline void stasis_histogram_tick(stasis_histogram_64_t* hist) { + struct timeval * val = pthread_getspecific(hist->tls); + if(!val) { val = malloc(sizeof(*val)); pthread_setspecific(hist->tls, val); } + gettimeofday(val,0); +} +static inline void stasis_histogram_tock(stasis_histogram_64_t* hist) { + struct timeval * val = pthread_getspecific(hist->tls); + assert(val); + struct timeval now; + gettimeofday(&now,0); + stasis_histogram_insert_log_timeval(hist, stasis_subtract_timeval(now, *val)); +} + static inline uint64_t stasis_histogram_earth_movers_distance_64(stasis_histogram_64_t* a, stasis_histogram_64_t* b) { double moved_so_far = 0.0; double in_shovel = 0.0; @@ -88,11 +108,10 @@ static inline uint64_t stasis_histogram_earth_movers_distance_32(stasis_histogra } return moved_so_far / a_mass; } - -void stasis_histogram_pretty_print_64(stasis_histogram_64_t* a); -void stasis_histogram_pretty_print_32(stasis_histogram_32_t* a); +/** @todo move all of these to a .c */ +static inline void stasis_histogram_pretty_print_64(stasis_histogram_64_t* a); +static inline void stasis_histogram_pretty_print_32(stasis_histogram_32_t* a); void stasis_histograms_auto_dump(void); -#endif /* HISTOGRAM_H_ */ void stasis_histogram_pretty_print_64(stasis_histogram_64_t* a) { uint8_t logs[64]; @@ -144,3 +163,4 @@ void stasis_histogram_pretty_print_32(stasis_histogram_32_t* a) { } } +#endif /* HISTOGRAM_H_ */