bug in logging code?

I've been playing around with usng the various write_*_log options in fio to record run statistics. What I'm finding is that some of the logs have malformed lines in them. The following snippet is from the bw log:

811820, 12263, 0, 4194304
812619, 35929, 0, 4194304
818437, 8448, 0, 419430, 4194304
1256299, 160627, 0, 4194304
1256831, 154274, 0, 4194304

Notice that the malformed line appears to be a partial write that gets truncated. The fio command being used to run the tests is autogenerated, so job files aren't used. here's the one that created the above log snippet:

/home/nhm/bin/fio
--rw=read
--ioengine=libaio
--runtime=7200
--ramp_time=0
--numjobs=1
--direct=1
--bs=4194304B
--iodepth=16
--size=9216M --write_iops_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra-00004096/client_ra-00000128/op_size-04194304/concurrent_procs-008/iodepth-016/read/output

--write_bw_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra-00004096/client_ra-00000128/op_size-04194304/concurrent_procs-008/iodepth-016/read/output

--write_lat_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra-00004096/client_ra-00000128/op_size-04194304/concurrent_procs-008/iodepth-016/read/output

--time_based
--name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-0 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-1 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-2 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-3 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-4 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-5 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-6 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-7

The --numjobs=1 line should be removed, but I believe it gets overridden anyway with multiple name parameters. I wonder if having multiple name parameters (ie multiple fio processes) is causing those processes to all try to write to the same log files, potentially at the same time? Any thoughts would be much appreicated!

Quoted 44 lines · Mark Nelson

I've been playing around with usng the various write_*_log options in fio to record run statistics. What I'm finding is that some of the logs have malformed lines in them. The following snippet is from the bw log:

811820, 12263, 0, 4194304
812619, 35929, 0, 4194304
818437, 8448, 0, 419430, 4194304
1256299, 160627, 0, 4194304
1256831, 154274, 0, 4194304

Notice that the malformed line appears to be a partial write that gets truncated. The fio command being used to run the tests is autogenerated, so job files aren't used. here's the one that created the above log snippet:

/home/nhm/bin/fio
--rw=read
--ioengine=libaio
--runtime=7200
--ramp_time=0
--numjobs=1
--direct=1
--bs=4194304B
--iodepth=16
--size=9216M --write_iops_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra-00004096/client_ra-00000128/op_size-04194304/concurrent_procs-008/iodepth-016/read/output

--write_bw_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra-00004096/client_ra-00000128/op_size-04194304/concurrent_procs-008/iodepth-016/read/output

--write_lat_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra-00004096/client_ra-00000128/op_size-04194304/concurrent_procs-008/iodepth-016/read/output

--time_based
--name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-0 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-1 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-2 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-3 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-4 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-5 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-6 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-7

Quoted 5 lines

The --numjobs=1 line should be removed, but I believe it gets overridden anyway with multiple name parameters. I wonder if having multiple name parameters (ie multiple fio processes) is causing those processes to all try to write to the same log files, potentially at the same time? Any thoughts would be much appreicated!

What version of fio are you running?

Quoted 54 lines · Jens Axboe

Quoted 52 lines · Mark Nelson

I've been playing around with usng the various write_*_log options in fio to record run statistics. What I'm finding is that some of the logs have malformed lines in them. The following snippet is from the bw log:

811820, 12263, 0, 4194304
812619, 35929, 0, 4194304
818437, 8448, 0, 419430, 4194304
1256299, 160627, 0, 4194304
1256831, 154274, 0, 4194304

Notice that the malformed line appears to be a partial write that gets truncated. The fio command being used to run the tests is autogenerated, so job files aren't used. here's the one that created the above log snippet:

/home/nhm/bin/fio
--rw=read
--ioengine=libaio
--runtime=7200
--ramp_time=0
--numjobs=1
--direct=1
--bs=4194304B
--iodepth=16
--size=9216M --write_iops_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra-00004096/client_ra-00000128/op_size-04194304/concurrent_procs-008/iodepth-016/read/output

