FIO creating empty latency log files

FIO creating empty latency log files

[Reed Crowe]

Using this version of FIO:
* io-threads
   master
rcrowe@rcrowe-desktop:~/fio_iothreads/fio$ ./fio --version
fio-2.2.7-14-g00b2

I have a job file which looks like this:

[global]
ioengine=libaio
direct=1
numjobs=1
bs=4k
iodepth=300
rw=randwrite
randrepeat=0
io_submit_mode=offload
rate_iops=8070
time_based=1
runtime=1m

[slow_write]
filename=/mnt/test1/testfile.io
write_lat_log=/tmp/fio_lat

And it produces empty files:
-rw-r--r-- 1 root   root         0 Jun  4 14:34 fio_lat_clat.1.log
-rw-r--r-- 1 root   root         0 Jun  4 14:34 fio_lat_lat.1.log
-rw-r--r-- 1 root   root         0 Jun  4 14:34 fio_lat_slat.1.log

What am I missing?

________________________________

PLEASE NOTE: The information contained in this electronic mail message is intended only for the use of the designated recipient(s) named above. If the reader of this message is not the intended recipient, you are hereby notified that you have received this message in error and that any review, dissemination, distribution, or copying of this message is strictly prohibited. If you have received this communication in error, please notify the sender by telephone or e-mail (as shown above) immediately and destroy any and all copies of this message in your possession (whether hard copies or electronically stored copies).

Re: FIO creating empty latency log files

[Jens Axboe]

On 06/04/2015 05:09 PM, Reed Crowe wrote:
>
> Using this version of FIO:
> * io-threads
>     master
> rcrowe@rcrowe-desktop:~/fio_iothreads/fio$ ./fio --version
> fio-2.2.7-14-g00b2
>
> I have a job file which looks like this:
>
> [global]
> ioengine=libaio
> direct=1
> numjobs=1
> bs=4k
> iodepth=300
> rw=randwrite
> randrepeat=0
> io_submit_mode=offload
> rate_iops=8070
> time_based=1
> runtime=1m
>
> [slow_write]
> filename=/mnt/test1/testfile.io
> write_lat_log=/tmp/fio_lat
>
> And it produces empty files:
> -rw-r--r-- 1 root   root         0 Jun  4 14:34 fio_lat_clat.1.log
> -rw-r--r-- 1 root   root         0 Jun  4 14:34 fio_lat_lat.1.log
> -rw-r--r-- 1 root   root         0 Jun  4 14:34 fio_lat_slat.1.log
>
> What am I missing?

Nothing, it was a bug in the io_submit_mode=offload code. Try updating 
to current -git, this should fix it:

http://git.kernel.dk/cgit/fio/commit/?id=75dc383e9d05369c830559496afa382178905e39

-- 
Jens Axboe

Re: FIO creating empty latency log files

[Buttetsu Batou]

On 06/04/2015 05:09 PM, Reed Crowe wrote:
> Using this version of FIO:
> * io-threads
>     master
> rcrowe@rcrowe-desktop:~/fio_iothreads/fio$ ./fio --version
> fio-2.2.7-14-g00b2
>
> I have a job file which looks like this:
>
> [global]
> ioengine=libaio
> direct=1
> numjobs=1
> bs=4k
> iodepth=300
> rw=randwrite
> randrepeat=0
> io_submit_mode=offload
> rate_iops=8070
> time_based=1
> runtime=1m
>
> [slow_write]
> filename=/mnt/test1/testfile.io
> write_lat_log=/tmp/fio_lat
>
> And it produces empty files:
> -rw-r--r-- 1 root   root         0 Jun  4 14:34 fio_lat_clat.1.log
> -rw-r--r-- 1 root   root         0 Jun  4 14:34 fio_lat_lat.1.log
> -rw-r--r-- 1 root   root         0 Jun  4 14:34 fio_lat_slat.1.log
>
> What am I missing?

I am seeing this behavior in the latest release fio-2.2.10 and in
master fio-2.2.10-29-g8a68 but I am not using offload.

Is anyone currently able to successfully generate log output? If so
could you share your fio version and your config?

Here is the job file I am using at the moment.. have tried variations
on these settings and different fio versions back to 2.0.15 but always
the same empty output:

[write]
group_reporting=1
numjobs=8
ioengine=posixaio
io_submit_mode=inline
stonewall
rw=write
bs=32k
time_based=1
runtime=10
filesize=64k
directory=/tmp
per_job_logs=1
write_bw_log=write_bw
write_iops_log=write_iops

