Bug #811105: Add an option to dump full stats after specified time

intervals.

Added a new --report-checkpoints option that allows to dump full
statistics and reset all counters at specified points in time. The
argument is a list of comma-separated values representing the amount of
time in seconds elapsed from start of test when report checkpoint(s)
must be performed. Report checkpoints are off by   Report checkpoints
are off by default.
This commit is contained in:
Alexey Kopytov
2011-07-21 17:29:08 +04:00
parent 3d52f3e5b5
commit 80df3b3500
12 changed files with 381 additions and 67 deletions

View File

@ -206,6 +206,7 @@ sys/mman.h \
sys/shm.h \
thread.h \
unistd.h \
limits.h \
])

View File

@ -85,7 +85,7 @@ typedef sb_list_item_t sb_list_t ;
((item_p)->prev_p != (head_p))
#define SB_LIST_ITEM_LAST(item_p, head_p) \
((item_p)->next_p != (head_p))
((item_p)->next_p == (head_p))
#define SB_LIST_ITEM_NEXT(item_p) \
((item_p)->next_p)

View File

@ -46,6 +46,9 @@
#define OPER_LOG_MIN_VALUE 1
#define OPER_LOG_MAX_VALUE 1E13
/* per-thread timers for response time stats */
sb_timer_t *timers;
/* Array of message handlers (one chain per message type) */
static sb_list_t handlers[LOG_MSG_TYPE_MAX];
@ -63,6 +66,15 @@ static pthread_mutex_t text_mutex;
static unsigned int text_cnt;
static char text_buf[TEXT_BUFFER_SIZE];
/* Temporary copy of timers */
static sb_timer_t *timers_copy;
/*
Mutex protecting timers.
TODO: replace with an rwlock (and implement pthread rwlocks for Windows).
*/
static pthread_mutex_t timers_mutex;
static int text_handler_init(void);
static int text_handler_process(log_msg_t *msg);
@ -472,6 +484,8 @@ int text_handler_process(log_msg_t *msg)
int oper_handler_init(void)
{
unsigned int i;
oper_percentile = sb_get_value_int("percentile");
if (oper_percentile < 1 || oper_percentile > 100)
{
@ -484,6 +498,20 @@ int oper_handler_init(void)
OPER_LOG_MAX_VALUE))
return 1;
timers = (sb_timer_t *)malloc(sb_globals.num_threads * sizeof(sb_timer_t));
timers_copy = (sb_timer_t *)malloc(sb_globals.num_threads *
sizeof(sb_timer_t));
if (timers == NULL || timers_copy == NULL)
{
log_text(LOG_FATAL, "Memory allocation failure");
return 1;
}
for (i = 0; i < sb_globals.num_threads; i++)
sb_timer_init(&timers[i]);
pthread_mutex_init(&timers_mutex, NULL);
return 0;
}
@ -494,27 +522,36 @@ int oper_handler_init(void)
int oper_handler_process(log_msg_t *msg)
{
log_msg_oper_t *oper_msg = (log_msg_oper_t *)msg->data;
sb_timer_t *timer = sb_globals.op_timers + oper_msg->thread_id;
sb_timer_t *timer = &timers[oper_msg->thread_id];
long long value;
if (oper_msg->action == LOG_MSG_OPER_START)
{
pthread_mutex_lock(&timers_mutex);
sb_timer_start(timer);
pthread_mutex_unlock(&timers_mutex);
return 0;
}
pthread_mutex_lock(&timers_mutex);
sb_timer_stop(timer);
value = sb_timer_value(timer);
pthread_mutex_unlock(&timers_mutex);
sb_percentile_update(&percentile, value);
return 0;
}
/*
Print global stats either from the last checkpoint (if used) or
from the test start.
*/
/* Uninitialize operations messages handler */
int oper_handler_done(void)
int print_global_stats(void)
{
double diff;
unsigned int i;
@ -525,23 +562,40 @@ int oper_handler_done(void)
double events_stddev;
double time_avg;
double time_stddev;
double percentile_val;
unsigned long long total_time_ns;
sb_timer_init(&t);
nthreads = sb_globals.num_threads;
for(i = 0; i < nthreads; i++)
t = merge_timers(&t,&(sb_globals.op_timers[i]));
/* Print total statistics */
/* Create a temporary copy of timers and reset them */
pthread_mutex_lock(&timers_mutex);
memcpy(timers_copy, timers, sb_globals.num_threads * sizeof(sb_timer_t));
for (i = 0; i < sb_globals.num_threads; i++)
sb_timer_reset(&timers[i]);
total_time_ns = sb_timer_split(&sb_globals.cumulative_timer2);
percentile_val = sb_percentile_calculate(&percentile, oper_percentile);
sb_percentile_reset(&percentile);
pthread_mutex_unlock(&timers_mutex);
for(i = 0; i < nthreads; i++)
t = merge_timers(&t, &timers_copy[i]);
/* Print total statistics */
log_text(LOG_NOTICE, "");
log_text(LOG_NOTICE, "Test execution summary:");
log_text(LOG_NOTICE, "General statistics:");
log_text(LOG_NOTICE, " total time: %.4fs",
NS2SEC(sb_timer_value(&sb_globals.exec_timer)));
NS2SEC(total_time_ns));
log_text(LOG_NOTICE, " total number of events: %lld",
t.events);
log_text(LOG_NOTICE, " total time taken by event execution: %.4f",
NS2SEC(get_sum_time(&t)));
log_text(LOG_NOTICE, " per-request statistics:");
log_text(LOG_NOTICE, " response time:");
log_text(LOG_NOTICE, " min: %10.2fms",
NS2MS(get_min_time(&t)));
log_text(LOG_NOTICE, " avg: %10.2fms",
@ -553,8 +607,7 @@ int oper_handler_done(void)
if (t.events > 0)
{
log_text(LOG_NOTICE, " approx. %3d percentile: %10.2fms",
oper_percentile,
NS2MS(sb_percentile_calculate(&percentile, oper_percentile)));
oper_percentile, NS2MS(percentile_val));
}
log_text(LOG_NOTICE, "");
@ -570,10 +623,10 @@ int oper_handler_done(void)
time_stddev = 0;
for(i = 0; i < nthreads; i++)
{
diff = fabs(events_avg - sb_globals.op_timers[i].events);
diff = fabs(events_avg - timers_copy[i].events);
events_stddev += diff*diff;
diff = fabs(time_avg - NS2SEC(get_sum_time(&sb_globals.op_timers[i])));
diff = fabs(time_avg - NS2SEC(get_sum_time(&timers_copy[i])));
time_stddev += diff*diff;
}
events_stddev = sqrt(events_stddev / nthreads);
@ -593,13 +646,13 @@ int oper_handler_done(void)
{
log_text(LOG_DEBUG, " thread #%3d: min: %.4fs avg: %.4fs max: %.4fs "
"events: %lld",i,
NS2SEC(get_min_time(&sb_globals.op_timers[i])),
NS2SEC(get_avg_time(&sb_globals.op_timers[i])),
NS2SEC(get_max_time(&sb_globals.op_timers[i])),
sb_globals.op_timers[i].events);
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);
log_text(LOG_DEBUG, " "
"total time taken by even execution: %.4fs",
NS2SEC(get_sum_time(&sb_globals.op_timers[i]))
NS2SEC(get_sum_time(&timers_copy[i]))
);
}
log_text(LOG_NOTICE, "");
@ -607,3 +660,17 @@ int oper_handler_done(void)
return 0;
}
/* Uninitialize operations messages handler */
int oper_handler_done(void)
{
print_global_stats();
free(timers);
free(timers_copy);
pthread_mutex_destroy(&timers_mutex);
return 0;
}