--write_bw_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra-00004096/client_ra-00000128/op_size-04194304/concurrent_procs-008/iodepth-016/read/output

--write_lat_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra-00004096/client_ra-00000128/op_size-04194304/concurrent_procs-008/iodepth-016/read/output

--time_based
--name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-0 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-1 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-2 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-3 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-4 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-5 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-6 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-7

The --numjobs=1 line should be removed, but I believe it gets overridden anyway with multiple name parameters. I wonder if having multiple name parameters (ie multiple fio processes) is causing those processes to all try to write to the same log files, potentially at the same time? Any thoughts would be much appreicated!

Quoted 2 lines

What version of fio are you running?

f42557f (ie master from yesterday) with a slightly different fix for the basename issues that just got resolved.

I can verify now that running fio with a single --name flag appears to generate logs without malformated lines.

Quoted 62 lines · Mark Nelson

Quoted 61 lines · Jens Axboe

Quoted 59 lines · Mark Nelson

I've been playing around with usng the various write_*_log options in fio to record run statistics. What I'm finding is that some of the logs
have malformed lines in them. The following snippet is from the bw log:

811820, 12263, 0, 4194304
812619, 35929, 0, 4194304
818437, 8448, 0, 419430, 4194304
1256299, 160627, 0, 4194304
1256831, 154274, 0, 4194304

Notice that the malformed line appears to be a partial write that gets truncated. The fio command being used to run the tests is autogenerated, so job files aren't used. here's the one that created the above log snippet:

/home/nhm/bin/fio
--rw=read
--ioengine=libaio
--runtime=7200
--ramp_time=0
--numjobs=1
--direct=1
--bs=4194304B
--iodepth=16
--size=9216M --write_iops_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra-00004096/client_ra-00000128/op_size-04194304/concurrent_procs-008/iodepth-016/read/output

--write_bw_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra-00004096/client_ra-00000128/op_size-04194304/concurrent_procs-008/iodepth-016/read/output

--write_lat_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra-00004096/client_ra-00000128/op_size-04194304/concurrent_procs-008/iodepth-016/read/output

--time_based
--name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-0 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-1 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-2 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-3 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-4 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-5 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-6 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-7

The --numjobs=1 line should be removed, but I believe it gets overridden
anyway with multiple name parameters. I wonder if having multiple name parameters (ie multiple fio processes) is causing those processes to all
try to write to the same log files, potentially at the same time? Any thoughts would be much appreicated!

Quoted 8 lines

Quoted 2 lines

What version of fio are you running?

f42557f (ie master from yesterday) with a slightly different fix for the basename issues that just got resolved.

I can verify now that running fio with a single --name flag appears to generate logs without malformated lines.

OK, I'll take a look, We should already be serializing the writing to the same log files, but your example definitely looks like we are not.

BTW, the numjobs option applies to each --name section. Just to clear that up from your original email. So you really get numjobs * name_sections running.

Quoted 79 lines · Jens Axboe

Quoted 66 lines · Mark Nelson

Quoted 65 lines · Jens Axboe

Quoted 63 lines · Mark Nelson

I've been playing around with usng the various write_*_log options in fio to record run statistics. What I'm finding is that some of the logs
have malformed lines in them. The following snippet is from the bw log:

811820, 12263, 0, 4194304
812619, 35929, 0, 4194304
818437, 8448, 0, 419430, 4194304
1256299, 160627, 0, 4194304
1256831, 154274, 0, 4194304

Notice that the malformed line appears to be a partial write that gets truncated. The fio command being used to run the tests is autogenerated, so job files aren't used. here's the one that created the above log snippet:

/home/nhm/bin/fio
--rw=read
--ioengine=libaio
--runtime=7200
--ramp_time=0
--numjobs=1
--direct=1
--bs=4194304B
--iodepth=16
--size=9216M --write_iops_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra-00004096/client_ra-00000128/op_size-04194304/concurrent_procs-008/iodepth-016/read/output

