From 46a950f9f99ec255236ba8e739d21ff0198620ac Mon Sep 17 00:00:00 2001 From: Mikael Ronstrom Date: Wed, 22 Sep 2010 11:14:13 +0200 Subject: [PATCH] Added intermediate-result-timer, also fixed more proper timing to avoid thread variations to impact result too much --- sysbench/sb_timer.c | 23 +++++++++++++ sysbench/sb_timer.h | 1 + sysbench/sysbench.c | 63 ++++++++++++++++++++++++++++++----- sysbench/sysbench.h | 5 ++- sysbench/tests/oltp/sb_oltp.c | 26 +++++++++++++-- 5 files changed, 106 insertions(+), 12 deletions(-) diff --git a/sysbench/sb_timer.c b/sysbench/sb_timer.c index 85dea13..d72b52d 100644 --- a/sysbench/sb_timer.c +++ b/sysbench/sb_timer.c @@ -59,6 +59,7 @@ void sb_timer_start(sb_timer_t *t) } SB_GETTIME(&t->time_start); + t->time_last_intermediate = t->time_start; t->state = TIMER_RUNNING; } @@ -130,6 +131,28 @@ unsigned long long sb_timer_current(sb_timer_t *t) (time_end.tv_nsec - t->time_start.tv_nsec); } +/* get current time without stopping timer AND update structure */ +void sb_timer_intermediate(sb_timer_t *t) +{ + switch (t->state) { + case TIMER_INITIALIZED: + log_text(LOG_WARNING, "timer was never started"); + break; + case TIMER_STOPPED: + log_text(LOG_WARNING, "timer was already stopped"); + break; + case TIMER_RUNNING: + break; + default: + log_text(LOG_FATAL, "uninitialized timer stopped"); + abort(); + } + + SB_GETTIME(&t->time_end); + t->my_time = SEC2NS(t->time_end.tv_sec - t->time_last_intermediate.tv_sec) + + (t->time_end.tv_nsec - t->time_last_intermediate.tv_nsec); + t->time_last_intermediate = t->time_end; +} /* get average time per event */ diff --git a/sysbench/sb_timer.h b/sysbench/sb_timer.h index 3d4e1c2..d29d4a9 100644 --- a/sysbench/sb_timer.h +++ b/sysbench/sb_timer.h @@ -66,6 +66,7 @@ typedef struct { struct timespec time_start; struct timespec time_end; + struct timespec time_last_intermediate; unsigned long long my_time; unsigned long long min_time; unsigned long long max_time; diff --git a/sysbench/sysbench.c b/sysbench/sysbench.c index 15458fd..1e68143 100644 --- a/sysbench/sysbench.c +++ b/sysbench/sysbench.c @@ -88,6 +88,8 @@ sb_arg_t general_args[] = {"tx-rate", "target transaction rate (tps)", SB_ARG_TYPE_INT, "0"}, {"tx-jitter", "target transaction variation, in microseconds", SB_ARG_TYPE_INT, "0"}, + {"intermediate-result-timer", "intermediate result timer, 0 is off", + SB_ARG_TYPE_INT, "0"}, {"test", "test to run", SB_ARG_TYPE_STRING, NULL}, {"debug", "print more debugging info", SB_ARG_TYPE_FLAG, "off"}, {"validate", "perform validation checks where possible", SB_ARG_TYPE_FLAG, "off"}, @@ -121,11 +123,17 @@ static void sigalrm_handler(int sig) { if (sig == SIGALRM) { - sb_timer_stop(&sb_globals.exec_timer); + pthread_mutex_lock(&thread_start_mutex); + if (!sb_globals.stopped) + { + sb_globals.stopped = 1; + sb_timer_stop(&sb_globals.exec_timer); + } + pthread_mutex_unlock(&thread_start_mutex); log_text(LOG_FATAL, "The --max-time limit has expired, forcing shutdown..."); if (current_test && current_test->ops.print_stats) - current_test->ops.print_stats(); + current_test->ops.print_stats(0); log_done(); exit(2); } @@ -347,6 +355,12 @@ void print_run_mode(sb_test_t *test) sb_globals.tx_rate, sb_globals.tx_jitter); } + if (sb_globals.intermediate_result_timer) + { + log_text(LOG_NOTICE, "Report intermediate results every %d second", + sb_globals.intermediate_result_timer); + } + if (sb_globals.debug) log_text(LOG_NOTICE, "Debug mode enabled.\n"); @@ -418,6 +432,7 @@ void *runner_thread(void *arg) about the same time */ pthread_mutex_lock(&thread_start_mutex); + sb_globals.num_running++; pthread_mutex_unlock(&thread_start_mutex); if (sb_globals.tx_rate > 0) @@ -463,6 +478,15 @@ void *runner_thread(void *arg) if (test->ops.thread_done != NULL) test->ops.thread_done(thread_id); + + pthread_mutex_lock(&thread_start_mutex); + sb_globals.num_running--; + if (sb_globals.num_running == 0 && !sb_globals.stopped) + { + sb_globals.stopped = 1; + sb_timer_stop(&sb_globals.exec_timer); + } + pthread_mutex_unlock(&thread_start_mutex); return NULL; } @@ -477,6 +501,7 @@ int run_test(sb_test_t *test) { unsigned int i; int err; + int loop_count; /* initialize test */ if (test->ops.init != NULL && test->ops.init() != 0) @@ -493,7 +518,6 @@ int run_test(sb_test_t *test) threads[i].id = i; threads[i].test = test; } - sb_timer_start(&sb_globals.exec_timer); /* prepare test */ if (test->ops.prepare != NULL && test->ops.prepare() != 0) @@ -503,8 +527,10 @@ int run_test(sb_test_t *test) /* start mutex used for barrier */ pthread_mutex_init(&thread_start_mutex,NULL); - pthread_mutex_lock(&thread_start_mutex); - + pthread_mutex_lock(&thread_start_mutex); + sb_globals.num_running = 0; + sb_globals.stopped = 0; + /* initialize attr */ pthread_attr_init(&thread_attr); #ifdef PTHREAD_SCOPE_SYSTEM @@ -531,6 +557,8 @@ int run_test(sb_test_t *test) } } + sb_timer_start(&sb_globals.exec_timer); /* Start benchmark time */ + /* Set the alarm to force shutdown */ #ifdef HAVE_ALARM if (sb_globals.force_shutdown) @@ -541,6 +569,25 @@ int run_test(sb_test_t *test) log_text(LOG_NOTICE, "Threads started!"); + if (test->ops.print_stats != NULL && + sb_globals.intermediate_result_timer) + { + loop_count = 0; + do + { + loop_count++; + sleep(1); + if (sb_globals.num_running == 0) + break; + if (loop_count < sb_globals.intermediate_result_timer) + continue; + loop_count = 0; + /* print test-specific stats */ + sb_timer_intermediate(&sb_globals.exec_timer); + test->ops.print_stats(1); + } while(1); + } + for(i = 0; i < sb_globals.num_threads; i++) { if((err = pthread_join(threads[i].thread, NULL)) != 0) @@ -559,11 +606,9 @@ int run_test(sb_test_t *test) if (test->ops.cleanup != NULL && test->ops.cleanup() != 0) return 1; - sb_timer_stop(&sb_globals.exec_timer); - /* print test-specific stats */ if (test->ops.print_stats != NULL && !sb_globals.error) - test->ops.print_stats(); + test->ops.print_stats(0); pthread_mutex_destroy(&sb_globals.exec_mutex); @@ -673,6 +718,8 @@ int init(void) } sb_globals.tx_rate = sb_get_value_int("tx-rate"); sb_globals.tx_jitter = sb_get_value_int("tx-jitter"); + sb_globals.intermediate_result_timer = + sb_get_value_int("intermediate-result-timer"); return 0; } diff --git a/sysbench/sysbench.h b/sysbench/sysbench.h index 243e931..bac2447 100644 --- a/sysbench/sysbench.h +++ b/sysbench/sysbench.h @@ -122,7 +122,7 @@ typedef int sb_op_thread_init(int); typedef void sb_op_print_mode(void); typedef sb_request_t sb_op_get_request(int); typedef int sb_op_execute_request(sb_request_t *, int); -typedef void sb_op_print_stats(void); +typedef void sb_op_print_stats(int); typedef int sb_op_thread_done(int); typedef int sb_op_cleanup(void); typedef int sb_op_done(void); @@ -189,6 +189,9 @@ typedef struct sb_timer_t *op_timers; /* timers to measure each thread's run time */ sb_timer_t exec_timer; /* total execution timer */ unsigned int num_threads; /* number of threads to use */ + unsigned int num_running; /* number of threads currently active */ + unsigned int intermediate_result_timer; /* Intermediate result timer */ + int stopped; /* Has test been stopped yet */ unsigned int tx_rate; /* target transaction rate */ unsigned int tx_jitter; /* target transaction variation (us) */ unsigned int max_requests; /* maximum number of requests */ diff --git a/sysbench/tests/oltp/sb_oltp.c b/sysbench/tests/oltp/sb_oltp.c index 7457608..7f26336 100644 --- a/sysbench/tests/oltp/sb_oltp.c +++ b/sysbench/tests/oltp/sb_oltp.c @@ -199,7 +199,7 @@ static int oltp_init(void); static void oltp_print_mode(void); static sb_request_t oltp_get_request(int); static int oltp_execute_request(sb_request_t *, int); -static void oltp_print_stats(void); +static void oltp_print_stats(int); static db_conn_t *oltp_connect(void); static int oltp_disconnect(db_conn_t *); static int oltp_reconnect(int thread_id); @@ -247,6 +247,7 @@ static int read_ops; static int write_ops; static int other_ops; static int transactions; +static int last_transactions; static int deadlocks; static sb_timer_t *exec_timers; @@ -498,7 +499,13 @@ int oltp_cmd_prepare(void) } oltp_disconnect(con); - + + read_ops = 0; + write_ops = 0; + other_ops = 0; + transactions = last_transactions = 0; + deadlocks = 0; + return 0; error: @@ -1349,14 +1356,27 @@ int oltp_execute_request(sb_request_t *sb_req, int thread_id) } -void oltp_print_stats(void) +void oltp_print_stats(int intermediate) { double total_time; unsigned int i; sb_timer_t exec_timer; sb_timer_t fetch_timer; + int trans_per_sec; + int curr_transactions, num_transactions; total_time = NS2SEC(sb_timer_value(&sb_globals.exec_timer)); + + if (intermediate) + { + curr_transactions = transactions; + num_transactions = curr_transactions - last_transactions; + last_transactions = curr_transactions; + trans_per_sec = (int)(((double)num_transactions) / total_time); + log_text(LOG_NOTICE, "Intermediate results: %d threads, %d tps", + sb_globals.num_threads, trans_per_sec); + return; + } log_text(LOG_NOTICE, "OLTP test statistics:"); log_text(LOG_NOTICE, " queries performed:");