Re: [PATCH] Log offsets of I/O operations

[Jens Axboe <axboe@kernel.dk>]

[-- Attachment #1: Type: text/plain, Size: 1514 bytes --]

On 2014-06-30 16:09, Abutalib Aghayev wrote:
>
> On Mon, Jun 30 2014 at 17:50 PM, Jens Axboe <axboe@kernel.dk> wrote:
>> On 2014-06-29 11:43, Abutalib Aghayev wrote:
>>>
>>> This is a quick and dirty patch to log offsets of I/O operations as
>>> well.  It is useful if you would like to make offset vs latency plot for
>>> random I/O, which may not be interesting to many people, so feel free to
>>> ignore it.
>>
>> I can definitely see this being useful. But adding 8 bytes to every log
>> entry complicates things, as fio is already memory intensive there when
>> logging longer runs.
>>
>> I'd suggest having two logging types:
>>
>> struct io_sample {
>>             uint64_t time;
>>             uint64_t val;
>>             uint32_t ddir;
>>             uint32_t bs;
>>             uint64_t offset;
>
> I assume you didn't mean offset being here as well.

Ah no, of course not.

>> struct io_sample_offset {
>>             struct io_sample s;
>>             uint64_t offset;
>> };
>>
>> and using the right type for what you are logging. This means you'd need
>> an option to switch on the offset logging, and that you'd need to store
>> this in the iolog struct (whether to log offset or not) and use the
>> appropriate size for allocating and extending the log entries when needed.
>>
>> Make sense?
>
> Yes, let me rework the patch.

Thanks! Note that you also need to handle the client/server part. 
Half-assed attempt attached, not tested at all. Still needs the client 
part update.


-- 
Jens Axboe


[-- Attachment #2: iolog-offset.patch --]
[-- Type: text/x-patch, Size: 16522 bytes --]

diff --git a/backend.c b/backend.c
index ee75566af84c..ac6ed3e45fc2 100644
--- a/backend.c
+++ b/backend.c
@@ -2020,9 +2020,9 @@ int fio_backend(void)
 		return 0;
 
 	if (write_bw_log) {
-		setup_log(&agg_io_log[DDIR_READ], 0, IO_LOG_TYPE_BW);
-		setup_log(&agg_io_log[DDIR_WRITE], 0, IO_LOG_TYPE_BW);
-		setup_log(&agg_io_log[DDIR_TRIM], 0, IO_LOG_TYPE_BW);
+		setup_log(&agg_io_log[DDIR_READ], 0, IO_LOG_TYPE_BW, 0);
+		setup_log(&agg_io_log[DDIR_WRITE], 0, IO_LOG_TYPE_BW, 0);
+		setup_log(&agg_io_log[DDIR_TRIM], 0, IO_LOG_TYPE_BW, 0);
 	}
 
 	startup_mutex = fio_mutex_init(FIO_MUTEX_LOCKED);
diff --git a/client.c b/client.c
index 828dd97b0b35..9ab7e70df8ca 100644
--- a/client.c
+++ b/client.c
@@ -1156,7 +1156,11 @@ static struct cmd_iolog_pdu *convert_iolog_gz(struct fio_net_cmd *cmd,
 	 */
 	nr_samples = le32_to_cpu(pdu->nr_samples);
 
-	total = nr_samples * sizeof(struct io_sample);
+	if (pdu->log_offset)
+		total = nr_samples * sizeof(struct io_sample);
+	else
+		total = nr_samples * sizeof(struct io_sample_offset);
+
 	ret = malloc(total + sizeof(*pdu));
 	ret->nr_samples = nr_samples;
 
@@ -1225,10 +1229,11 @@ static struct cmd_iolog_pdu *convert_iolog(struct fio_net_cmd *cmd)
 	} else
 		ret = pdu;
 
+	ret->nr_samples		= le64_to_cpu(ret->nr_samples);
 	ret->thread_number	= le32_to_cpu(ret->thread_number);
-	ret->nr_samples		= le32_to_cpu(ret->nr_samples);
 	ret->log_type		= le32_to_cpu(ret->log_type);
 	ret->compressed		= le32_to_cpu(ret->compressed);
+	ret->log_offset		= le32_to_cpu(ret->log_offset);
 
 	for (i = 0; i < ret->nr_samples; i++) {
 		struct io_sample *s = &ret->samples[i];
diff --git a/init.c b/init.c
index 6b29aa702407..4f8b38d6e632 100644
--- a/init.c
+++ b/init.c
@@ -1146,14 +1146,19 @@ static int add_job(struct thread_data *td, const char *jobname, int job_add_num,
 		goto err;
 
 	if (o->lat_log_file || write_lat_log) {
-		setup_log(&td->lat_log, o->log_avg_msec, IO_LOG_TYPE_LAT);
-		setup_log(&td->slat_log, o->log_avg_msec, IO_LOG_TYPE_SLAT);
-		setup_log(&td->clat_log, o->log_avg_msec, IO_LOG_TYPE_CLAT);
+		setup_log(&td->lat_log, o->log_avg_msec, IO_LOG_TYPE_LAT,
+				o->log_offset);
+		setup_log(&td->slat_log, o->log_avg_msec, IO_LOG_TYPE_SLAT,
+				o->log_offset);
+		setup_log(&td->clat_log, o->log_avg_msec, IO_LOG_TYPE_CLAT,
+				o->log_offset);
 	}
 	if (o->bw_log_file || write_bw_log)
-		setup_log(&td->bw_log, o->log_avg_msec, IO_LOG_TYPE_BW);
+		setup_log(&td->bw_log, o->log_avg_msec, IO_LOG_TYPE_BW,
+				o->log_offset);
 	if (o->iops_log_file)
-		setup_log(&td->iops_log, o->log_avg_msec, IO_LOG_TYPE_IOPS);
+		setup_log(&td->iops_log, o->log_avg_msec, IO_LOG_TYPE_IOPS,
+				o->log_offset);
 
 	if (!o->name)
 		o->name = strdup(jobname);
diff --git a/io_u.c b/io_u.c
index 997e1137ab90..5b9d483dcd33 100644
--- a/io_u.c
+++ b/io_u.c
@@ -1567,7 +1567,7 @@ static void account_io_completion(struct thread_data *td, struct io_u *io_u,
 		unsigned long tusec;
 
 		tusec = utime_since(&io_u->start_time, &icd->time);
-		add_lat_sample(td, idx, tusec, bytes);
+		add_lat_sample(td, idx, tusec, bytes, io_u->offset);
 
 		if (td->flags & TD_F_PROFILE_OPS) {
 			struct prof_io_ops *ops = &td->prof_io_ops;
@@ -1585,7 +1585,7 @@ static void account_io_completion(struct thread_data *td, struct io_u *io_u,
 	}
 
 	if (!td->o.disable_clat) {
-		add_clat_sample(td, idx, lusec, bytes);
+		add_clat_sample(td, idx, lusec, bytes, io_u->offset);
 		io_u_mark_latency(td, lusec);
 	}
 
@@ -1823,7 +1823,8 @@ void io_u_queued(struct thread_data *td, struct io_u *io_u)
 		unsigned long slat_time;
 
 		slat_time = utime_since(&io_u->start_time, &io_u->issue_time);
-		add_slat_sample(td, io_u->ddir, slat_time, io_u->xfer_buflen);
+		add_slat_sample(td, io_u->ddir, slat_time, io_u->xfer_buflen,
+				io_u->offset);
 	}
 }
 
diff --git a/iolog.c b/iolog.c
index fd1e9e49dd18..ad3cf9cd9151 100644
--- a/iolog.c
+++ b/iolog.c
@@ -539,7 +539,8 @@ int init_iolog(struct thread_data *td)
 	return ret;
 }
 
-void setup_log(struct io_log **log, unsigned long avg_msec, int log_type)
+void setup_log(struct io_log **log, unsigned long avg_msec, int log_type,
+	       int log_offset)
 {
 	struct io_log *l = malloc(sizeof(*l));
 
@@ -547,7 +548,8 @@ void setup_log(struct io_log **log, unsigned long avg_msec, int log_type)
 	l->nr_samples = 0;
 	l->max_samples = 1024;
 	l->log_type = log_type;
-	l->log = malloc(l->max_samples * sizeof(struct io_sample));
+	l->log_offset = log_offset;
+	l->log = malloc(l->max_samples * log_entry_sz(l));
 	l->avg_msec = avg_msec;
 	*log = l;
 }
@@ -593,10 +595,22 @@ void __finish_log(struct io_log *log, const char *name)
 	buf = set_file_buffer(f);
 
 	for (i = 0; i < log->nr_samples; i++) {
-		fprintf(f, "%lu, %lu, %u, %u\n",
-				(unsigned long) log->log[i].time,
-				(unsigned long) log->log[i].val,
-				log->log[i].ddir, log->log[i].bs);
+		struct io_sample *s = get_sample(log, i);
+
+		if (!log->log_offset) {
+			fprintf(f, "%lu, %lu, %u, %u\n",
+					(unsigned long) s->time,
+					(unsigned long) s->val,
+					s->ddir, s->bs);
+		} else {
+			struct io_sample_offset *so = (void *) s;
+
+			fprintf(f, "%lu, %lu, %u, %u, %llu\n",
+					(unsigned long) s->time,
+					(unsigned long) s->val,
+					s->ddir, s->bs,
+					(unsigned long long) so->offset);
+		}
 	}
 
 	fclose(f);
diff --git a/iolog.h b/iolog.h
index 3af56682c64e..42095b2379ff 100644
--- a/iolog.h
+++ b/iolog.h
@@ -28,6 +28,11 @@ struct io_sample {
 	uint32_t bs;
 };
 
+struct io_sample_offset {
+	struct io_sample s;
+	uint64_t offset;
+};
+
 enum {
 	IO_LOG_TYPE_LAT = 1,
 	IO_LOG_TYPE_CLAT,
@@ -45,7 +50,7 @@ struct io_log {
 	 */
 	unsigned long nr_samples;
 	unsigned long max_samples;
-	struct io_sample *log;
+	void *log;
 
 	unsigned int log_type;
 
@@ -55,6 +60,11 @@ struct io_log {
 	unsigned int disabled;
 
 	/*
+	 * Log offsets
+	 */
+	unsigned int log_offset;
+
+	/*
 	 * Windowed average, for logging single entries average over some
 	 * period of time.
 	 */
@@ -63,6 +73,20 @@ struct io_log {
 	unsigned long avg_last;
 };
 
+static inline size_t log_entry_sz(struct io_log *log)
+{
+	if (log->log_offset)
+		return sizeof(struct io_sample_offset);
+	else
+		return sizeof(struct io_sample);
+}
+
+static inline struct io_sample *get_sample(struct io_log *iolog,
+					   uint64_t sample)
+{
+	return iolog->log + sample * log_entry_sz(iolog);
+}
+
 enum {
 	IP_F_ONRB	= 1,
 	IP_F_ONLIST	= 2,
@@ -121,18 +145,18 @@ extern void write_iolog_close(struct thread_data *);
  */
 extern void finalize_logs(struct thread_data *td);
 extern void add_lat_sample(struct thread_data *, enum fio_ddir, unsigned long,
-				unsigned int);
+				unsigned int, unsigned long long);
 extern void add_clat_sample(struct thread_data *, enum fio_ddir, unsigned long,
-				unsigned int);
+				unsigned int, unsigned long long);
 extern void add_slat_sample(struct thread_data *, enum fio_ddir, unsigned long,
-				unsigned int);
+				unsigned int, unsigned long long);
 extern void add_bw_sample(struct thread_data *, enum fio_ddir, unsigned int,
 				struct timeval *);
 extern void add_iops_sample(struct thread_data *, enum fio_ddir, unsigned int,
 				struct timeval *);
 extern void init_disk_util(struct thread_data *);
 extern void update_rusage_stat(struct thread_data *);
-extern void setup_log(struct io_log **, unsigned long, int);
+extern void setup_log(struct io_log **, unsigned long, int, int);
 extern void __finish_log(struct io_log *, const char *);
 extern struct io_log *agg_io_log[DDIR_RWDIR_CNT];
 extern int write_bw_log;
diff --git a/options.c b/options.c
index 74347f3554e0..da70087d2fd7 100644
--- a/options.c
+++ b/options.c
@@ -3095,6 +3095,16 @@ struct fio_option fio_options[FIO_MAX_OPTS] = {
 		.group	= FIO_OPT_G_INVALID,
 	},
 	{
+		.name	= "log_offset",
+		.lname	= "Log offset of IO",
+		.type	= FIO_OPT_INT,
+		.off1	= td_var_offset(log_offset),
+		.help	= "Include offset of IO for each log entry",
+		.def	= "0",
+		.category = FIO_OPT_C_LOG,
+		.group	= FIO_OPT_G_INVALID,
+	},
+	{
 		.name	= "bwavgtime",
 		.lname	= "Bandwidth average time",
 		.type	= FIO_OPT_INT,
diff --git a/server.c b/server.c
index 76b6b54d369b..cd00cc65f852 100644
--- a/server.c
+++ b/server.c
@@ -1177,7 +1177,7 @@ static int fio_send_iolog_gz(struct cmd_iolog_pdu *pdu, struct io_log *log)
 	}
 
 	stream.next_in = (void *) log->log;
-	stream.avail_in = log->nr_samples * sizeof(struct io_sample);
+	stream.avail_in = log->nr_samples * log_entry_sz(log);
 
 	do {
 		unsigned int this_len, flags = 0;
@@ -1214,8 +1214,8 @@ int fio_send_iolog(struct thread_data *td, struct io_log *log, const char *name)
 	struct cmd_iolog_pdu pdu;
 	int i, ret = 0;
 
+	pdu.nr_samples = cpu_to_le64(log->nr_samples);
 	pdu.thread_number = cpu_to_le32(td->thread_number);
-	pdu.nr_samples = __cpu_to_le32(log->nr_samples);
 	pdu.log_type = cpu_to_le32(log->log_type);
 	pdu.compressed = cpu_to_le32(use_zlib);
 
@@ -1223,12 +1223,18 @@ int fio_send_iolog(struct thread_data *td, struct io_log *log, const char *name)
 	pdu.name[FIO_NET_NAME_MAX - 1] = '\0';
 
 	for (i = 0; i < log->nr_samples; i++) {
-		struct io_sample *s = &log->log[i];
+		struct io_sample *s = get_sample(log, i);
 
 		s->time	= cpu_to_le64(s->time);
 		s->val	= cpu_to_le64(s->val);
 		s->ddir	= cpu_to_le32(s->ddir);
 		s->bs	= cpu_to_le32(s->bs);
+
+		if (log->log_offset) {
+			struct io_sample_offset *so = (void *) s;
+
+			so->offset = cpu_to_le64(so->offset);
+		}
 	}
 
 	/*
@@ -1246,7 +1252,7 @@ int fio_send_iolog(struct thread_data *td, struct io_log *log, const char *name)
 		return fio_send_iolog_gz(&pdu, log);
 
 	return fio_send_cmd_ext_pdu(server_fd, FIO_NET_CMD_IOLOG, log->log,
-			log->nr_samples * sizeof(struct io_sample), 0, 0);
+			log->nr_samples * log_entry_sz(log), 0, 0);
 }
 
 void fio_server_send_add_job(struct thread_data *td)
diff --git a/server.h b/server.h
index 52ad4a1518fb..cc4c5b435a2f 100644
--- a/server.h
+++ b/server.h
@@ -143,10 +143,11 @@ struct cmd_text_pdu {
 };
 
 struct cmd_iolog_pdu {
+	uint64_t nr_samples;
 	uint32_t thread_number;
-	uint32_t nr_samples;
 	uint32_t log_type;
 	uint32_t compressed;
+	uint32_t log_offset;
 	uint8_t name[FIO_NET_NAME_MAX];
 	struct io_sample samples[0];
 };
diff --git a/stat.c b/stat.c
index 3adb46eab808..bac637592f94 100644
--- a/stat.c
+++ b/stat.c
@@ -1563,9 +1563,10 @@ static inline void add_stat_sample(struct io_stat *is, unsigned long data)
 
 static void __add_log_sample(struct io_log *iolog, unsigned long val,
 			     enum fio_ddir ddir, unsigned int bs,
-			     unsigned long t)
+			     unsigned long t, unsigned long long offset)
 {
 	const int nr_samples = iolog->nr_samples;
+	struct io_sample *s;
 
 	if (iolog->disabled)
 		return;
@@ -1574,9 +1575,10 @@ static void __add_log_sample(struct io_log *iolog, unsigned long val,
 		iolog->avg_last = t;
 
 	if (iolog->nr_samples == iolog->max_samples) {
-		int new_size = sizeof(struct io_sample) * iolog->max_samples*2;
+		size_t new_size;
 		void *new_log;
 
+		new_size = 2 * iolog->max_samples * log_entry_sz(iolog);
 		new_log = realloc(iolog->log, new_size);
 		if (!new_log) {
 			log_err("fio: failed extending iolog! Will stop logging.\n");
@@ -1587,10 +1589,19 @@ static void __add_log_sample(struct io_log *iolog, unsigned long val,
 		iolog->max_samples <<= 1;
 	}
 
-	iolog->log[nr_samples].val = val;
-	iolog->log[nr_samples].time = t;
-	iolog->log[nr_samples].ddir = ddir;
-	iolog->log[nr_samples].bs = bs;
+	s = get_sample(iolog, nr_samples);
+
+	s->val = val;
+	s->time = t;
+	s->ddir = ddir;
+	s->bs = bs;
+
+	if (iolog->log_offset) {
+		struct io_sample_offset *so = (void *) s;
+
+		so->offset = offset;
+	}
+
 	iolog->nr_samples++;
 }
 
@@ -1646,19 +1657,19 @@ static void _add_stat_to_log(struct io_log *iolog, unsigned long elapsed)
 		unsigned long mr;
 
 		mr = iolog->avg_window[DDIR_READ].mean.u.f + 0.50;
-		__add_log_sample(iolog, mr, DDIR_READ, 0, elapsed);
+		__add_log_sample(iolog, mr, DDIR_READ, 0, elapsed, 0);
 	}
 	if (iolog->avg_window[DDIR_WRITE].samples) {
 		unsigned long mw;
 
 		mw = iolog->avg_window[DDIR_WRITE].mean.u.f + 0.50;
-		__add_log_sample(iolog, mw, DDIR_WRITE, 0, elapsed);
+		__add_log_sample(iolog, mw, DDIR_WRITE, 0, elapsed, 0);
 	}
 	if (iolog->avg_window[DDIR_TRIM].samples) {
 		unsigned long mw;
 
 		mw = iolog->avg_window[DDIR_TRIM].mean.u.f + 0.50;
-		__add_log_sample(iolog, mw, DDIR_TRIM, 0, elapsed);
+		__add_log_sample(iolog, mw, DDIR_TRIM, 0, elapsed, 0);
 	}
 
 	reset_io_stat(&iolog->avg_window[DDIR_READ]);
@@ -1668,7 +1679,7 @@ static void _add_stat_to_log(struct io_log *iolog, unsigned long elapsed)
 
 static void add_log_sample(struct thread_data *td, struct io_log *iolog,
 			   unsigned long val, enum fio_ddir ddir,
-			   unsigned int bs)
+			   unsigned int bs, unsigned long long offset)
 {
 	unsigned long elapsed, this_window;
 
@@ -1681,7 +1692,7 @@ static void add_log_sample(struct thread_data *td, struct io_log *iolog,
 	 * If no time averaging, just add the log sample.
 	 */
 	if (!iolog->avg_msec) {
-		__add_log_sample(iolog, val, ddir, bs, elapsed);
+		__add_log_sample(iolog, val, ddir, bs, elapsed, offset);
 		return;
 	}
 
@@ -1730,7 +1741,7 @@ void add_agg_sample(unsigned long val, enum fio_ddir ddir, unsigned int bs)
 		return;
 
 	iolog = agg_io_log[ddir];
-	__add_log_sample(iolog, val, ddir, bs, mtime_since_genesis());
+	__add_log_sample(iolog, val, ddir, bs, mtime_since_genesis(), 0);
 }
 
 static void add_clat_percentile_sample(struct thread_stat *ts,
@@ -1743,7 +1754,8 @@ static void add_clat_percentile_sample(struct thread_stat *ts,
 }
 
 void add_clat_sample(struct thread_data *td, enum fio_ddir ddir,
-		     unsigned long usec, unsigned int bs)
+		     unsigned long usec, unsigned int bs,
+		     unsigned long long offset)
 {
 	struct thread_stat *ts = &td->ts;
 
@@ -1753,14 +1765,15 @@ void add_clat_sample(struct thread_data *td, enum fio_ddir ddir,
 	add_stat_sample(&ts->clat_stat[ddir], usec);
 
 	if (td->clat_log)
-		add_log_sample(td, td->clat_log, usec, ddir, bs);
+		add_log_sample(td, td->clat_log, usec, ddir, bs, offset);
 
 	if (ts->clat_percentiles)
 		add_clat_percentile_sample(ts, usec, ddir);
 }
 
 void add_slat_sample(struct thread_data *td, enum fio_ddir ddir,
-		     unsigned long usec, unsigned int bs)
+		     unsigned long usec, unsigned int bs,
+		     unsigned long long offset)
 {
 	struct thread_stat *ts = &td->ts;
 
@@ -1770,11 +1783,12 @@ void add_slat_sample(struct thread_data *td, enum fio_ddir ddir,
 	add_stat_sample(&ts->slat_stat[ddir], usec);
 
 	if (td->slat_log)
-		add_log_sample(td, td->slat_log, usec, ddir, bs);
+		add_log_sample(td, td->slat_log, usec, ddir, bs, offset);
 }
 
 void add_lat_sample(struct thread_data *td, enum fio_ddir ddir,
-		    unsigned long usec, unsigned int bs)
+		    unsigned long usec, unsigned int bs,
+		    unsigned long long offset)
 {
 	struct thread_stat *ts = &td->ts;
 
@@ -1784,7 +1798,7 @@ void add_lat_sample(struct thread_data *td, enum fio_ddir ddir,
 	add_stat_sample(&ts->lat_stat[ddir], usec);
 
 	if (td->lat_log)
-		add_log_sample(td, td->lat_log, usec, ddir, bs);
+		add_log_sample(td, td->lat_log, usec, ddir, bs, offset);
 }
 
 void add_bw_sample(struct thread_data *td, enum fio_ddir ddir, unsigned int bs,
@@ -1818,7 +1832,7 @@ void add_bw_sample(struct thread_data *td, enum fio_ddir ddir, unsigned int bs,
 		add_stat_sample(&ts->bw_stat[ddir], rate);
 
 		if (td->bw_log)
-			add_log_sample(td, td->bw_log, rate, ddir, bs);
+			add_log_sample(td, td->bw_log, rate, ddir, bs, 0);
 
 		td->stat_io_bytes[ddir] = td->this_io_bytes[ddir];
 	}
@@ -1857,7 +1871,7 @@ void add_iops_sample(struct thread_data *td, enum fio_ddir ddir, unsigned int bs
 		add_stat_sample(&ts->iops_stat[ddir], iops);
 
 		if (td->iops_log)
-			add_log_sample(td, td->iops_log, iops, ddir, bs);
+			add_log_sample(td, td->iops_log, iops, ddir, bs, 0);
 
 		td->stat_io_blocks[ddir] = td->this_io_blocks[ddir];
 	}
diff --git a/thread_options.h b/thread_options.h
index 57d84dbba3de..e53000ab248b 100644
--- a/thread_options.h
+++ b/thread_options.h
@@ -108,6 +108,7 @@ struct thread_options {
 	unsigned long long rand_seed;
 	unsigned int use_os_rand;
 	unsigned int log_avg_msec;
+	unsigned int log_offset;
 	unsigned int norandommap;
 	unsigned int softrandommap;
 	unsigned int bs_unaligned;
@@ -335,6 +336,7 @@ struct thread_options_pack {
 	uint64_t rand_seed;
 	uint32_t use_os_rand;
 	uint32_t log_avg_msec;
+	uint32_t log_offset;
 	uint32_t norandommap;
 	uint32_t softrandommap;
 	uint32_t bs_unaligned;