--write_bw_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra-00004096/client_ra-00000128/op_size-04194304/concurrent_procs-008/iodepth-016/read/output

--write_lat_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra-00004096/client_ra-00000128/op_size-04194304/concurrent_procs-008/iodepth-016/read/output

--time_based
--name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-0 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-1 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-2 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-3 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-4 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-5 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-6 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-7

The --numjobs=1 line should be removed, but I believe it gets overridden
anyway with multiple name parameters. I wonder if having multiple name
parameters (ie multiple fio processes) is causing those processes to all
try to write to the same log files, potentially at the same time? Any thoughts would be much appreicated!

Quoted 8 lines

Quoted 2 lines

What version of fio are you running?

f42557f (ie master from yesterday) with a slightly different fix for the basename issues that just got resolved.

I can verify now that running fio with a single --name flag appears to generate logs without malformated lines.

OK, I'll take a look, We should already be serializing the writing to the same log files, but your example definitely looks like we are not.

Quoted 3 lines

BTW, the numjobs option applies to each --name section. Just to clear that up from your original email. So you really get numjobs * name_sections running.

Aha, thanks for clearing that up!

Is github the right place to create new issues? If so, want me to create one for this?

Quoted 90 lines · Mark Nelson

Quoted 88 lines · Jens Axboe

Quoted 74 lines · Mark Nelson

Quoted 70 lines · Jens Axboe

Quoted 59 lines · Mark Nelson

I've been playing around with usng the various write_*_log options in fio to record run statistics. What I'm finding is that some of the logs
have malformed lines in them. The following snippet is from the bw log:

811820, 12263, 0, 4194304
812619, 35929, 0, 4194304
818437, 8448, 0, 419430, 4194304
1256299, 160627, 0, 4194304
1256831, 154274, 0, 4194304

Notice that the malformed line appears to be a partial write that gets
truncated. The fio command being used to run the tests is autogenerated, so job files aren't used. here's the one that created the above log snippet:

/home/nhm/bin/fio
--rw=read
--ioengine=libaio
--runtime=7200
--ramp_time=0
--numjobs=1
--direct=1
--bs=4194304B
--iodepth=16
--size=9216M --write_iops_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra-00004096/client_ra-00000128/op_size-04194304/concurrent_procs-008/iodepth-016/read/output

--write_bw_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra-00004096/client_ra-00000128/op_size-04194304/concurrent_procs-008/iodepth-016/read/output

--write_lat_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra-00004096/client_ra-00000128/op_size-04194304/concurrent_procs-008/iodepth-016/read/output

--time_based
--name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-0 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-1 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-2 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-3 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-4 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-5 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-6 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-7

Quoted 9 lines

The --numjobs=1 line should be removed, but I believe it gets overridden
anyway with multiple name parameters. I wonder if having multiple name
parameters (ie multiple fio processes) is causing those processes to all
try to write to the same log files, potentially at the same time? Any
thoughts would be much appreicated!

Quoted 2 lines

What version of fio are you running?

Quoted 6 lines

f42557f (ie master from yesterday) with a slightly different fix for the
basename issues that just got resolved.

I can verify now that running fio with a single --name flag appears to generate logs without malformated lines.

OK, I'll take a look, We should already be serializing the writing to the same log files, but your example definitely looks like we are not.

BTW, the numjobs option applies to each --name section. Just to clear that up from your original email. So you really get numjobs * name_sections running.

Quoted 4 lines

Aha, thanks for clearing that up!

Is github the right place to create new issues? If so, want me to create one for this?

Sure, you can go ahead and do that.

I'm puzzled by this report. The writeout of the logs is fully serialized, there should be no interleaving. Looking at your output, it's definitely either the output from two jobs, or mangled output from just one job. The corrupted line is at time 818437, and the next line is much further ahead. Normally you would expect to see:

500, some-bw, 0, blocksize <- job X
1000, some-bw, 0, blocksize
[...]
end-time, some-bw, 0, blocksize <- last entry from job X
500, some-bw, 0, blocksize <- job Y now starts

