From 821be2a7c4adaac95a6d9ced0706d032b21bb34e Mon Sep 17 00:00:00 2001 From: Alexey Kopytov Date: Mon, 2 Jan 2017 13:25:36 +0300 Subject: [PATCH] Timers overhaul. --- configure.ac | 2 +- sysbench/Makefile.am | 2 +- sysbench/db_driver.c | 11 +-- sysbench/sb_histogram.c | 7 +- sysbench/sb_logger.c | 55 ++--------- sysbench/sb_logger.h | 2 +- sysbench/sb_timer.c | 143 +++------------------------ sysbench/sb_timer.h | 78 ++++++++++----- sysbench/{sb_utility.h => sb_util.h} | 24 +++++ sysbench/sysbench.c | 77 +++++++++------ sysbench/sysbench.h | 9 +- sysbench/tests/fileio/sb_fileio.c | 12 +-- sysbench/tests/memory/sb_memory.c | 9 +- tests/t/opt_report_checkpoints.t | 4 +- 14 files changed, 174 insertions(+), 261 deletions(-) rename sysbench/{sb_utility.h => sb_util.h} (68%) diff --git a/configure.ac b/configure.ac index bf0d104..af4c778 100644 --- a/configure.ac +++ b/configure.ac @@ -421,7 +421,7 @@ then W_FAIL="-Werror" fi BASE_WARNINGS="-W -Wall -Wextra -Wpointer-arith -Wbad-function-cast \ - -Wstrict-prototypes -Wnested-externs -Winline -Wno-format-zero-length \ + -Wstrict-prototypes -Wnested-externs -Wno-inline -Wno-format-zero-length \ -funroll-loops ${W_FAIL}" if test "$ac_profiling" = "yes" diff --git a/sysbench/Makefile.am b/sysbench/Makefile.am index 842cec4..5bb82ef 100644 --- a/sysbench/Makefile.am +++ b/sysbench/Makefile.am @@ -48,7 +48,7 @@ sysbench_SOURCES = sysbench.c sysbench.h sb_timer.c sb_timer.h \ sb_options.c sb_options.h sb_logger.c sb_logger.h sb_list.h db_driver.h \ db_driver.c sb_histogram.c sb_histogram.h sb_rnd.c sb_rnd.h \ sb_thread.c sb_thread.h sb_barrier.c sb_barrier.h sb_global.h sb_lua.c \ -sb_lua.h lua/internal/sysbench.lua.h sb_utility.h +sb_lua.h lua/internal/sysbench.lua.h sb_util.h sysbench_LDADD = tests/fileio/libsbfileio.a tests/threads/libsbthreads.a \ tests/memory/libsbmemory.a tests/cpu/libsbcpu.a \ diff --git a/sysbench/db_driver.c b/sysbench/db_driver.c index b1f4dd6..5de7f67 100644 --- a/sysbench/db_driver.c +++ b/sysbench/db_driver.c @@ -836,13 +836,13 @@ void db_print_stats(sb_stat_t type) if (type == SB_STAT_INTERMEDIATE) { - seconds = NS2SEC(sb_timer_split(&sb_globals.exec_timer)); + seconds = NS2SEC(sb_timer_checkpoint(&sb_intermediate_timer)); const double percentile_val = sb_histogram_get_pct_intermediate(&global_histogram, sb_globals.percentile); - log_timestamp(LOG_NOTICE, &sb_globals.exec_timer, + log_timestamp(LOG_NOTICE, seconds, "threads: %d, tps: %4.2f, reads: %4.2f, writes: %4.2f, " "response time: %4.2fms (%u%%), errors: %4.2f, " "reconnects: %5.2f", @@ -858,7 +858,7 @@ void db_print_stats(sb_stat_t type) { pthread_mutex_lock(&event_queue_mutex); - log_timestamp(LOG_NOTICE, &sb_globals.exec_timer, + log_timestamp(LOG_NOTICE, seconds, "queue length: %d, concurrency: %d", sb_globals.event_queue_length, sb_globals.concurrency); @@ -878,7 +878,7 @@ void db_print_stats(sb_stat_t type) else if (type != SB_STAT_CUMULATIVE) return; - seconds = NS2SEC(sb_timer_split(&sb_globals.cumulative_timer1)); + seconds = NS2SEC(sb_timer_checkpoint(&sb_checkpoint_timer1)); log_text(LOG_NOTICE, "OLTP test statistics:"); log_text(LOG_NOTICE, " queries performed:"); @@ -1008,8 +1008,7 @@ static void db_reset_stats(void) So that intermediate stats are calculated from the current moment rather than from the previous intermediate report */ - if (sb_timer_running(&sb_globals.exec_timer)) - sb_timer_split(&sb_globals.exec_timer); + sb_timer_checkpoint(&sb_intermediate_timer); if (db_globals.debug) { diff --git a/sysbench/sb_histogram.c b/sysbench/sb_histogram.c index 3f908e4..1e06822 100644 --- a/sysbench/sb_histogram.c +++ b/sysbench/sb_histogram.c @@ -41,6 +41,9 @@ #include "ck_pr.h" #include "ck_cc.h" +#include "sb_util.h" + + /* Number of slots for current histogram array. TODO: replace this constant with some autodetection code based on the number of available cores or some such. @@ -104,9 +107,9 @@ void sb_histogram_update(sb_histogram_t *h, double value) slot = sb_rnd() % SB_HISTOGRAM_NSLOTS; i = floor((log(value) - h->range_deduct) * h->range_mult + 0.5); - if (CK_CC_UNLIKELY(i < 0)) + if (SB_UNLIKELY(i < 0)) i = 0; - else if (CK_CC_UNLIKELY(i >= (ssize_t) (h->array_size))) + else if (SB_UNLIKELY(i >= (ssize_t) (h->array_size))) i = h->array_size - 1; ck_pr_inc_64(&h->interm_slots[slot][i]); diff --git a/sysbench/sb_logger.c b/sysbench/sb_logger.c index 2001f23..bb52ea9 100644 --- a/sysbench/sb_logger.c +++ b/sysbench/sb_logger.c @@ -81,7 +81,6 @@ static int text_handler_init(void); static int text_handler_process(log_msg_t *msg); static int oper_handler_init(void); -static int oper_handler_process(log_msg_t *msg); static int oper_handler_done(void); /* Built-in log handlers */ @@ -122,7 +121,7 @@ static sb_arg_t oper_handler_args[] = static log_handler_t oper_handler = { { oper_handler_init, - &oper_handler_process, + NULL, oper_handler_done, }, oper_handler_args, @@ -303,7 +302,7 @@ void log_text(log_msg_priority_t priority, const char *fmt, ...) */ -void log_timestamp(log_msg_priority_t priority, const sb_timer_t *timer, +void log_timestamp(log_msg_priority_t priority, double seconds, const char *fmt, ...) { log_msg_t msg; @@ -315,7 +314,7 @@ void log_timestamp(log_msg_priority_t priority, const sb_timer_t *timer, maxlen = TEXT_BUFFER_SIZE; clen = 0; - n = snprintf(buf, maxlen, "[%4.0fs] ", NS2SEC(timer->elapsed)); + n = snprintf(buf, maxlen, "[%4.0fs] ", seconds); clen += n; maxlen -= n; @@ -532,42 +531,6 @@ int oper_handler_init(void) } -/* Process operation start/stop messages */ - - -int oper_handler_process(log_msg_t *msg) -{ - log_msg_oper_t *oper_msg = (log_msg_oper_t *)msg->data; - sb_timer_t *timer = &timers[oper_msg->thread_id]; - long long value; - - if (oper_msg->action == LOG_MSG_OPER_START) - { - if (sb_globals.n_checkpoints > 0) - pthread_mutex_lock(&timers_mutex); - sb_timer_start(timer); - if (sb_globals.n_checkpoints > 0) - pthread_mutex_unlock(&timers_mutex); - - return 0; - } - - if (sb_globals.n_checkpoints > 0) - pthread_mutex_lock(&timers_mutex); - - sb_timer_stop(timer); - - value = sb_timer_value(timer); - - if (sb_globals.n_checkpoints > 0) - pthread_mutex_unlock(&timers_mutex); - - if (sb_globals.percentile > 0) - sb_histogram_update(&global_histogram, NS2MS(value)); - - return 0; -} - /* Print global stats either from the last checkpoint (if used) or from the test start. @@ -597,7 +560,7 @@ int print_global_stats(void) for (i = 0; i < sb_globals.num_threads; i++) sb_timer_reset(&timers[i]); - total_time_ns = sb_timer_split(&sb_globals.cumulative_timer2); + total_time_ns = sb_timer_checkpoint(&sb_checkpoint_timer2); if (sb_globals.n_checkpoints > 0) pthread_mutex_unlock(&timers_mutex); @@ -634,13 +597,13 @@ int print_global_stats(void) for(i = 0; i < nthreads; i++) t = merge_timers(&t, &timers_copy[i]); -/* Print total statistics */ + /* Print total statistics */ log_text(LOG_NOTICE, ""); log_text(LOG_NOTICE, "General statistics:"); log_text(LOG_NOTICE, " total time: %.4fs", NS2SEC(total_time_ns)); - log_text(LOG_NOTICE, " total number of events: %lld", - t.events); + log_text(LOG_NOTICE, " total number of events: %llu", + (unsigned long long) t.events); log_text(LOG_NOTICE, " total time taken by event execution: %.4fs", NS2SEC(get_sum_time(&t))); @@ -709,11 +672,11 @@ int print_global_stats(void) for(i = 0; i < nthreads; i++) { log_text(LOG_DEBUG, " thread #%3d: min: %.4fs avg: %.4fs max: %.4fs " - "events: %lld",i, + "events: %llu",i, NS2SEC(get_min_time(&timers_copy[i])), NS2SEC(get_avg_time(&timers_copy[i])), NS2SEC(get_max_time(&timers_copy[i])), - timers_copy[i].events); + (unsigned long long) timers_copy[i].events); log_text(LOG_DEBUG, " " "total time taken by even execution: %.4fs", NS2SEC(get_sum_time(&timers_copy[i])) diff --git a/sysbench/sb_logger.h b/sysbench/sb_logger.h index 0d37dab..5b6ebb7 100644 --- a/sysbench/sb_logger.h +++ b/sysbench/sb_logger.h @@ -141,7 +141,7 @@ void log_text(log_msg_priority_t priority, const char *fmt, ...) specified timer. */ -void log_timestamp(log_msg_priority_t priority, const sb_timer_t *timer, +void log_timestamp(log_msg_priority_t priority, double seconds, const char *fmt, ...) SB_ATTRIBUTE_FORMAT(printf, 3, 4); diff --git a/sysbench/sb_timer.c b/sysbench/sb_timer.c index 00e285f..06b5efe 100644 --- a/sysbench/sb_timer.c +++ b/sysbench/sb_timer.c @@ -33,166 +33,54 @@ /* Some functions for simple time operations */ -static inline void sb_timer_update(sb_timer_t *t) -{ - SB_GETTIME(&t->time_end); - t->elapsed = TIMESPEC_DIFF(t->time_end, t->time_start) + t->queue_time; -} - /* initialize timer */ - void sb_timer_init(sb_timer_t *t) { memset(&t->time_start, 0, sizeof(struct timespec)); memset(&t->time_end, 0, sizeof(struct timespec)); - memset(&t->time_split, 0, sizeof(struct timespec)); sb_timer_reset(t); - t->state = TIMER_INITIALIZED; } - /* Reset timer counters, but leave the current state intact */ + void sb_timer_reset(sb_timer_t *t) { t->min_time = 0xffffffffffffffffULL; t->max_time = 0; t->sum_time = 0; t->events = 0; - t->elapsed = 0; t->queue_time = 0; } +/* Clone a timer */ -/* check whether the timer is initialized */ -int sb_timer_initialized(sb_timer_t *t) +void sb_timer_copy(sb_timer_t *to, sb_timer_t *from) { - return t->state != TIMER_UNINITIALIZED; + memcpy(to, from, sizeof(sb_timer_t)); } /* check whether the timer is running */ -int sb_timer_running(sb_timer_t *t) + +bool sb_timer_running(sb_timer_t *t) { - return t->state == TIMER_RUNNING; -} - -/* start timer */ - - -void sb_timer_start(sb_timer_t *t) -{ - switch (t->state) { - case TIMER_INITIALIZED: - case TIMER_STOPPED: - break; - case TIMER_RUNNING: - log_text(LOG_WARNING, "timer was already started"); - break; - default: - log_text(LOG_FATAL, "uninitialized timer started"); - abort(); - } - - SB_GETTIME(&t->time_start); - t->time_split = t->time_start; - t->state = TIMER_RUNNING; -} - - -/* stop timer */ - - -void sb_timer_stop(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_timer_update(t); - t->events++; - t->sum_time += t->elapsed; - if (t->elapsed < t->min_time) - t->min_time = t->elapsed; - if (t->elapsed > t->max_time) - t->max_time = t->elapsed; - - t->state = TIMER_STOPPED; -} - - -/* - get the current timer value in nanoseconds without affecting is state, i.e. - is safe to be used concurrently on a shared timer. -*/ - - -unsigned long long sb_timer_value(sb_timer_t *t) -{ - struct timespec ts; - - switch (t->state) { - case TIMER_INITIALIZED: - log_text(LOG_WARNING, "timer was never started"); - return 0; - case TIMER_STOPPED: - return t->elapsed; - case TIMER_RUNNING: - break; - default: - log_text(LOG_FATAL, "uninitialized timer queried"); - abort(); - } - - SB_GETTIME(&ts); - return TIMESPEC_DIFF(ts, t->time_start) + t->queue_time; + return TIMESPEC_DIFF(t->time_start, t->time_end) > 0; } /* - get time elapsed since the previous call to sb_timer_split() for the specified - timer without stopping it. The first call returns time elapsed since the - timer was started. + get time elapsed since the previous call to sb_timer_checkpoint() for the + specified timer without stopping it. The first call returns time elapsed + since the timer was started. */ -unsigned long long sb_timer_split(sb_timer_t *t) +uint64_t sb_timer_checkpoint(sb_timer_t *t) { - struct timespec tmp; - unsigned long long res; - - switch (t->state) { - case TIMER_INITIALIZED: - log_text(LOG_WARNING, "timer was never started"); - return 0; - case TIMER_STOPPED: - res = TIMESPEC_DIFF(t->time_end, t->time_split); - t->time_split = t->time_end; - if (res) - return res; - else - { - log_text(LOG_WARNING, "timer was already stopped"); - return 0; - } - case TIMER_RUNNING: - break; - default: - log_text(LOG_FATAL, "uninitialized timer queried"); - abort(); - } + struct timespec tmp; + uint64_t res; SB_GETTIME(&tmp); - t->elapsed = TIMESPEC_DIFF(tmp, t->time_start); - res = TIMESPEC_DIFF(tmp, t->time_split); - t->time_split = tmp; + res = TIMESPEC_DIFF(tmp, t->time_start); + t->time_start = tmp; return res; } @@ -245,7 +133,6 @@ sb_timer_t merge_timers(sb_timer_t *t1, sb_timer_t *t2) /* Initialize to avoid warnings */ memset(&t, 0, sizeof(sb_timer_t)); - t.elapsed = t1->elapsed + t2->elapsed; t.sum_time = t1->sum_time+t2->sum_time; t.events = t1->events+t2->events; diff --git a/sysbench/sb_timer.h b/sysbench/sb_timer.h index eeb53a1..1c7fd69 100644 --- a/sysbench/sb_timer.h +++ b/sysbench/sb_timer.h @@ -38,11 +38,14 @@ # endif #endif -#include "sb_utility.h" +#include +#include + +#include "sb_util.h" /* Convert nanoseconds to seconds and vice versa */ #define NS2SEC(nsec) ((nsec)/1000000000.) -#define SEC2NS(sec) ((sec)*1000000000ULL) +#define SEC2NS(sec) ((uint64_t)(sec) * 1000000000) /* Convert nanoseconds to milliseconds and vice versa */ #define NS2MS(nsec) ((nsec)/1000000.) @@ -72,19 +75,15 @@ typedef enum {TIMER_UNINITIALIZED, TIMER_INITIALIZED, TIMER_STOPPED, \ typedef struct { - struct timespec time_start; - struct timespec time_end; - struct timespec time_split; - unsigned long long elapsed; - unsigned long long min_time; - unsigned long long max_time; - unsigned long long sum_time; - unsigned long long events; - unsigned long long queue_time; - timer_state_t state; + struct timespec time_start; + struct timespec time_end; + uint64_t events; + uint64_t queue_time; + uint64_t min_time; + uint64_t max_time; + uint64_t sum_time; - char pad[SB_CACHELINE_PAD(sizeof(struct timespec)*3 + sizeof(long long)*6 + - sizeof(timer_state_t))]; + char pad[SB_CACHELINE_PAD(sizeof(struct timespec)*2 + sizeof(uint64_t)*5)]; } sb_timer_t; @@ -96,27 +95,54 @@ void sb_timer_init(sb_timer_t *); /* Reset timer counters, but leave the current state intact */ void sb_timer_reset(sb_timer_t *t); -/* check whether the timer is initialized */ -int sb_timer_initialized(sb_timer_t *t); - /* check whether the timer is running */ -int sb_timer_running(sb_timer_t *t); +bool sb_timer_running(sb_timer_t *t); /* start timer */ -void sb_timer_start(sb_timer_t *); +static inline void sb_timer_start(sb_timer_t *t) +{ + SB_GETTIME(&t->time_start); +} /* stop timer */ -void sb_timer_stop(sb_timer_t *); +static inline uint64_t sb_timer_stop(sb_timer_t *t) +{ + SB_GETTIME(&t->time_end); -/* get the current timer value in nanoseconds */ -unsigned long long sb_timer_value(sb_timer_t *); + uint64_t elapsed = TIMESPEC_DIFF(t->time_end, t->time_start) + t->queue_time; + + t->events++; + t->sum_time += elapsed; + + if (CK_CC_UNLIKELY(elapsed < t->min_time)) + t->min_time = elapsed; + if (CK_CC_UNLIKELY(elapsed > t->max_time)) + t->max_time = elapsed; + + return elapsed; +} /* - get time elapsed since the previos call to sb_timer_split() for the specified - timer without stopping it. The first call returns time elapsed since the - timer was started. + get the current timer value in nanoseconds without affecting is state, i.e. + is safe to be used concurrently on a shared timer. */ -unsigned long long sb_timer_split(sb_timer_t *); +static inline uint64_t sb_timer_value(sb_timer_t *t) +{ + struct timespec ts; + + SB_GETTIME(&ts); + return TIMESPEC_DIFF(ts, t->time_start) + t->queue_time; +} + +/* Clone a timer */ +void sb_timer_copy(sb_timer_t *to, sb_timer_t *from); + +/* + get time elapsed since the previous call to sb_timer_checkpoint() for the + specified timer without stopping it. The first call returns time elapsed + since the timer was started. +*/ +uint64_t sb_timer_checkpoint(sb_timer_t *t); /* get average time per event */ unsigned long long get_avg_time(sb_timer_t *); diff --git a/sysbench/sb_utility.h b/sysbench/sb_util.h similarity index 68% rename from sysbench/sb_utility.h rename to sysbench/sb_util.h index 17dfbb5..cbeff74 100644 --- a/sysbench/sb_utility.h +++ b/sysbench/sb_util.h @@ -16,6 +16,9 @@ Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA */ +#ifndef SB_UTIL_H +#define SB_UTIL_H + /* General utility macros and functions. */ @@ -25,6 +28,7 @@ #endif #include "ck_md.h" +#include "ck_cc.h" /* Calculate the smallest multiple of m that is not smaller than n, when m is a @@ -40,3 +44,23 @@ /* Calculate padding to cache line size. */ #define SB_CACHELINE_PAD(n) (SB_PAD(n, CK_MD_CACHELINE)) + +/* Minimum/maximum values */ +#ifdef __GNUC__ +# define SB_MIN(a,b) \ + ({ __typeof__ (a) _a = (a); \ + __typeof__ (b) _b = (b); \ + _a < _b ? _a : _b; }) +# define SB_MAX(a,b) \ + ({ __typeof__ (a) _a = (a); \ + __typeof__ (b) _b = (b); \ + _a > _b ? _a : _b; }) +#else +# define SB_MIN(a,b) (((a) < (b)) ? (a) : (b)) +# define SB_MAX(a,b) (((a) > (b)) ? (a) : (b)) +#endif /* __GNUC__ */ + +#define SB_LIKELY(x) CK_CC_LIKELY(x) +#define SB_UNLIKELY(x) CK_CC_UNLIKELY(x) + +#endif /* SB_UTIL_H */ diff --git a/sysbench/sysbench.c b/sysbench/sysbench.c index fbed2a9..f90e830 100644 --- a/sysbench/sysbench.c +++ b/sysbench/sysbench.c @@ -74,6 +74,8 @@ #include "sb_thread.h" #include "sb_barrier.h" +#include "ck_cc.h" + #define VERSION_STRING PACKAGE" "PACKAGE_VERSION SB_GIT_SHA /* Large prime number to generate unique random IDs */ @@ -187,6 +189,17 @@ static int report_thread_created; static int checkpoints_thread_created; static int eventgen_thread_created; +/* Time limit (--max-time) in nanoseconds */ +static uint64_t max_time_ns CK_CC_CACHELINE; + +/* Global execution timer */ +sb_timer_t sb_exec_timer CK_CC_CACHELINE; + +/* timers for intermediate/checkpoint reports */ +sb_timer_t sb_intermediate_timer CK_CC_CACHELINE; +sb_timer_t sb_checkpoint_timer1 CK_CC_CACHELINE; +sb_timer_t sb_checkpoint_timer2 CK_CC_CACHELINE; + static void print_header(void); static void print_help(void); static void print_run_mode(sb_test_t *); @@ -211,9 +224,10 @@ static void sigalrm_forced_shutdown_handler(int sig) sb_globals.forced_shutdown_in_progress = 1; - sb_timer_stop(&sb_globals.exec_timer); - sb_timer_stop(&sb_globals.cumulative_timer1); - sb_timer_stop(&sb_globals.cumulative_timer2); + sb_timer_stop(&sb_exec_timer); + sb_timer_stop(&sb_intermediate_timer); + sb_timer_stop(&sb_checkpoint_timer1); + sb_timer_stop(&sb_checkpoint_timer2); log_text(LOG_FATAL, "The --max-time limit has expired, forcing shutdown..."); @@ -454,8 +468,8 @@ sb_event_t sb_next_event(sb_test_t *test, int thread_id) return event; /* Check if we have a time limit */ - if (sb_globals.max_time != 0 && - sb_timer_value(&sb_globals.exec_timer) >= SEC2NS(sb_globals.max_time)) + if (max_time_ns > 0 && + sb_timer_value(&sb_exec_timer) >= max_time_ns) { log_text(LOG_INFO, "Time limit exceeded, exiting..."); return event; @@ -487,7 +501,7 @@ sb_event_t sb_next_event(sb_test_t *test, int thread_id) pthread_mutex_unlock(&event_queue_mutex); - timers[thread_id].queue_time = sb_timer_value(&sb_globals.exec_timer) - + timers[thread_id].queue_time = sb_timer_value(&sb_exec_timer) - queue_start_time; } @@ -520,9 +534,7 @@ void sb_event_stop(int thread_id) if (sb_globals.n_checkpoints > 0) pthread_mutex_lock(&timers_mutex); - sb_timer_stop(timer); - - value = sb_timer_value(timer); + value = sb_timer_stop(timer); if (sb_globals.n_checkpoints > 0) pthread_mutex_unlock(&timers_mutex); @@ -632,7 +644,7 @@ static void *eventgen_thread_proc(void *arg) eventgen_thread_created = 1; - curr_ns = sb_timer_value(&sb_globals.exec_timer); + curr_ns = sb_timer_value(&sb_exec_timer); /* emulate exponential distribution with Lambda = tx_rate */ intr_ns = (long) (log(1 - sb_rnd_double()) / (-(double) sb_globals.tx_rate)*1000000); @@ -640,7 +652,7 @@ static void *eventgen_thread_proc(void *arg) for (;;) { - curr_ns = sb_timer_value(&sb_globals.exec_timer); + curr_ns = sb_timer_value(&sb_exec_timer); /* emulate exponential distribution with Lambda = tx_rate */ intr_ns = (long) (log(1 - sb_rnd_double()) / @@ -654,12 +666,12 @@ static void *eventgen_thread_proc(void *arg) } else { - log_timestamp(LOG_DEBUG, &sb_globals.exec_timer, + log_timestamp(LOG_DEBUG, NS2SEC(curr_ns), "Event generation thread is too slow"); } - queue_array[i].event_time = sb_timer_value(&sb_globals.exec_timer); + queue_array[i].event_time = sb_timer_value(&sb_exec_timer); pthread_mutex_lock(&event_queue_mutex); SB_LIST_ADD_TAIL(&queue_array[i].listitem, &event_queue); sb_globals.event_queue_length++; @@ -710,7 +722,7 @@ static void *report_thread_proc(void *arg) report_thread_created = 1; pause_ns = interval_ns; - prev_ns = sb_timer_value(&sb_globals.exec_timer) + interval_ns; + prev_ns = sb_timer_value(&sb_exec_timer) + interval_ns; for (;;) { usleep(pause_ns / 1000); @@ -723,7 +735,7 @@ static void *report_thread_proc(void *arg) current_test->ops.print_stats(SB_STAT_INTERMEDIATE); pthread_mutex_unlock(&report_interval_mutex); - curr_ns = sb_timer_value(&sb_globals.exec_timer); + curr_ns = sb_timer_value(&sb_exec_timer); do { next_ns = prev_ns + interval_ns; @@ -764,20 +776,16 @@ static void *checkpoints_thread_proc(void *arg) for (i = 0; i < sb_globals.n_checkpoints; i++) { next_ns = SEC2NS(sb_globals.checkpoints[i]); - curr_ns = sb_timer_value(&sb_globals.exec_timer); + curr_ns = sb_timer_value(&sb_exec_timer); if (next_ns <= curr_ns) continue; pause_ns = next_ns - curr_ns; usleep(pause_ns / 1000); - /* - Just to update elapsed time in timer which is later used by - log_timestamp. - */ - curr_ns = sb_timer_value(&sb_globals.exec_timer); SB_THREAD_MUTEX_LOCK(); - log_timestamp(LOG_NOTICE, &sb_globals.exec_timer, "Checkpoint report:"); + log_timestamp(LOG_NOTICE, NS2SEC(sb_timer_value(&sb_exec_timer)), + "Checkpoint report:"); current_test->ops.print_stats(SB_STAT_CUMULATIVE); print_global_stats(); SB_THREAD_MUTEX_UNLOCK(); @@ -798,9 +806,10 @@ static int threads_started_callback(void *arg) sb_globals.num_running = sb_globals.num_threads; - sb_timer_start(&sb_globals.exec_timer); - sb_timer_start(&sb_globals.cumulative_timer1); - sb_timer_start(&sb_globals.cumulative_timer2); + sb_timer_start(&sb_exec_timer); + sb_timer_copy(&sb_intermediate_timer, &sb_exec_timer); + sb_timer_copy(&sb_checkpoint_timer1, &sb_exec_timer); + sb_timer_copy(&sb_checkpoint_timer2, &sb_exec_timer); return 0; } @@ -826,10 +835,11 @@ static int run_test(sb_test_t *test) /* print test mode */ print_run_mode(test); - /* initialize and start timers */ - sb_timer_init(&sb_globals.exec_timer); - sb_timer_init(&sb_globals.cumulative_timer1); - sb_timer_init(&sb_globals.cumulative_timer2); + /* initialize timers */ + sb_timer_init(&sb_exec_timer); + sb_timer_init(&sb_intermediate_timer); + sb_timer_init(&sb_checkpoint_timer1); + sb_timer_init(&sb_checkpoint_timer2); for(i = 0; i < sb_globals.num_threads; i++) { threads[i].id = i; @@ -963,9 +973,10 @@ static int run_test(sb_test_t *test) sb_globals.num_running--; } - sb_timer_stop(&sb_globals.exec_timer); - sb_timer_stop(&sb_globals.cumulative_timer1); - sb_timer_stop(&sb_globals.cumulative_timer2); + sb_timer_stop(&sb_exec_timer); + sb_timer_stop(&sb_intermediate_timer); + sb_timer_stop(&sb_checkpoint_timer1); + sb_timer_stop(&sb_checkpoint_timer2); /* Silence periodic reports if they were on */ pthread_mutex_lock(&report_interval_mutex); @@ -1064,6 +1075,8 @@ static int init(void) } sb_globals.max_requests = sb_get_value_int("max-requests"); sb_globals.max_time = sb_get_value_int("max-time"); + max_time_ns = SEC2NS(sb_globals.max_time); + if (!sb_globals.max_requests && !sb_globals.max_time) log_text(LOG_WARNING, "WARNING: Both max-requests and max-time are 0, running endless test"); diff --git a/sysbench/sysbench.h b/sysbench/sysbench.h index d1dae8d..14fac35 100644 --- a/sysbench/sysbench.h +++ b/sysbench/sysbench.h @@ -183,10 +183,6 @@ typedef struct sb_cmd_t command; /* command passed from command line */ int error; /* global error - everyone exit */ pthread_mutex_t exec_mutex; /* execution mutex */ - sb_timer_t exec_timer; /* total execution timer */ - /* timers for cumulative reports */ - sb_timer_t cumulative_timer1; - sb_timer_t cumulative_timer2; unsigned int num_threads; /* number of threads to use */ unsigned int num_running; /* number of threads currently active */ unsigned int report_interval; /* intermediate reports interval */ @@ -214,6 +210,11 @@ typedef struct extern sb_globals_t sb_globals; extern pthread_mutex_t event_queue_mutex; +/* timers for checkpoint reports */ +extern sb_timer_t sb_intermediate_timer; +extern sb_timer_t sb_checkpoint_timer1; +extern sb_timer_t sb_checkpoint_timer2; + sb_event_t sb_next_event(sb_test_t *test, int thread_id); void sb_event_start(int thread_id); void sb_event_stop(int thread_id); diff --git a/sysbench/tests/fileio/sb_fileio.c b/sysbench/tests/fileio/sb_fileio.c index 8169f84..808dc12 100644 --- a/sysbench/tests/fileio/sb_fileio.c +++ b/sysbench/tests/fileio/sb_fileio.c @@ -834,7 +834,7 @@ void file_print_stats(sb_stat_t type) { SB_THREAD_MUTEX_LOCK(); - seconds = NS2SEC(sb_timer_split(&sb_globals.exec_timer)); + seconds = NS2SEC(sb_timer_checkpoint(&sb_intermediate_timer)); diff_read = bytes_read - last_bytes_read; diff_written = bytes_written - last_bytes_written; @@ -850,7 +850,7 @@ void file_print_stats(sb_stat_t type) sb_histogram_get_pct_intermediate(&global_histogram, sb_globals.percentile); - log_timestamp(LOG_NOTICE, &sb_globals.exec_timer, + log_timestamp(LOG_NOTICE, seconds, "reads: %4.2f MiB/s writes: %4.2f MiB/s fsyncs: %4.2f/s " "latency: %4.3f ms (%uth pct.)", diff_read / megabyte / seconds, @@ -863,7 +863,7 @@ void file_print_stats(sb_stat_t type) } case SB_STAT_CUMULATIVE: - seconds = NS2SEC(sb_timer_split(&sb_globals.cumulative_timer1)); + seconds = NS2SEC(sb_timer_checkpoint(&sb_checkpoint_timer1)); log_text(LOG_NOTICE, "\n" "File operations:\n" @@ -1060,8 +1060,7 @@ int create_files(void) close(fd); } - sb_timer_stop(&t); - seconds = NS2SEC(sb_timer_value(&t)); + seconds = NS2SEC(sb_timer_stop(&t)); if (written > 0) log_text(LOG_NOTICE, "%llu bytes written in %.2f seconds (%.2f MiB/sec).", @@ -1160,8 +1159,7 @@ void clear_stats(void) So that intermediate stats are calculated from the current moment rather than from the previous intermediate report */ - if (sb_timer_initialized(&sb_globals.exec_timer)) - sb_timer_split(&sb_globals.exec_timer); + sb_timer_checkpoint(&sb_intermediate_timer); } diff --git a/sysbench/tests/memory/sb_memory.c b/sysbench/tests/memory/sb_memory.c index 502e352..5fa203c 100644 --- a/sysbench/tests/memory/sb_memory.c +++ b/sysbench/tests/memory/sb_memory.c @@ -344,9 +344,9 @@ void memory_print_stats(sb_stat_t type) switch (type) { case SB_STAT_INTERMEDIATE: SB_THREAD_MUTEX_LOCK(); - seconds = NS2SEC(sb_timer_split(&sb_globals.exec_timer)); + seconds = NS2SEC(sb_timer_checkpoint(&sb_intermediate_timer)); - log_timestamp(LOG_NOTICE, &sb_globals.exec_timer, + log_timestamp(LOG_NOTICE, seconds, "%4.2f MiB/sec,", (double)(total_bytes - last_bytes) / megabyte / seconds); last_bytes = total_bytes; @@ -355,7 +355,7 @@ void memory_print_stats(sb_stat_t type) break; case SB_STAT_CUMULATIVE: - seconds = NS2SEC(sb_timer_split(&sb_globals.cumulative_timer1)); + seconds = NS2SEC(sb_timer_checkpoint(&sb_checkpoint_timer1)); log_text(LOG_NOTICE, "Operations performed: %d (%8.2f ops/sec)\n", total_ops, total_ops / seconds); @@ -369,8 +369,7 @@ void memory_print_stats(sb_stat_t type) So that intermediate stats are calculated from the current moment rather than from the previous intermediate report */ - if (sb_timer_initialized(&sb_globals.exec_timer)) - sb_timer_split(&sb_globals.exec_timer); + sb_timer_checkpoint(&sb_intermediate_timer); break; } diff --git a/tests/t/opt_report_checkpoints.t b/tests/t/opt_report_checkpoints.t index 7fb0252..7edcf22 100644 --- a/tests/t/opt_report_checkpoints.t +++ b/tests/t/opt_report_checkpoints.t @@ -8,10 +8,10 @@ > fi $ sysbench --test=${SBTEST_SCRIPTDIR}/oltp.lua --db-driver=mysql --mysql-dry-run --max-time=3 --max-requests=0 --report-checkpoints=1,2 run | egrep '(Checkpoint report|OLTP test statistics)' - [ 0s] Checkpoint report: - OLTP test statistics: [ 1s] Checkpoint report: OLTP test statistics: + [ 2s] Checkpoint report: + OLTP test statistics: OLTP test statistics: # Run a test that does not support checkpoint reports