add convenience macros to latency profiler; turn on pread/pwrite profiling by default

This commit is contained in:
Sears Russell 2010-11-30 18:33:22 +00:00
parent d8634edb3d
commit a7f71d6dbf
3 changed files with 69 additions and 19 deletions

View file

@ -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();

View file

@ -1,11 +1,26 @@
#include <config.h>
#include <stasis/io/handle.h>
#include <stasis/util/histogram.h>
#include <fcntl.h>
#include <stdio.h>
#include <assert.h>
#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) {

View file

@ -8,15 +8,20 @@
#define HISTOGRAM_H_
#include <stasis/common.h>
#include <assert.h>
#include <stdio.h>
#include <stasis/util/log2.h>
#include <stasis/util/time.h>
/** @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_ */