Note that the log writing always appends. Did you possibly have this half-done files in that location from a previous run?

Quoted 96 lines · Jens Axboe

Quoted 95 lines · Mark Nelson

Quoted 93 lines · Jens Axboe

Quoted 79 lines · Mark Nelson

Quoted 75 lines · Jens Axboe

Quoted 64 lines · Mark Nelson

I've been playing around with usng the various write_*_log options in
fio to record run statistics. What I'm finding is that some of the logs
have malformed lines in them. The following snippet is from the bw log:

811820, 12263, 0, 4194304
812619, 35929, 0, 4194304
818437, 8448, 0, 419430, 4194304
1256299, 160627, 0, 4194304
1256831, 154274, 0, 4194304

Notice that the malformed line appears to be a partial write that gets
truncated. The fio command being used to run the tests is autogenerated, so job files aren't used. here's the one that created
the above log snippet:

/home/nhm/bin/fio
--rw=read
--ioengine=libaio
--runtime=7200
--ramp_time=0
--numjobs=1
--direct=1
--bs=4194304B
--iodepth=16
--size=9216M --write_iops_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra-00004096/client_ra-00000128/op_size-04194304/concurrent_procs-008/iodepth-016/read/output

--write_bw_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra-00004096/client_ra-00000128/op_size-04194304/concurrent_procs-008/iodepth-016/read/output

--write_lat_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra-00004096/client_ra-00000128/op_size-04194304/concurrent_procs-008/iodepth-016/read/output

--time_based
--name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-0 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-1 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-2 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-3 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-4 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-5 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-6 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-7

Quoted 9 lines

The --numjobs=1 line should be removed, but I believe it gets overridden
anyway with multiple name parameters. I wonder if having multiple name
parameters (ie multiple fio processes) is causing those processes to all
try to write to the same log files, potentially at the same time? Any
thoughts would be much appreicated!

Quoted 2 lines

What version of fio are you running?

Quoted 6 lines

f42557f (ie master from yesterday) with a slightly different fix for the
basename issues that just got resolved.

I can verify now that running fio with a single --name flag appears to generate logs without malformated lines.

OK, I'll take a look, We should already be serializing the writing to the same log files, but your example definitely looks like we are not.

BTW, the numjobs option applies to each --name section. Just to clear that up from your original email. So you really get numjobs * name_sections running.

Quoted 6 lines

Quoted 4 lines

Aha, thanks for clearing that up!

Is github the right place to create new issues? If so, want me to create one for this?

Sure, you can go ahead and do that.

Actually, I'm going to wait after hearing your response below!

Quoted 13 lines

I'm puzzled by this report. The writeout of the logs is fully serialized, there should be no interleaving. Looking at your output, it's definitely either the output from two jobs, or mangled output from just one job. The corrupted line is at time 818437, and the next line is much further ahead. Normally you would expect to see:

500, some-bw, 0, blocksize <- job X
1000, some-bw, 0, blocksize
[...]
end-time, some-bw, 0, blocksize <- last entry from job X
500, some-bw, 0, blocksize <- job Y now starts

Quoted 2 lines

Note that the log writing always appends. Did you possibly have this half-done files in that location from a previous run?

I think this is possible. My tool is supposed to clean out old tmp directories but it was broken (and unnoticed because all other output files were getting overwritten each time). Guess I should prioritize a long-standing plan to use UUIDs for all tests/directories to make this kind of bug more obvious. :)

Quoted 140 lines · Mark Nelson

Quoted 110 lines · Jens Axboe

Quoted 108 lines · Mark Nelson

Quoted 105 lines · Jens Axboe

Quoted 88 lines · Mark Nelson

Quoted 83 lines · Jens Axboe

Quoted 70 lines · Mark Nelson

I've been playing around with usng the various write_*_log options in
fio to record run statistics. What I'm finding is that some of the logs
have malformed lines in them. The following snippet is from the bw log:

