Add total latency log

We log submission and completion latencies, also log total latencies.
This makes it easier to graph and make histograms, if you care only
about the complete latency.

Signed-off-by: Jens Axboe <jaxboe@fusionio.com>

diff --git a/HOWTO b/HOWTO
index 3af4ce6b9e75b89a3089c509281f241f5a836baa..7db02b1e5a6758a5930bde67e4b6d8a030364239 100644 (file)
--- a/HOWTO
+++ b/HOWTO
@@ -976,15 +976,16 @@ write_bw_log=str If given, write a bandwidth log of the jobs in this job
                filename. For this option, the postfix is _bw.log.
 
 write_lat_log=str Same as write_bw_log, except that this option stores io
                filename. For this option, the postfix is _bw.log.
 
 write_lat_log=str Same as write_bw_log, except that this option stores io

-               completion latencies instead. If no filename is given
-               with this option, the default filename of "jobname_type.log"
-               is used. Even if the filename is given, fio will still
-               append the type of log. So if one specifies
+               submission, completion, and total latencies instead. If no
+               filename is given with this option, the default filename of
+               "jobname_type.log" is used. Even if the filename is given,
+               fio will still append the type of log. So if one specifies

 
                write_lat_log=foo
 
 
                write_lat_log=foo
 

-               The actual log names will be foo_clat.log and foo_slat.log.
-               This helps fio_generate_plot fine the logs automatically.
+               The actual log names will be foo_slat.log, foo_slat.log,
+               and foo_lat.log. This helps fio_generate_plot fine the logs
+               automatically.

 
 lockmem=int    Pin down the specified amount of memory with mlock(2). Can
                potentially be used instead of removing memory or booting
 
 lockmem=int    Pin down the specified amount of memory with mlock(2). Can
                potentially be used instead of removing memory or booting


@@ -1008,18 +1009,21 @@ cpuchunks=int   If the job is a CPU cycle eater, split the load into
 disk_util=bool Generate disk utilization statistics, if the platform
                supports it. Defaults to on.
 
 disk_util=bool Generate disk utilization statistics, if the platform
                supports it. Defaults to on.
 

-disable_clat=bool Disable measurements of completion latency numbers. Useful
+disable_lat=bool Disable measurements of total latency numbers. Useful

                only for cutting back the number of calls to gettimeofday,
                as that does impact performance at really high IOPS rates.
                Note that to really get rid of a large amount of these
                calls, this option must be used with disable_slat and
                disable_bw as well.
 
                only for cutting back the number of calls to gettimeofday,
                as that does impact performance at really high IOPS rates.
                Note that to really get rid of a large amount of these
                calls, this option must be used with disable_slat and
                disable_bw as well.
 

+disable_clat=bool Disable measurements of completion latency numbers. See
+               disable_lat.
+

 disable_slat=bool Disable measurements of submission latency numbers. See
 disable_slat=bool Disable measurements of submission latency numbers. See

-               disable_clat.
+               disable_slat.

 
 disable_bw=bool        Disable measurements of throughput/bandwidth numbers. See
 
 disable_bw=bool        Disable measurements of throughput/bandwidth numbers. See

-               disable_clat.
+               disable_lat.

 
 gtod_reduce=bool Enable all of the gettimeofday() reducing options
                (disable_clat, disable_slat, disable_bw) plus reduce
 
 gtod_reduce=bool Enable all of the gettimeofday() reducing options
                (disable_clat, disable_slat, disable_bw) plus reduce

diff --git a/fio.1 b/fio.1
index 0e6095d6499b1f33e8cd1937a17ecbdd2fa548b5..cabff41e0fa21377edc4818681ca36c9cea66c74 100644 (file)
--- a/fio.1
+++ b/fio.1
@@ -722,17 +722,20 @@ Same as \fBwrite_bw_log\fR, but writes I/O completion latencies.  If no
 filename is given with this option, the default filename of "jobname_type.log"
 is used. Even if the filename is given, fio will still append the type of log.
 .TP
 filename is given with this option, the default filename of "jobname_type.log"
 is used. Even if the filename is given, fio will still append the type of log.
 .TP