Updated the issue reported here:

https://github.com/axboe/fio/issues/29

Thank you for any ideas you may have!

Re: FIO creating empty latency log files

[Jens Axboe]

On 10/28/2015 12:41 AM, Buttetsu Batou wrote:
> On 06/04/2015 05:09 PM, Reed Crowe wrote:
>> Using this version of FIO:
>> * io-threads
>>      master
>> rcrowe@rcrowe-desktop:~/fio_iothreads/fio$ ./fio --version
>> fio-2.2.7-14-g00b2
>>
>> I have a job file which looks like this:
>>
>> [global]
>> ioengine=libaio
>> direct=1
>> numjobs=1
>> bs=4k
>> iodepth=300
>> rw=randwrite
>> randrepeat=0
>> io_submit_mode=offload
>> rate_iops=8070
>> time_based=1
>> runtime=1m
>>
>> [slow_write]
>> filename=/mnt/test1/testfile.io
>> write_lat_log=/tmp/fio_lat
>>
>> And it produces empty files:
>> -rw-r--r-- 1 root   root         0 Jun  4 14:34 fio_lat_clat.1.log
>> -rw-r--r-- 1 root   root         0 Jun  4 14:34 fio_lat_lat.1.log
>> -rw-r--r-- 1 root   root         0 Jun  4 14:34 fio_lat_slat.1.log
>>
>> What am I missing?
>
> I am seeing this behavior in the latest release fio-2.2.10 and in
> master fio-2.2.10-29-g8a68 but I am not using offload.
>
> Is anyone currently able to successfully generate log output? If so
> could you share your fio version and your config?
>
> Here is the job file I am using at the moment.. have tried variations
> on these settings and different fio versions back to 2.0.15 but always
> the same empty output:
>
> [write]
> group_reporting=1
> numjobs=8
> ioengine=posixaio
> io_submit_mode=inline
> stonewall
> rw=write
> bs=32k
> time_based=1
> runtime=10
> filesize=64k
> directory=/tmp
> per_job_logs=1
> write_bw_log=write_bw
> write_iops_log=write_iops
>
> Updated the issue reported here:
>
> https://github.com/axboe/fio/issues/29
>
> Thank you for any ideas you may have!

I think your issue is because you set filesize=64k. Your job basically 
sets up 8 files of 64k each, then writes to them for 10 seconds. This 
means that the fio main loop keeps re-entering for every 64k for each 
thread. The bandwidth/iops is averaged over a window of 500msec by 
default, and the main loop runs for much shorter than that since it only 
does 64k each time. Hence you never get logged any entries.

Now, it should work. If you comment out these two lines:

memcpy(&td->bw_sample_time, &td->start, sizeof(td->start));
memcpy(&td->iops_sample_time, &td->start, sizeof(td->start));

in backend.c around 1568/1569, then I suspect the logging should improve 
for you. I'll have to see if we can safely do that without making other 
changes, before committing a change like that.t

-- 
Jens Axboe

Re: FIO creating empty latency log files

[Jens Axboe]

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