811820, 12263, 0, 4194304
812619, 35929, 0, 4194304
818437, 8448, 0, 419430, 4194304
1256299, 160627, 0, 4194304
1256831, 154274, 0, 4194304

Notice that the malformed line appears to be a partial write that gets
truncated. The fio command being used to run the tests is autogenerated, so job files aren't used. here's the one that created
the above log snippet:

/home/nhm/bin/fio
--rw=read
--ioengine=libaio
--runtime=7200
--ramp_time=0
--numjobs=1
--direct=1
--bs=4194304B
--iodepth=16
--size=9216M --write_iops_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra- 00004096/client_ra-00000128/op_size-04194304/concurrent_ procs-008/iodepth-016/read/output

--write_bw_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra-00004096/ client_ra-00000128/op_size-04194304/concurrent_procs-008/ iodepth-016/read/output

--write_lat_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra-00004096/ client_ra-00000128/op_size-04194304/concurrent_procs-008/ iodepth-016/read/output

--time_based
--name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-0 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-1 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-2 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-3 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-4 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-5 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-6 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-7

Quoted 10 lines

The --numjobs=1 line should be removed, but I believe it gets overridden
anyway with multiple name parameters. I wonder if having multiple name
parameters (ie multiple fio processes) is causing those processes to all
try to write to the same log files, potentially at the same time? Any
thoughts would be much appreicated!

Quoted 3 lines

What version of fio are you running?

Quoted 7 lines

f42557f (ie master from yesterday) with a slightly different fix for the
basename issues that just got resolved.

I can verify now that running fio with a single --name flag appears to generate logs without malformated lines.

OK, I'll take a look, We should already be serializing the writing to the same log files, but your example definitely looks like we are not.

BTW, the numjobs option applies to each --name section. Just to clear that up from your original email. So you really get numjobs * name_sections running.

Quoted 8 lines

Quoted 5 lines

Aha, thanks for clearing that up!

Is github the right place to create new issues? If so, want me to create one for this?

Sure, you can go ahead and do that.

Actually, I'm going to wait after hearing your response below!

Quoted 6 lines

I'm puzzled by this report. The writeout of the logs is fully serialized, there should be no interleaving. Looking at your output, it's definitely either the output from two jobs, or mangled output from just one job. The corrupted line is at time 818437, and the next line is much further ahead. Normally you would expect to see:

Quoted 9 lines

500, some-bw, 0, blocksize <- job X
1000, some-bw, 0, blocksize
[...]
end-time, some-bw, 0, blocksize <- last entry from job X
500, some-bw, 0, blocksize <- job Y now starts

Note that the log writing always appends. Did you possibly have this half-done files in that location from a previous run?

Quoted 6 lines

I think this is possible. My tool is supposed to clean out old tmp directories but it was broken (and unnoticed because all other output files were getting overwritten each time). Guess I should prioritize a long-standing plan to use UUIDs for all tests/directories to make this kind of bug more obvious. :)

That makes me feel better, and does make a lot more sense! But since I was looking at this code anyway, I could not help but be annoyed at how we serialize all the logs when writing them out. If the logs are big, it can take a long time per log. So I added some code to only lock per file instead. This means that if no log sharing is happening, we'll write all 5 logs in parallel. A quick test here with a 5s null run which resulted in 4 logs (two tiny, the bw and iops log) reduced the log writing from 26 seconds to 14 seconds. And that was just two 18M logs.

So even if we didn't have a real bug here, at least the logging is now substantially faster.

--
Jens Axboe

--
To unsubscribe from this list: send the line "unsubscribe fio" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Another reduction idea would be to open/read/write io logs via gz frontend, defaulting to regular I/O where compression is either unavailable or undesired. Should be a big deal with large logs, which is often the case. I planned to take on this in my spare time couple of months back, but it's still where it was at that time :(.

Quoted 124 lines · Mark Nelson

Quoted 101 lines · Jens Axboe

Quoted 100 lines · Mark Nelson