View File

@ -118,6 +118,9 @@ typedef struct {
sb_list_item_t listitem; /* can be linked in a list */
} log_handler_t;
/* per-thread timers for response time stats */
extern sb_timer_t *timers;
/* Register logger */
int log_register(void);
@ -158,4 +161,11 @@ void log_errno(log_msg_priority_t priority, const char *fmt, ...);
void log_done(void);
/*
Print global stats either from the last checkpoint (if used) or
from the test start.
*/
int print_global_stats(void);
#endif /* SB_LOGGER_H */

View File

@ -29,6 +29,10 @@
# include <ctype.h>
#endif
#ifdef HAVE_LIMITS_H
# include <limits.h>
#endif
#include "sb_options.h"
#define VALUE_DELIMITER '='
@ -177,6 +181,8 @@ int sb_get_value_int(const char *name)
option_t *opt;
value_t *val;
sb_list_item_t *pos;
long res;
char *endptr;
opt = find_option(&options, name);
if (opt == NULL)
@ -185,7 +191,14 @@ int sb_get_value_int(const char *name)
SB_LIST_FOR_EACH(pos, &opt->values)
{
val = SB_LIST_ENTRY(pos, value_t, listitem);
return atoi(val->data);
res = strtol(val->data, &endptr, 10);
if (*endptr != '\0' || res > INT_MAX || res < INT_MIN)
{
fprintf(stderr, "Invalid value for the '%s' option: '%s'\n",
name, val->data);
exit(EXIT_FAILURE);
}
return (int) res;
}
return 0;
@ -606,4 +619,3 @@ int write_config(FILE *fp, sb_list_t *options)
return 0;
}