On 10/28/2015 06:13 AM, Jens Axboe wrote:
> On 10/28/2015 12:41 AM, Buttetsu Batou wrote:
>> On 06/04/2015 05:09 PM, Reed Crowe wrote:
>>> Using this version of FIO:
>>> * io-threads
>>>      master
>>> rcrowe@rcrowe-desktop:~/fio_iothreads/fio$ ./fio --version
>>> fio-2.2.7-14-g00b2
>>>
>>> I have a job file which looks like this:
>>>
>>> [global]
>>> ioengine=libaio
>>> direct=1
>>> numjobs=1
>>> bs=4k
>>> iodepth=300
>>> rw=randwrite
>>> randrepeat=0
>>> io_submit_mode=offload
>>> rate_iops=8070
>>> time_based=1
>>> runtime=1m
>>>
>>> [slow_write]
>>> filename=/mnt/test1/testfile.io
>>> write_lat_log=/tmp/fio_lat
>>>
>>> And it produces empty files:
>>> -rw-r--r-- 1 root   root         0 Jun  4 14:34 fio_lat_clat.1.log
>>> -rw-r--r-- 1 root   root         0 Jun  4 14:34 fio_lat_lat.1.log
>>> -rw-r--r-- 1 root   root         0 Jun  4 14:34 fio_lat_slat.1.log
>>>
>>> What am I missing?
>>
>> I am seeing this behavior in the latest release fio-2.2.10 and in
>> master fio-2.2.10-29-g8a68 but I am not using offload.
>>
>> Is anyone currently able to successfully generate log output? If so
>> could you share your fio version and your config?
>>
>> Here is the job file I am using at the moment.. have tried variations
>> on these settings and different fio versions back to 2.0.15 but always
>> the same empty output:
>>
>> [write]
>> group_reporting=1
>> numjobs=8
>> ioengine=posixaio
>> io_submit_mode=inline
>> stonewall
>> rw=write
>> bs=32k
>> time_based=1
>> runtime=10
>> filesize=64k
>> directory=/tmp
>> per_job_logs=1
>> write_bw_log=write_bw
>> write_iops_log=write_iops
>>
>> Updated the issue reported here:
>>
>> https://github.com/axboe/fio/issues/29
>>
>> Thank you for any ideas you may have!
>
> I think your issue is because you set filesize=64k. Your job basically
> sets up 8 files of 64k each, then writes to them for 10 seconds. This
> means that the fio main loop keeps re-entering for every 64k for each
> thread. The bandwidth/iops is averaged over a window of 500msec by
> default, and the main loop runs for much shorter than that since it only
> does 64k each time. Hence you never get logged any entries.
>
> Now, it should work. If you comment out these two lines:
>
> memcpy(&td->bw_sample_time, &td->start, sizeof(td->start));
> memcpy(&td->iops_sample_time, &td->start, sizeof(td->start));
>
> in backend.c around 1568/1569, then I suspect the logging should improve
> for you. I'll have to see if we can safely do that without making other
> changes, before committing a change like that.t

Try the attached patch, we need to retain the stat block and byte counts 
too.

-- 
Jens Axboe