Quoted 98 lines · Jens Axboe

Quoted 83 lines · Mark Nelson

Quoted 79 lines · Jens Axboe

Quoted 67 lines · Mark Nelson

I've been playing around with usng the various write_*_log options in
fio to record run statistics. What I'm finding is that some of the logs
have malformed lines in them. The following snippet is from the bw log:

811820, 12263, 0, 4194304
812619, 35929, 0, 4194304
818437, 8448, 0, 419430, 4194304
1256299, 160627, 0, 4194304
1256831, 154274, 0, 4194304

Notice that the malformed line appears to be a partial write that gets
truncated. The fio command being used to run the tests is autogenerated, so job files aren't used. here's the one that created
the above log snippet:

/home/nhm/bin/fio
--rw=read
--ioengine=libaio
--runtime=7200
--ramp_time=0
--numjobs=1
--direct=1
--bs=4194304B
--iodepth=16
--size=9216M --write_iops_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra-00004096/client_ra-00000128/op_size-04194304/concurrent_procs-008/iodepth-016/read/output

--write_bw_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra-00004096/client_ra-00000128/op_size-04194304/concurrent_procs-008/iodepth-016/read/output

--write_lat_log=/tmp/cbt/ceph/kvmrbdfio/osd_ra-00004096/client_ra-00000128/op_size-04194304/concurrent_procs-008/iodepth-016/read/output

--time_based
--name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-0 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-1 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-2 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-3 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-4 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-5 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-6 --name=/srv/rbdfio-hostname -s-0/cbt-kvmrbdfio-7

Quoted 10 lines

The --numjobs=1 line should be removed, but I believe it gets overridden
anyway with multiple name parameters. I wonder if having multiple name
parameters (ie multiple fio processes) is causing those processes to
all
try to write to the same log files, potentially at the same time? Any
thoughts would be much appreicated!

Quoted 2 lines

What version of fio are you running?

Quoted 7 lines

f42557f (ie master from yesterday) with a slightly different fix for the
basename issues that just got resolved.

I can verify now that running fio with a single --name flag appears to
generate logs without malformated lines.

OK, I'll take a look, We should already be serializing the writing to the same log files, but your example definitely looks like we are not.

BTW, the numjobs option applies to each --name section. Just to clear that up from your original email. So you really get numjobs * name_sections running.

Quoted 6 lines

Quoted 4 lines

Aha, thanks for clearing that up!

Is github the right place to create new issues? If so, want me to create one for this?

Sure, you can go ahead and do that.

Actually, I'm going to wait after hearing your response below!

Quoted 13 lines

I'm puzzled by this report. The writeout of the logs is fully serialized, there should be no interleaving. Looking at your output, it's definitely either the output from two jobs, or mangled output from just one job. The corrupted line is at time 818437, and the next line is much further ahead. Normally you would expect to see:

500, some-bw, 0, blocksize <- job X
1000, some-bw, 0, blocksize
[...]
end-time, some-bw, 0, blocksize <- last entry from job X
500, some-bw, 0, blocksize <- job Y now starts

Quoted 8 lines

Quoted 2 lines

Note that the log writing always appends. Did you possibly have this half-done files in that location from a previous run?

I think this is possible. My tool is supposed to clean out old tmp directories but it was broken (and unnoticed because all other output files were getting overwritten each time). Guess I should prioritize a long-standing plan to use UUIDs for all tests/directories to make this kind of bug more obvious. :)

That makes me feel better, and does make a lot more sense! But since I was looking at this code anyway, I could not help but be annoyed at how we serialize all the logs when writing them out. If the logs are big, it can take a long time per log. So I added some code to only lock per file instead. This means that if no log sharing is happening, we'll write all 5 logs in parallel. A quick test here with a 5s null run which resulted in 4 logs (two tiny, the bw and iops log) reduced the log writing from 26 seconds to 14 seconds. And that was just two 18M logs.

So even if we didn't have a real bug here, at least the logging is now substantially faster.