View File

@ -34,25 +34,40 @@
static inline void sb_timer_update(sb_timer_t *t)
{
struct timespec time_end;
SB_GETTIME(&time_end);
t->elapsed = TIMESPEC_DIFF(time_end, t->time_start);
SB_GETTIME(&t->time_end);
t->elapsed = TIMESPEC_DIFF(t->time_end, t->time_start);
}
/* 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->state = TIMER_INITIALIZED;
t->elapsed = 0;
}
/* check whether the timer is initialized */
int sb_timer_initialized(sb_timer_t *t)
{
return t->state != TIMER_UNINITIALIZED;
}
/* start timer */
@ -148,8 +163,15 @@ unsigned long long sb_timer_split(sb_timer_t *t)
log_text(LOG_WARNING, "timer was never started");
return 0;
case TIMER_STOPPED:
log_text(LOG_WARNING, "timer was already stopped");
return 0;;
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:

View File

@ -69,6 +69,7 @@ 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;
@ -84,6 +85,12 @@ typedef struct
/* Initialize timer */
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);
/* start timer */
void sb_timer_start(sb_timer_t *);

View File

@ -59,6 +59,9 @@
#ifdef HAVE_SIGNAL_H
# include <signal.h>
#endif
#ifdef HAVE_LIMITS_H
# include <limits.h>
#endif
#include "sysbench.h"
#include "sb_options.h"
@ -91,6 +94,11 @@ sb_arg_t general_args[] =
{"report-interval", "periodically report intermediate statistics "
"with a specified interval in seconds. 0 disables intermediate reports",
SB_ARG_TYPE_INT, "0"},
{"report-checkpoints", "dump full statistics and reset all counters at "
"specified points in time. The argument is a list of comma-separated values "
"representing the amount of time in seconds elapsed from start of test "
"when report checkpoint(s) must be performed. Report checkpoints are off by "
"default.", SB_ARG_TYPE_LIST, ""},
{"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"},
@ -125,6 +133,8 @@ static void sigalrm_handler(int sig)
if (sig == SIGALRM)
{
sb_timer_stop(&sb_globals.exec_timer);
sb_timer_stop(&sb_globals.cumulative_timer1);
sb_timer_stop(&sb_globals.cumulative_timer2);
log_text(LOG_FATAL,
"The --max-time limit has expired, forcing shutdown...");
if (current_test && current_test->ops.print_stats)
@ -337,6 +347,27 @@ void print_run_mode(sb_test_t *test)
sb_globals.report_interval);
}
if (sb_globals.n_checkpoints > 0)
{
char list_str[MAX_CHECKPOINTS * 12];
char *tmp = list_str;
unsigned int i;
int n, size = sizeof(list_str);
for (i = 0; i < sb_globals.n_checkpoints - 1; i++)
{
n = snprintf(tmp, size, "%u, ", sb_globals.checkpoints[i]);
if (n >= size)
break;
tmp += n;
size -= n;
}
if (i == sb_globals.n_checkpoints - 1)
snprintf(tmp, size, "%u", sb_globals.checkpoints[i]);
log_text(LOG_NOTICE, "Report checkpoint(s) at %s seconds",
list_str);
}
if (sb_globals.debug)
log_text(LOG_NOTICE, "Debug mode enabled.\n");
@ -511,6 +542,53 @@ static void *report_thread_proc(void *arg)
return NULL;
}
/* Checkpoints reports thread */
static void *checkpoints_thread_proc(void *arg)
{
unsigned long long pause_ns;
unsigned long long next_ns;
unsigned long long curr_ns;
unsigned int i;
(void)arg; /* unused */
if (current_test->ops.print_stats == NULL)
{
log_text(LOG_DEBUG, "Reporting not supported by the current test, ",
"terminating the reporting thread");
return NULL;
}
log_text(LOG_DEBUG, "Checkpoints report thread started");
pthread_mutex_lock(&thread_start_mutex);
pthread_mutex_unlock(&thread_start_mutex);
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);
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 alter 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:");
current_test->ops.print_stats(SB_STAT_CUMULATIVE);
print_global_stats();
SB_THREAD_MUTEX_UNLOCK();
}
return NULL;
}
/*
Main test function. Start threads.
@ -522,7 +600,9 @@ static int run_test(sb_test_t *test)
unsigned int i;
int err;
pthread_t report_thread;
pthread_t checkpoints_thread;
int report_thread_created = 0;
int checkpoints_thread_created = 0;
/* initialize test */
if (test->ops.init != NULL && test->ops.init() != 0)
@ -533,9 +613,10 @@ static int run_test(sb_test_t *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);
for(i = 0; i < sb_globals.num_threads; i++)
{
sb_timer_init(&sb_globals.op_timers[i]);
threads[i].id = i;
threads[i].test = test;
}
@ -575,6 +656,19 @@ static int run_test(sb_test_t *test)
report_thread_created = 1;
}
if (sb_globals.n_checkpoints > 0)
{
/* Create a thread for checkpoint statistic reports */
if ((err = pthread_create(&checkpoints_thread, &thread_attr,
&checkpoints_thread_proc, NULL)) != 0)
{
log_errno(LOG_FATAL, "pthread_create() for the checkpoint thread "
"failed.");
return 1;
}
checkpoints_thread_created = 1;
}
/* Starting the test threads */
for(i = 0; i < sb_globals.num_threads; i++)
{
@ -589,6 +683,8 @@ static int run_test(sb_test_t *test)
}
sb_timer_start(&sb_globals.exec_timer); /* Start benchmark timer */
sb_timer_start(&sb_globals.cumulative_timer1);
sb_timer_start(&sb_globals.cumulative_timer2);
#ifdef HAVE_ALARM
/* Set the alarm to force shutdown */
@ -607,6 +703,8 @@ static int run_test(sb_test_t *test)
}
sb_timer_stop(&sb_globals.exec_timer);
sb_timer_stop(&sb_globals.cumulative_timer1);
sb_timer_stop(&sb_globals.cumulative_timer2);
/* Silence periodic reports if they were on */
sb_globals.report_interval = 0;
@ -633,12 +731,18 @@ static int run_test(sb_test_t *test)
if (test->ops.done != NULL)
(*(test->ops.done))();
/* Delay killing the reporting thread to avoid mutex lock leaks */
/* Delay killing the reporting threads to avoid mutex lock leaks */
if (report_thread_created)
{
if (pthread_cancel(report_thread) || pthread_join(report_thread, NULL))
log_errno(LOG_FATAL, "Terminating the reporting thread failed.");
}
if (checkpoints_thread_created)
{
if (pthread_cancel(checkpoints_thread) ||
pthread_join(checkpoints_thread, NULL))
log_errno(LOG_FATAL, "Terminating the checkpoint thread failed.");
}
return sb_globals.error != 0;
}
@ -660,10 +764,23 @@ static sb_test_t *find_test(char *name)
}
static int checkpoint_cmp(const void *a_ptr, const void *b_ptr)
{
const unsigned int a = *(const unsigned int *) a_ptr;
const unsigned int b = *(const unsigned int *) b_ptr;
return (int) (a - b);
}
static int init(void)
{
option_t *opt;
char *tmp;
sb_list_t *checkpoints_list;
sb_list_item_t *pos_val;
value_t *val;
long res;
sb_globals.num_threads = sb_get_value_int("num-threads");
if (sb_globals.num_threads <= 0)
@ -703,12 +820,10 @@ static int init(void)
else
sb_globals.force_shutdown = 0;
}
sb_globals.op_timers = (sb_timer_t *)malloc(sb_globals.num_threads *
sizeof(sb_timer_t));
threads = (sb_thread_ctxt_t *)malloc(sb_globals.num_threads *
sizeof(sb_thread_ctxt_t));
if (sb_globals.op_timers == NULL || threads == NULL)
if (threads == NULL)
{
log_text(LOG_FATAL, "Memory allocation failure.\n");
return 1;
@ -740,9 +855,37 @@ static 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.report_interval =
sb_get_value_int("report-interval");
sb_globals.report_interval = sb_get_value_int("report-interval");
sb_globals.n_checkpoints = 0;
checkpoints_list = sb_get_value_list("report-checkpoints");
SB_LIST_FOR_EACH(pos_val, checkpoints_list)
{
char *endptr;
val = SB_LIST_ENTRY(pos_val, value_t, listitem);
res = strtol(val->data, &endptr, 10);
if (*endptr != '\0' || res < 0 || res > UINT_MAX)
{
log_text(LOG_FATAL, "Invalid value for --report-checkpoints: '%s'",
val->data);
return 1;
}
if (++sb_globals.n_checkpoints > MAX_CHECKPOINTS)
{
log_text(LOG_FATAL, "Too many checkpoints in --report-checkpoints "
"(up to %d can be defined)", MAX_CHECKPOINTS);
return 1;
}
sb_globals.checkpoints[sb_globals.n_checkpoints-1] = (unsigned int) res;
}
if (sb_globals.n_checkpoints > 0)
{
qsort(sb_globals.checkpoints, sb_globals.n_checkpoints,
sizeof(unsigned int), checkpoint_cmp);
}
return 0;
}