[-- Attachment #2: short-logging.patch --]
[-- Type: text/x-patch, Size: 2044 bytes --]

diff --git a/backend.c b/backend.c
index b180196e4c4e..5f3bbd44f3ea 100644
--- a/backend.c
+++ b/backend.c
@@ -1559,25 +1559,26 @@ static void *thread_main(void *data)
 
 	fio_gettime(&td->epoch, NULL);
 	fio_getrusage(&td->ru_start);
+	memcpy(&td->bw_sample_time, &td->epoch, sizeof(td->epoch));
+	memcpy(&td->iops_sample_time, &td->epoch, sizeof(td->epoch));
+
+	if (o->ratemin[DDIR_READ] || o->ratemin[DDIR_WRITE] ||
+			o->ratemin[DDIR_TRIM]) {
+	        memcpy(&td->lastrate[DDIR_READ], &td->bw_sample_time,
+					sizeof(td->bw_sample_time));
+	        memcpy(&td->lastrate[DDIR_WRITE], &td->bw_sample_time,
+					sizeof(td->bw_sample_time));
+	        memcpy(&td->lastrate[DDIR_TRIM], &td->bw_sample_time,
+					sizeof(td->bw_sample_time));
+	}
+
 	clear_state = 0;
 	while (keep_running(td)) {
 		uint64_t verify_bytes;
 
 		fio_gettime(&td->start, NULL);
-		memcpy(&td->bw_sample_time, &td->start, sizeof(td->start));
-		memcpy(&td->iops_sample_time, &td->start, sizeof(td->start));
 		memcpy(&td->tv_cache, &td->start, sizeof(td->start));
 
-		if (o->ratemin[DDIR_READ] || o->ratemin[DDIR_WRITE] ||
-				o->ratemin[DDIR_TRIM]) {
-		        memcpy(&td->lastrate[DDIR_READ], &td->bw_sample_time,
-						sizeof(td->bw_sample_time));
-		        memcpy(&td->lastrate[DDIR_WRITE], &td->bw_sample_time,
-						sizeof(td->bw_sample_time));
-		        memcpy(&td->lastrate[DDIR_TRIM], &td->bw_sample_time,
-						sizeof(td->bw_sample_time));
-		}
-
 		if (clear_state)
 			clear_io_state(td);
 
diff --git a/libfio.c b/libfio.c
index d4cad3ec5aba..d5110d4a1c2b 100644
--- a/libfio.c
+++ b/libfio.c
@@ -82,12 +82,14 @@ static void reset_io_counters(struct thread_data *td)
 	int ddir;
 
 	for (ddir = 0; ddir < DDIR_RWDIR_CNT; ddir++) {
+#if  0
 		td->stat_io_bytes[ddir] = 0;
 		td->this_io_bytes[ddir] = 0;
 		td->stat_io_blocks[ddir] = 0;
 		td->this_io_blocks[ddir] = 0;
 		td->rate_bytes[ddir] = 0;
 		td->rate_blocks[ddir] = 0;
+#endif
 		td->bytes_done[ddir] = 0;
 		td->rate_io_issue_bytes[ddir] = 0;
 		td->rate_next_io_time[ddir] = 0;

Re: FIO creating empty latency log files

[Jens Axboe]

On 10/28/2015 09:20 AM, Jens Axboe wrote:
> On 10/28/2015 06:13 AM, Jens Axboe wrote:
>> On 10/28/2015 12:41 AM, Buttetsu Batou wrote:
>>> On 06/04/2015 05:09 PM, Reed Crowe wrote:
>>>> Using this version of FIO:
>>>> * io-threads
>>>>      master
>>>> rcrowe@rcrowe-desktop:~/fio_iothreads/fio$ ./fio --version
>>>> fio-2.2.7-14-g00b2
>>>>
>>>> I have a job file which looks like this:
>>>>
>>>> [global]
>>>> ioengine=libaio
>>>> direct=1
>>>> numjobs=1
>>>> bs=4k
>>>> iodepth=300
>>>> rw=randwrite
>>>> randrepeat=0
>>>> io_submit_mode=offload
>>>> rate_iops=8070
>>>> time_based=1
>>>> runtime=1m
>>>>
>>>> [slow_write]
>>>> filename=/mnt/test1/testfile.io
>>>> write_lat_log=/tmp/fio_lat
>>>>
>>>> And it produces empty files:
>>>> -rw-r--r-- 1 root   root         0 Jun  4 14:34 fio_lat_clat.1.log
>>>> -rw-r--r-- 1 root   root         0 Jun  4 14:34 fio_lat_lat.1.log
>>>> -rw-r--r-- 1 root   root         0 Jun  4 14:34 fio_lat_slat.1.log
>>>>
>>>> What am I missing?
>>>
>>> I am seeing this behavior in the latest release fio-2.2.10 and in
>>> master fio-2.2.10-29-g8a68 but I am not using offload.
>>>
>>> Is anyone currently able to successfully generate log output? If so
>>> could you share your fio version and your config?
>>>
>>> Here is the job file I am using at the moment.. have tried variations
>>> on these settings and different fio versions back to 2.0.15 but always
>>> the same empty output:
>>>
>>> [write]
>>> group_reporting=1
>>> numjobs=8
>>> ioengine=posixaio
>>> io_submit_mode=inline
>>> stonewall
>>> rw=write
>>> bs=32k
>>> time_based=1
>>> runtime=10
>>> filesize=64k
>>> directory=/tmp
>>> per_job_logs=1
>>> write_bw_log=write_bw
>>> write_iops_log=write_iops
>>>
>>> Updated the issue reported here:
>>>
>>> https://github.com/axboe/fio/issues/29
>>>
>>> Thank you for any ideas you may have!
>>
>> I think your issue is because you set filesize=64k. Your job basically
>> sets up 8 files of 64k each, then writes to them for 10 seconds. This
>> means that the fio main loop keeps re-entering for every 64k for each
>> thread. The bandwidth/iops is averaged over a window of 500msec by
>> default, and the main loop runs for much shorter than that since it only
>> does 64k each time. Hence you never get logged any entries.
>>
>> Now, it should work. If you comment out these two lines:
>>
>> memcpy(&td->bw_sample_time, &td->start, sizeof(td->start));
>> memcpy(&td->iops_sample_time, &td->start, sizeof(td->start));
>>
>> in backend.c around 1568/1569, then I suspect the logging should improve
>> for you. I'll have to see if we can safely do that without making other
>> changes, before committing a change like that.t
>
> Try the attached patch, we need to retain the stat block and byte counts
> too.

Just run current -git, I committed a similar patch.

-- 
Jens Axboe

Re: FIO creating empty latency log files

[DoubleDensity]

This worked! I am in your debt, it is extremely cool to have this
operational now.

Please let me know if there is anything I may do to help test or
validate this fix or otherwise repay the favor!

On Tue, Oct 27, 2015 at 8:30 PM, Jens Axboe <axboe@kernel.dk> wrote:
> On 10/28/2015 09:20 AM, Jens Axboe wrote:
>>
>> On 10/28/2015 06:13 AM, Jens Axboe wrote:
>>>
>>> On 10/28/2015 12:41 AM, Buttetsu Batou wrote:
>>>>
>>>> On 06/04/2015 05:09 PM, Reed Crowe wrote:
>>>>>
>>>>> Using this version of FIO:
>>>>> * io-threads
>>>>>      master
>>>>> rcrowe@rcrowe-desktop:~/fio_iothreads/fio$ ./fio --version
>>>>> fio-2.2.7-14-g00b2
>>>>>
>>>>> I have a job file which looks like this:
>>>>>
>>>>> [global]
>>>>> ioengine=libaio
>>>>> direct=1
>>>>> numjobs=1
>>>>> bs=4k
>>>>> iodepth=300
>>>>> rw=randwrite
>>>>> randrepeat=0
>>>>> io_submit_mode=offload
>>>>> rate_iops=8070
>>>>> time_based=1
>>>>> runtime=1m
>>>>>
>>>>> [slow_write]
>>>>> filename=/mnt/test1/testfile.io
>>>>> write_lat_log=/tmp/fio_lat
>>>>>
>>>>> And it produces empty files:
>>>>> -rw-r--r-- 1 root   root         0 Jun  4 14:34 fio_lat_clat.1.log
>>>>> -rw-r--r-- 1 root   root         0 Jun  4 14:34 fio_lat_lat.1.log
>>>>> -rw-r--r-- 1 root   root         0 Jun  4 14:34 fio_lat_slat.1.log
>>>>>
>>>>> What am I missing?
>>>>
>>>>
>>>> I am seeing this behavior in the latest release fio-2.2.10 and in
>>>> master fio-2.2.10-29-g8a68 but I am not using offload.
>>>>
>>>> Is anyone currently able to successfully generate log output? If so
>>>> could you share your fio version and your config?
>>>>
>>>> Here is the job file I am using at the moment.. have tried variations
>>>> on these settings and different fio versions back to 2.0.15 but always
>>>> the same empty output:
>>>>
>>>> [write]
>>>> group_reporting=1
>>>> numjobs=8
>>>> ioengine=posixaio
>>>> io_submit_mode=inline
>>>> stonewall
>>>> rw=write
>>>> bs=32k
>>>> time_based=1
>>>> runtime=10
>>>> filesize=64k
>>>> directory=/tmp
>>>> per_job_logs=1
>>>> write_bw_log=write_bw
>>>> write_iops_log=write_iops
>>>>
>>>> Updated the issue reported here:
>>>>
>>>> https://github.com/axboe/fio/issues/29
>>>>
>>>> Thank you for any ideas you may have!
>>>
>>>
>>> I think your issue is because you set filesize=64k. Your job basically
>>> sets up 8 files of 64k each, then writes to them for 10 seconds. This
>>> means that the fio main loop keeps re-entering for every 64k for each
>>> thread. The bandwidth/iops is averaged over a window of 500msec by
>>> default, and the main loop runs for much shorter than that since it only
>>> does 64k each time. Hence you never get logged any entries.
>>>
>>> Now, it should work. If you comment out these two lines:
>>>
>>> memcpy(&td->bw_sample_time, &td->start, sizeof(td->start));
>>> memcpy(&td->iops_sample_time, &td->start, sizeof(td->start));
>>>
>>> in backend.c around 1568/1569, then I suspect the logging should improve
>>> for you. I'll have to see if we can safely do that without making other
>>> changes, before committing a change like that.t
>>
>>
>> Try the attached patch, we need to retain the stat block and byte counts
>> too.
>
>
> Just run current -git, I committed a similar patch.
>
> --
> Jens Axboe
>

Re: FIO creating empty latency log files

[Jens Axboe]

On Tue, Oct 27 2015, DoubleDensity wrote:
> This worked! I am in your debt, it is extremely cool to have this
> operational now.
> 
> Please let me know if there is anything I may do to help test or
> validate this fix or otherwise repay the favor!

Glad it works! Just throw it through your regular testing, both things
that broke before and worked before. We just need more coverage testing,
that is all.

-- 
Jens Axboe