hcq/sysbench
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Timers overhaul.

Browse Source
This commit is contained in:
Alexey Kopytov
2017-01-02 13:25:36 +03:00
parent 8f5cbe3608
commit 821be2a7c4
14 changed files with 174 additions and 261 deletions
Download Patch File Download Diff File Expand all files Collapse all files

2
configure.ac
View File

@ -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"

2
sysbench/Makefile.am
View File

@ -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 \

11
sysbench/db_driver.c
View File

@ -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)
{

7
sysbench/sb_histogram.c
View File

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

55
sysbench/sb_logger.c
View File

@ -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]))

2
sysbench/sb_logger.h
View File

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

143
sysbench/sb_timer.c
View File

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

78
sysbench/sb_timer.h
View File

@ -38,11 +38,14 @@
# endif
#endif
#include "sb_utility.h"
#include <stdint.h>
#include <stdbool.h>
#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 *);

24
sysbench/sb_utility.h → sysbench/sb_util.h
View File

@ -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 */

77
sysbench/sysbench.c
View File

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

9
sysbench/sysbench.h
View File

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

12
sysbench/tests/fileio/sb_fileio.c
View File

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

9
sysbench/tests/memory/sb_memory.c
View File

@ -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;
}

4
tests/t/opt_report_checkpoints.t
View File

@ -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