View File

@ -53,6 +53,9 @@
#define SB_MAX_RND 0x3fffffffu
/* Maximum number of elements in --report-checkpoints list */
#define MAX_CHECKPOINTS 256
/* random() is not thread-safe on most platforms, use lrand48() if available */
#ifdef HAVE_LRAND48
#define sb_rnd() (lrand48() % SB_MAX_RND)
@ -192,11 +195,16 @@ 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 *op_timers; /* timers to measure each thread's run time */
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 */
/* array of report checkpoints */
unsigned int checkpoints[MAX_CHECKPOINTS];
unsigned int n_checkpoints; /* number of checkpoints */
unsigned int tx_rate; /* target transaction rate */
unsigned int tx_jitter; /* target transaction variation (us) */
unsigned int max_requests; /* maximum number of requests */

View File

@ -259,6 +259,7 @@ static int create_files(void);
static int remove_files(void);
static int parse_arguments(void);
static void clear_stats(void);
static void init_vars(void);
static sb_request_t file_get_seq_request(void);
static sb_request_t file_get_rnd_request(void);
static void check_seq_req(sb_file_request_t *, sb_file_request_t *);
@ -313,6 +314,7 @@ int file_init(void)
return 1;
#endif
init_vars();
clear_stats();
return 0;
@ -785,7 +787,7 @@ void file_print_stats(sb_stat_t type)
}
case SB_STAT_CUMULATIVE:
seconds = NS2SEC(sb_timer_value(&sb_globals.exec_timer));
seconds = NS2SEC(sb_timer_split(&sb_globals.cumulative_timer1));
log_text(LOG_NOTICE,
"Operations performed: %d reads, %d writes, %d Other = %d Total",
@ -799,6 +801,8 @@ void file_print_stats(sb_stat_t type)
(bytes_read + bytes_written) / seconds));
log_text(LOG_NOTICE, "%8.2f Requests/sec executed",
(read_ops + write_ops) / seconds);
clear_stats();
break;
}
}
@ -962,12 +966,25 @@ int file_cmd_cleanup(void)
return remove_files();
}
void clear_stats(void)
void init_vars(void)
{
position = 0; /* position in file */
current_file = 0;
fsynced_file = 0; /* for counting file to be fsynced */
fsynced_file2 = 0;
req_performed = 0;
is_dirty = 0;
if (sb_globals.validate)
{
prev_req.size = 0;
prev_req.operation = FILE_OP_TYPE_NULL;
prev_req.file_id = 0;
prev_req.pos = 0;
}
}
void clear_stats(void)
{
read_ops = 0;
real_read_ops = 0;
write_ops = 0;
@ -978,15 +995,12 @@ void clear_stats(void)
last_bytes_read = 0;
bytes_written = 0;
last_bytes_written = 0;
req_performed = 0;
is_dirty = 0;
if (sb_globals.validate)
{
prev_req.size = 0;
prev_req.operation = FILE_OP_TYPE_NULL;
prev_req.file_id = 0;
prev_req.pos = 0;
}
/*
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);
}

View File

@ -379,7 +379,7 @@ void memory_print_stats(sb_stat_t type)
break;
case SB_STAT_CUMULATIVE:
seconds = NS2SEC(sb_timer_value(&sb_globals.exec_timer));
seconds = NS2SEC(sb_timer_split(&sb_globals.cumulative_timer1));
log_text(LOG_NOTICE, "Operations performed: %d (%8.2f ops/sec)\n",
total_ops, total_ops / seconds);
@ -387,6 +387,14 @@ void memory_print_stats(sb_stat_t type)
log_text(LOG_NOTICE, "%4.2f MB transferred (%4.2f MB/sec)\n",
total_bytes / megabyte,
total_bytes / megabyte / seconds);
total_ops = 0;
total_bytes = 0;
/*
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);
break;
}

View File

@ -300,6 +300,8 @@ static int prepare_stmt_set_trx(oltp_stmt_set_t *, oltp_bind_set_t *, db_conn_t
static int prepare_stmt_set_nontrx(oltp_stmt_set_t *, oltp_bind_set_t *, db_conn_t *);
static int prepare_stmt_set_sp(oltp_stmt_set_t *, oltp_bind_set_t *, db_conn_t *);
static void oltp_reset_stats(void);
/* Close a set of statements */
void close_stmt_set(oltp_stmt_set_t *set);
@ -505,12 +507,8 @@ int oltp_cmd_prepare(void)
oltp_disconnect(con);
read_ops = last_read_ops = 0;
write_ops = last_write_ops = 0;
other_ops = 0;
transactions = last_transactions = 0;
deadlocks = 0;
oltp_reset_stats();
return 0;
error:
@ -645,13 +643,10 @@ int oltp_init(void)
{
exec_timers = (sb_timer_t *)malloc(sb_globals.num_threads * sizeof(sb_timer_t));
fetch_timers = (sb_timer_t *)malloc(sb_globals.num_threads * sizeof(sb_timer_t));
for (thread_id = 0; thread_id < sb_globals.num_threads; thread_id++)
{
sb_timer_init(exec_timers + thread_id);
sb_timer_init(fetch_timers + thread_id);
}
}
oltp_reset_stats();
/* Percentile stats for --report-interval */
if (sb_percentile_init(&local_percentile, 100000, 1.0, 1e13))
return 1;
@ -1348,8 +1343,7 @@ int oltp_execute_request(sb_request_t *sb_req, int thread_id)
LOG_EVENT_STOP(msg, thread_id);
/* Update percentile stats for --report-interval */
sb_percentile_update(&local_percentile,
sb_timer_value(&sb_globals.op_timers[thread_id]));
sb_percentile_update(&local_percentile, sb_timer_value(&timers[thread_id]));
SB_THREAD_MUTEX_LOCK();
read_ops += local_read_ops;
@ -1413,9 +1407,8 @@ void oltp_print_stats(sb_stat_t type)
else if (type != SB_STAT_CUMULATIVE)
return;
seconds = NS2SEC(sb_timer_value(&sb_globals.exec_timer));
seconds = NS2SEC(sb_timer_split(&sb_globals.cumulative_timer1));
log_text(LOG_NOTICE, "OLTP test statistics:");
log_text(LOG_NOTICE, " queries performed:");
log_text(LOG_NOTICE, " read: %d",
@ -1468,6 +1461,8 @@ void oltp_print_stats(sb_stat_t type)
log_text(LOG_DEBUG, " total: %.4fs",
NS2SEC(get_sum_time(&fetch_timer)));
}
oltp_reset_stats();
}
@ -2345,3 +2340,30 @@ int get_think_time(void)
return t;
}
static void oltp_reset_stats(void)
{
unsigned int thread_id;
read_ops = last_read_ops = 0;
write_ops = last_write_ops = 0;
other_ops = 0;
transactions = last_transactions = 0;
deadlocks = 0;
/*
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);
if (sb_globals.debug)
{
for (thread_id = 0; thread_id < sb_globals.num_threads; thread_id++)
{
sb_timer_init(exec_timers + thread_id);
sb_timer_init(fetch_timers + thread_id);
}
}
}