-.B disable_clat \fR=\fPbool
-Disable measurements of completion latency numbers. Useful only for cutting
+.B disable_lat \fR=\fPbool
+Disable measurements of total latency numbers. Useful only for cutting

 back the number of calls to gettimeofday, as that does impact performance at
 really high IOPS rates.  Note that to really get rid of a large amount of these
 calls, this option must be used with disable_slat and disable_bw as well.
 .TP
 back the number of calls to gettimeofday, as that does impact performance at
 really high IOPS rates.  Note that to really get rid of a large amount of these
 calls, this option must be used with disable_slat and disable_bw as well.
 .TP

+.B disable_clat \fR=\fPbool
+Disable measurements of submission latency numbers. See \fBdisable_lat\fR.
+.TP

 .B disable_slat \fR=\fPbool
 .B disable_slat \fR=\fPbool

-Disable measurements of submission latency numbers. See \fBdisable_clat\fR.
+Disable measurements of submission latency numbers. See \fBdisable_lat\fR.

 .TP
 .B disable_bw_measurement \fR=\fPbool
 .TP
 .B disable_bw_measurement \fR=\fPbool

-Disable measurements of throughput/bandwidth numbers. See \fBdisable_clat\fR.
+Disable measurements of throughput/bandwidth numbers. See \fBdisable_lat\fR.

 .TP
 .BI lockmem \fR=\fPint
 Pin the specified amount of memory with \fBmlock\fR\|(2).  Can be used to
 .TP
 .BI lockmem \fR=\fPint
 Pin the specified amount of memory with \fBmlock\fR\|(2).  Can be used to

diff --git a/fio.c b/fio.c
index b2a08bf0154f594e06f0ea8850f3c49bd5189dd3..2dab64ee3212b35e400a430b342b80da835ae5d3 100644 (file)
--- a/fio.c
+++ b/fio.c
@@ -1177,6 +1177,13 @@ static void *thread_main(void *data)
                } else
                        finish_log(td, td->ts.bw_log, "bw");
        }
                } else
                        finish_log(td, td->ts.bw_log, "bw");
        }

