Formats for log files

Formats for log files

[Bill Hooper (whooper)]

Where can I find documentation for the format of the write_bw_log, write_iops_log, and write_lat_log output?

Bill Hooper
Micron

Re: Formats for log files

[Josh Carter]

Bill,

Format of entries is:

  time, rate/latency, data direction, block size

Time: in milliseconds. Bandwidth logs are usually 500 or 1000ms apart; that can be controlled by the config file with "bwavgtime=[x ms]".

Rate/latency: for bandwidth, this is in KB/sec. For latency, it's microseconds.

Data direction: 0 is read, 1 is write.

Block size: block size of IOs in bytes.

For those using R to analyze log files, I have some useful stuff here:

  https://github.com/joshcarter/fio_tools

In particular, /analysis/fio_log_parsers.R has read_bw_log() and read_lat_log() functions.

Best regards,
Josh

On Feb 15, 2012, at 2:42 PM, Bill Hooper (whooper) wrote:

> Where can I find documentation for the format of the write_bw_log, write_iops_log, and write_lat_log output?
> 
> Bill Hooper
> Micron
> --
> To unsubscribe from this list: send the line "unsubscribe fio" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

RE: Formats for log files

[Bill Hooper (whooper)]

Thanks for the information. I suspected that was the format. I do notice that I do not always have the block size in the log. I am using version 2.0 and will try a more recent version.

It appears that when I set the numjobs parameter the log files will contain the data from each job concatenated. I also notice that the times for each job is not synchronized between jobs. The question is how do I merge the data from each job to consolidate the data?

Bill Hooper
Micron

> -----Original Message-----
> From: fio-owner@vger.kernel.org [mailto:fio-owner@vger.kernel.org] On
> Behalf Of Josh Carter
> Sent: Wednesday, February 15, 2012 5:26 PM
> To: Bill Hooper (whooper); fio@vger.kernel.org
> Subject: Re: Formats for log files
> 
> Bill,
> 
> Format of entries is:
> 
>   time, rate/latency, data direction, block size
> 
> Time: in milliseconds. Bandwidth logs are usually 500 or 1000ms apart; that
> can be controlled by the config file with "bwavgtime=[x ms]".
> 
> Rate/latency: for bandwidth, this is in KB/sec. For latency, it's
> microseconds.
> 
> Data direction: 0 is read, 1 is write.
> 
> Block size: block size of IOs in bytes.
> 
> For those using R to analyze log files, I have some useful stuff here:
> 
>   https://github.com/joshcarter/fio_tools
> 
> In particular, /analysis/fio_log_parsers.R has read_bw_log() and
> read_lat_log() functions.
> 
> Best regards,
> Josh
> 
> On Feb 15, 2012, at 2:42 PM, Bill Hooper (whooper) wrote:
> 
> > Where can I find documentation for the format of the write_bw_log,
> write_iops_log, and write_lat_log output?
> >
> > Bill Hooper
> > Micron
> > --
> > To unsubscribe from this list: send the line "unsubscribe fio" in
> > the body of a message to majordomo@vger.kernel.org
> > More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 
> --
> To unsubscribe from this list: send the line "unsubscribe fio" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Formats for log files

[Josh Carter]

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

Hi Bill,

Looking at the code, I believe you're correct, the bandwidth logging for mixed loads isn't right. While read and write logs are kept separate, only one direction's log will get flushed on each interval. Instead, fio should flush both directions.

I'm attaching a patch. Jens: could you take a look at this? I've tested both mixed and single-direction workloads, seems to work fine.

Best regards,
Josh


[-- Attachment #2: 0001-Fix-bandwidth-logging-for-mixed-read-write-workloads.patch --]
[-- Type: application/octet-stream, Size: 1841 bytes --]

From 94e3fb2641d5aa2f3c12a021fd6e1ecf0595a8de Mon Sep 17 00:00:00 2001
From: Josh Carter <public@joshcarter.com>
Date: Thu, 16 Feb 2012 11:31:11 +0000
Subject: [PATCH] Fix bandwidth logging for mixed read/write workloads.

fio was maintaining separate read/write stats, but only one timer for
bw_avg_time. Whichever IO direction happened to cross the timer would
get its interval logged; the other data direction would not. Now both
ddir are logged each time we cross bw_avg_time.

Where intervals don't contain any activity in a given ddir, no log
entry is made.
---
 stat.c |   21 +++++++++++++++------
 1 files changed, 15 insertions(+), 6 deletions(-)

diff --git a/stat.c b/stat.c
index 7e3b979..462f9ba 100644
--- a/stat.c
+++ b/stat.c
@@ -1291,16 +1291,25 @@ void add_bw_sample(struct thread_data *td, enum fio_ddir ddir, unsigned int bs,
 	spent = mtime_since(&td->bw_sample_time, t);
 	if (spent < td->o.bw_avg_time)
 		return;
+	
+	/* 
+	 * Compute both read and write rates for the interval.
+	 */
+	for (ddir = DDIR_READ; ddir <= DDIR_WRITE; ddir++) {
+	    if (td->stat_io_bytes[ddir] == td->this_io_bytes[ddir])
+		continue; /* No entries for interval */
+	    
+	    rate = (td->this_io_bytes[ddir] - td->stat_io_bytes[ddir]) *
+		1000 / spent / 1024;
+	    add_stat_sample(&ts->bw_stat[ddir], rate);
 
-	rate = (td->this_io_bytes[ddir] - td->stat_io_bytes[ddir]) *
-			1000 / spent / 1024;
-	add_stat_sample(&ts->bw_stat[ddir], rate);
-
-	if (td->bw_log)
+	    if (td->bw_log)
 		add_log_sample(td, td->bw_log, rate, ddir, bs);
 
+	    td->stat_io_bytes[ddir] = td->this_io_bytes[ddir];
+	}
+
 	fio_gettime(&td->bw_sample_time, NULL);
-	td->stat_io_bytes[ddir] = td->this_io_bytes[ddir];
 }
 
 void add_iops_sample(struct thread_data *td, enum fio_ddir ddir,
-- 
1.7.7


[-- Attachment #3: Type: text/plain, Size: 2675 bytes --]



On Feb 16, 2012, at 11:51 AM, Bill Hooper (whooper) wrote:

> Thanks for the reply. I ended doing something similar to your script consolidate the jobs. If the job was a read only or write only I found that I can add together the jobs based on the timestamps. The resulting data give me a good representation of the totals across the intervals.
> 
> Unfortunately this all falls apart with mixed workloads. Have you done any analysis work with the log files produced by mixed workloads?
> 
> Bill
> ________________________________________
> From: Josh Carter [public@joshcarter.com]
> Sent: Thursday, February 16, 2012 10:41 AM
> To: Bill Hooper (whooper)
> Subject: Re: Formats for log files
> 
> Hi Bill,
> 
> The times across jobs are accurate -- it's all coming from the same clock. Say you've got 4 jobs, you'll indeed see the time go from 500-ish..end then hop back to 500-ish for the next job's log. The sample points won't be *exactly* the same, however. Job 1 might take a sample at 501ms, job 2 might not sample until 507ms. Fio samples when IOs are completed, so tests with longer-running IOs (like with large block sizes) will have more jitter.
> 
> All jobs are using the same clock, however, so it's valid to plot jobs against each other, or do some analysis with binning, etc.. You may need to post-process the log file, e.g. adding a column for the job number. Example (using Ruby):
> 
>    File.open("multi_job_test_bw-split.log", "w+") do |outfile|
>      File.open("multi_job_test_bw.log") do |infile|
>        job = 1
>        last_time = nil
> 
>        infile.each_line do |line|
>          time, rate, ddir, bs = line.chomp.split(',')
>          time = time.to_i
> 
>          # When time hops backwards, that means we're
>          # on the next job.
>          job += 1 if (last_time && time < last_time)
> 
>          outfile.puts "#{time},#{rate},#{rate},#{bs},#{job}"
>          last_time = time
>        end
>      end
>    end
> 
> I haven't seen empty block sizes in the log -- sounds like a bug.
> 
> Best regards,
> Josh
> 
> On Feb 16, 2012, at 10:33 AM, Bill Hooper (whooper) wrote:
> 
>> Thanks for the information. I suspected that was the format. I do notice that I do not always have the block size in the log. I am using version 2.0 and will try a more recent version.
>> 
>> It appears that when I set the numjobs parameter the log files will contain the data from each job concatenated. I also notice that the times for each job is not synchronized between jobs. The question is how do I merge the data from each job to consolidate the data?
>> 
>> Bill Hooper
>> Micron
> 

Re: Formats for log files

[Jens Axboe]

On 02/16/2012 08:46 PM, Josh Carter wrote:
> Hi Bill,
> 
> Looking at the code, I believe you're correct, the bandwidth logging
> for mixed loads isn't right. While read and write logs are kept
> separate, only one direction's log will get flushed on each interval.
> Instead, fio should flush both directions.
> 
> I'm attaching a patch. Jens: could you take a look at this? I've
> tested both mixed and single-direction workloads, seems to work fine.

Patch looks good, applied. Thanks!

-- 
Jens Axboe

RE: Formats for log files

[Bill Hooper (whooper)]

> -----Original Message-----
> From: fio-owner@vger.kernel.org [mailto:fio-owner@vger.kernel.org] On
> Behalf Of Jens Axboe
> Sent: Monday, February 20, 2012 1:08 AM
> To: Josh Carter
> Cc: fio@vger.kernel.org; Bill Hooper (whooper)
> Subject: Re: Formats for log files
> 
> On 02/16/2012 08:46 PM, Josh Carter wrote:
> > Hi Bill,
> >
> > Looking at the code, I believe you're correct, the bandwidth logging
> > for mixed loads isn't right. While read and write logs are kept
> > separate, only one direction's log will get flushed on each interval.
> > Instead, fio should flush both directions.
> >
> > I'm attaching a patch. Jens: could you take a look at this? I've
> > tested both mixed and single-direction workloads, seems to work fine.
> 
> Patch looks good, applied. Thanks!
> 
> --
> Jens Axboe
> 
> --
> To unsubscribe from this list: send the line "unsubscribe fio" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

I did test the patch from Josh and it appears to work correctly. I noticed that the issue also exists in the iops and latency logging. I was able to use the code Josh provided to correct the iops logging. I did not spend any time attempting to correct the latency logging issue, although I suspect the fix is similar to the others. Could someone take a deeper look into this?

Bill Hooper
Micron

Re: Formats for log files

[Jens Axboe]

On 2012-02-20 18:17, Bill Hooper (whooper) wrote:
>> -----Original Message-----
>> From: fio-owner@vger.kernel.org [mailto:fio-owner@vger.kernel.org] On
>> Behalf Of Jens Axboe
>> Sent: Monday, February 20, 2012 1:08 AM
>> To: Josh Carter
>> Cc: fio@vger.kernel.org; Bill Hooper (whooper)
>> Subject: Re: Formats for log files
>>
>> On 02/16/2012 08:46 PM, Josh Carter wrote:
>>> Hi Bill,
>>>
>>> Looking at the code, I believe you're correct, the bandwidth logging
>>> for mixed loads isn't right. While read and write logs are kept
>>> separate, only one direction's log will get flushed on each interval.
>>> Instead, fio should flush both directions.
>>>
>>> I'm attaching a patch. Jens: could you take a look at this? I've
>>> tested both mixed and single-direction workloads, seems to work fine.
>>
>> Patch looks good, applied. Thanks!
>>
>> --
>> Jens Axboe
>>
>> --
>> To unsubscribe from this list: send the line "unsubscribe fio" in
>> the body of a message to majordomo@vger.kernel.org
>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 
> I did test the patch from Josh and it appears to work correctly. I
> noticed that the issue also exists in the iops and latency logging. I
> was able to use the code Josh provided to correct the iops logging. I
> did not spend any time attempting to correct the latency logging
> issue, although I suspect the fix is similar to the others. Could
> someone take a deeper look into this?

Can you send what you have? I can fix up the rest.

-- 
Jens Axboe

Re: Formats for log files

[Jens Axboe]

On 2012-02-20 19:57, Jens Axboe wrote:
> On 2012-02-20 18:17, Bill Hooper (whooper) wrote:
>>> -----Original Message-----
>>> From: fio-owner@vger.kernel.org [mailto:fio-owner@vger.kernel.org] On
>>> Behalf Of Jens Axboe
>>> Sent: Monday, February 20, 2012 1:08 AM
>>> To: Josh Carter
>>> Cc: fio@vger.kernel.org; Bill Hooper (whooper)
>>> Subject: Re: Formats for log files
>>>
>>> On 02/16/2012 08:46 PM, Josh Carter wrote:
>>>> Hi Bill,
>>>>
>>>> Looking at the code, I believe you're correct, the bandwidth logging
>>>> for mixed loads isn't right. While read and write logs are kept
>>>> separate, only one direction's log will get flushed on each interval.
>>>> Instead, fio should flush both directions.
>>>>
>>>> I'm attaching a patch. Jens: could you take a look at this? I've
>>>> tested both mixed and single-direction workloads, seems to work fine.
>>>
>>> Patch looks good, applied. Thanks!
>>>
>>> --
>>> Jens Axboe
>>>
>>> --
>>> To unsubscribe from this list: send the line "unsubscribe fio" in
>>> the body of a message to majordomo@vger.kernel.org
>>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>>
>> I did test the patch from Josh and it appears to work correctly. I
>> noticed that the issue also exists in the iops and latency logging. I
>> was able to use the code Josh provided to correct the iops logging. I
>> did not spend any time attempting to correct the latency logging
>> issue, although I suspect the fix is similar to the others. Could
>> someone take a deeper look into this?
> 
> Can you send what you have? I can fix up the rest.

I committed a fix for the IOPS logging. The latency logging is per-IO,
so it should work fine as-is.

-- 
Jens Axboe