+       if (td->ts.lat_log) {
+               if (td->o.lat_log_file) {
+                       finish_log_named(td, td->ts.lat_log,
+                                               td->o.lat_log_file, "lat");
+               } else
+                       finish_log(td, td->ts.lat_log, "lat");
+       }

        if (td->ts.slat_log) {
                if (td->o.lat_log_file) {
                        finish_log_named(td, td->ts.slat_log,
        if (td->ts.slat_log) {
                if (td->o.lat_log_file) {
                        finish_log_named(td, td->ts.slat_log,

diff --git a/fio.h b/fio.h
index 2a762aa2e5427c93adfdc6cdf9426c3e60ec4b6a..bce81eb9e05e89dfdf41d7024552a121552d7d0b 100644 (file)
--- a/fio.h
+++ b/fio.h
@@ -80,6 +80,7 @@ struct thread_stat {
 
        struct io_log *slat_log;
        struct io_log *clat_log;
 
        struct io_log *slat_log;
        struct io_log *clat_log;

+       struct io_log *lat_log;

        struct io_log *bw_log;
 
        /*
        struct io_log *bw_log;
 
        /*


@@ -87,6 +88,7 @@ struct thread_stat {
         */
        struct io_stat clat_stat[2];            /* completion latency */
        struct io_stat slat_stat[2];            /* submission latency */
         */
        struct io_stat clat_stat[2];            /* completion latency */
        struct io_stat slat_stat[2];            /* submission latency */

+       struct io_stat lat_stat[2];             /* total latency */

        struct io_stat bw_stat[2];              /* bandwidth stats */
 
        unsigned long long stat_io_bytes[2];
        struct io_stat bw_stat[2];              /* bandwidth stats */
 
        unsigned long long stat_io_bytes[2];


@@ -235,6 +237,7 @@ struct thread_options {
        unsigned int zero_buffers;
        unsigned int refill_buffers;
        unsigned int time_based;
        unsigned int zero_buffers;
        unsigned int refill_buffers;
        unsigned int time_based;

+       unsigned int disable_lat;

        unsigned int disable_clat;
        unsigned int disable_slat;
        unsigned int disable_bw;
        unsigned int disable_clat;
        unsigned int disable_slat;
        unsigned int disable_bw;

diff --git a/fio_generate_plots b/fio_generate_plots
index ff479a7d41f7f543b102bd5522db9eec2c8171f3..611f49fc0eec2e812a4df79c181d595820986286 100755 (executable)
--- a/fio_generate_plots
+++ b/fio_generate_plots
@@ -68,3 +68,21 @@ if [ "$PLOT_LINE"x != "x" ]; then
        echo Making clat logs $PLOT_LINE
        echo "set title 'Completion latency - $TITLE'; set xlabel 'time (msec)'; set ylabel 'latency (msec)'; set terminal png; set output '$TITLE-clat.png'; plot " $PLOT_LINE | $GNUPLOT -
 fi
        echo Making clat logs $PLOT_LINE
        echo "set title 'Completion latency - $TITLE'; set xlabel 'time (msec)'; set ylabel 'latency (msec)'; set terminal png; set output '$TITLE-clat.png'; plot " $PLOT_LINE | $GNUPLOT -
 fi

+
+PLOT_LINE=""
+for i in *_lat.log; do
+       if [ ! -r $i ]; then
+               continue
+       fi
+       PT=$(echo $i | sed s/_lat.log//g)
+       if [ "$PLOT_LINE"x != "x" ]; then
+               PLOT_LINE=$PLOT_LINE", "
+       fi
+
+       PLOT_LINE=$PLOT_LINE"'$i' title '$PT' with lines"
+done
+
+if [ "$PLOT_LINE"x != "x" ]; then
+       echo Making lat logs $PLOT_LINE
+       echo "set title 'Latency - $TITLE'; set xlabel 'time (msec)'; set ylabel 'latency (msec)'; set terminal png; set output '$TITLE-lat.png'; plot " $PLOT_LINE | $GNUPLOT -
+fi

diff --git a/init.c b/init.c
index fad487d46871cbdfeaf9b327b307d2e75e92d9dc..9847be21ea52ab0dd6ba81892944a80279ee70ba 100644 (file)
--- a/init.c
+++ b/init.c
@@ -555,6 +555,7 @@ static int add_job(struct thread_data *td, const char *jobname, int job_add_num)
 
        td->ts.clat_stat[0].min_val = td->ts.clat_stat[1].min_val = ULONG_MAX;
        td->ts.slat_stat[0].min_val = td->ts.slat_stat[1].min_val = ULONG_MAX;
 
        td->ts.clat_stat[0].min_val = td->ts.clat_stat[1].min_val = ULONG_MAX;
        td->ts.slat_stat[0].min_val = td->ts.slat_stat[1].min_val = ULONG_MAX;

+       td->ts.lat_stat[0].min_val = td->ts.lat_stat[1].min_val = ULONG_MAX;

        td->ts.bw_stat[0].min_val = td->ts.bw_stat[1].min_val = ULONG_MAX;
        td->ddir_nr = td->o.ddir_nr;
 
        td->ts.bw_stat[0].min_val = td->ts.bw_stat[1].min_val = ULONG_MAX;
        td->ddir_nr = td->o.ddir_nr;
 


@@ -573,6 +574,7 @@ static int add_job(struct thread_data *td, const char *jobname, int job_add_num)
                goto err;
 
        if (td->o.write_lat_log) {
                goto err;
 
        if (td->o.write_lat_log) {

+               setup_log(&td->ts.lat_log);

                setup_log(&td->ts.slat_log);
                setup_log(&td->ts.clat_log);
        }
                setup_log(&td->ts.slat_log);
                setup_log(&td->ts.clat_log);
        }

diff --git a/io_u.c b/io_u.c
index 69edd70e5eafbb97ce3f5f915ee50450fcc90ac6..b2b72302d58ee8b0790fb123dd882c508bbd9360 100644 (file)
--- a/io_u.c
+++ b/io_u.c
@@ -1079,7 +1079,13 @@ static void io_completed(struct thread_data *td, struct io_u *io_u,
                        if (!td->o.disable_clat || !td->o.disable_bw)
                                lusec = utime_since(&io_u->issue_time,
                                                        &icd->time);
                        if (!td->o.disable_clat || !td->o.disable_bw)
                                lusec = utime_since(&io_u->issue_time,
                                                        &icd->time);

+                       if (!td->o.disable_lat) {
+                               unsigned long tusec;

 
 

+                               tusec = utime_since(&io_u->start_time,
+                                                       &icd->time);
+                               add_lat_sample(td, idx, tusec, bytes);
+                       }

                        if (!td->o.disable_clat) {
                                add_clat_sample(td, idx, lusec, bytes);
                                io_u_mark_latency(td, lusec);
                        if (!td->o.disable_clat) {
                                add_clat_sample(td, idx, lusec, bytes);
                                io_u_mark_latency(td, lusec);

diff --git a/iolog.h b/iolog.h
index 2b646866007f89c3ea5cb3112ac0519f205b54a5..2a97e2855c2e11455a508947f594d20316f184c0 100644 (file)
--- a/iolog.h
+++ b/iolog.h
@@ -75,6 +75,8 @@ extern void write_iolog_close(struct thread_data *);
 /*
  * Logging
  */
 /*
  * Logging
  */

+extern void add_lat_sample(struct thread_data *, enum fio_ddir, unsigned long,
+                               unsigned int);

 extern void add_clat_sample(struct thread_data *, enum fio_ddir, unsigned long,
                                unsigned int);
 extern void add_slat_sample(struct thread_data *, enum fio_ddir, unsigned long,
 extern void add_clat_sample(struct thread_data *, enum fio_ddir, unsigned long,
                                unsigned int);
 extern void add_slat_sample(struct thread_data *, enum fio_ddir, unsigned long,

diff --git a/options.c b/options.c
index fb187489766205d64a15e08b7d86b7a1edb04f2e..de691eb32144ef0468341639ef5fc79aab0d441c 100644 (file)
--- a/options.c
+++ b/options.c
@@ -710,6 +710,7 @@ static int str_gtod_reduce_cb(void *data, int *il)
        struct thread_data *td = data;
        int val = *il;
 
        struct thread_data *td = data;
        int val = *il;
 

+       td->o.disable_lat = !!val;

        td->o.disable_clat = !!val;
        td->o.disable_slat = !!val;
        td->o.disable_bw = !!val;
        td->o.disable_clat = !!val;
        td->o.disable_slat = !!val;
        td->o.disable_bw = !!val;


@@ -1791,6 +1792,14 @@ static struct fio_option options[FIO_MAX_OPTS] = {
                .cb     = str_gtod_reduce_cb,
                .def    = "0",
        },
                .cb     = str_gtod_reduce_cb,
                .def    = "0",
        },

+       {
+               .name   = "disable_lat",
+               .type   = FIO_OPT_BOOL,
+               .off1   = td_var_offset(disable_lat),
+               .help   = "Disable latency numbers",
+               .parent = "gtod_reduce",
+               .def    = "0",
+       },

        {
                .name   = "disable_clat",
                .type   = FIO_OPT_BOOL,
        {
                .name   = "disable_clat",
                .type   = FIO_OPT_BOOL,

diff --git a/stat.c b/stat.c
index 143325aa1879680e2e09c5a18c13964b57661845..0f259d273bd48e04e8f7752e522ff44bd72a1a3c 100644 (file)
--- a/stat.c
+++ b/stat.c
@@ -210,6 +210,22 @@ static void show_ddir_status(struct group_run_stats *rs, struct thread_stat *ts,
                free(minp);
                free(maxp);
        }
                free(minp);
                free(maxp);
        }

+       if (calc_lat(&ts->lat_stat[ddir], &min, &max, &mean, &dev)) {
+               const char *base = "(usec)";
+               char *minp, *maxp;
+
+               if (!usec_to_msec(&min, &max, &mean, &dev))
+                       base = "(msec)";
+
+               minp = num2str(min, 6, 1, 0);
+               maxp = num2str(max, 6, 1, 0);
+
+               log_info("     lat %s: min=%s, max=%s, avg=%5.02f,"
+                        " stdev=%5.02f\n", base, minp, maxp, mean, dev);
+
+               free(minp);
+               free(maxp);
+       }

        if (calc_lat(&ts->bw_stat[ddir], &min, &max, &mean, &dev)) {
                double p_of_agg;
 
        if (calc_lat(&ts->bw_stat[ddir], &min, &max, &mean, &dev)) {
                double p_of_agg;
 


@@ -371,6 +387,11 @@ static void show_ddir_status_terse(struct thread_stat *ts,
        else
                log_info(";%lu;%lu;%f;%f", 0UL, 0UL, 0.0, 0.0);
 
        else
                log_info(";%lu;%lu;%f;%f", 0UL, 0UL, 0.0, 0.0);
 

+       if (calc_lat(&ts->lat_stat[ddir], &min, &max, &mean, &dev))
+               log_info(";%lu;%lu;%f;%f", min, max, mean, dev);
+       else
+               log_info(";%lu;%lu;%f;%f", 0UL, 0UL, 0.0, 0.0);
+

        if (calc_lat(&ts->bw_stat[ddir], &min, &max, &mean, &dev)) {
                double p_of_agg;
 
        if (calc_lat(&ts->bw_stat[ddir], &min, &max, &mean, &dev)) {
                double p_of_agg;
 


@@ -498,6 +519,7 @@ void show_run_stats(void)
 
                memset(ts, 0, sizeof(*ts));
                for (j = 0; j <= DDIR_WRITE; j++) {
 
                memset(ts, 0, sizeof(*ts));
                for (j = 0; j <= DDIR_WRITE; j++) {

+                       ts->lat_stat[j].min_val = -1UL;

                        ts->clat_stat[j].min_val = -1UL;
                        ts->slat_stat[j].min_val = -1UL;
                        ts->bw_stat[j].min_val = -1UL;
                        ts->clat_stat[j].min_val = -1UL;
                        ts->slat_stat[j].min_val = -1UL;
                        ts->bw_stat[j].min_val = -1UL;


@@ -559,6 +581,7 @@ void show_run_stats(void)
                for (l = 0; l <= DDIR_WRITE; l++) {
                        sum_stat(&ts->clat_stat[l], &td->ts.clat_stat[l], idx);
                        sum_stat(&ts->slat_stat[l], &td->ts.slat_stat[l], idx);
                for (l = 0; l <= DDIR_WRITE; l++) {
                        sum_stat(&ts->clat_stat[l], &td->ts.clat_stat[l], idx);
                        sum_stat(&ts->slat_stat[l], &td->ts.slat_stat[l], idx);

+                       sum_stat(&ts->lat_stat[l], &td->ts.lat_stat[l], idx);

                        sum_stat(&ts->bw_stat[l], &td->ts.bw_stat[l], idx);
 
                        ts->stat_io_bytes[l] += td->ts.stat_io_bytes[l];
                        sum_stat(&ts->bw_stat[l], &td->ts.bw_stat[l], idx);
 
                        ts->stat_io_bytes[l] += td->ts.stat_io_bytes[l];


@@ -742,6 +765,17 @@ void add_slat_sample(struct thread_data *td, enum fio_ddir ddir,
                add_log_sample(td, ts->slat_log, usec, ddir, bs);
 }
 
                add_log_sample(td, ts->slat_log, usec, ddir, bs);
 }
 

+void add_lat_sample(struct thread_data *td, enum fio_ddir ddir,
+                   unsigned long usec, unsigned int bs)
+{
+       struct thread_stat *ts = &td->ts;
+
+       add_stat_sample(&ts->lat_stat[ddir], usec);
+
+       if (ts->lat_log)
+               add_log_sample(td, ts->lat_log, usec, ddir, bs);
+}
+

 void add_bw_sample(struct thread_data *td, enum fio_ddir ddir, unsigned int bs,
                   struct timeval *t)
 {
 void add_bw_sample(struct thread_data *td, enum fio_ddir ddir, unsigned int bs,
                   struct timeval *t)
 {