fio icon indicating copy to clipboard operation
fio copied to clipboard

Published 20 hours ago • verified publisher icon axboe

In client mode per_job_logs=0 only records one job's data in .log file

Open derek-wan opened this issue 5 years ago • 11 comments
trafficstars

When using fio 3.20 in server/client mode with per_job_logs=0, fio only records the information of one job in logs like the write_iops_log whereas the correct thing happens in non-client mode.

# issue1032.fio
[global]
per_job_logs=0
ioengine=null

[issue1032]
size=1M
numjobs=2
write_iops_log=issue1032

$ rm -f issue1032_*
$ ./fio --minimal issue1032.fio
[...]
$ wc -l issue1032_iops.log 
     512 issue1032_iops.log
$ ./fio --server &
[...]
$ rm -f issue1032_*
$ ./fio --minimal --client=localhost issue1032.fio
[...]
$ wc -l issue1032_iops.log.localhost 
     256 issue1032_iops.log.localhost

derek-wan avatar Jul 03 '20 02:07 derek-wan

Hello @derek-wan,

Are you really using fio 3.2.0? If so can you reproduce the problem with the latest fio because we (upstream) only support the latest fio. See https://github.com/axboe/fio/releases for which version we're up to.

sitsofe avatar Jul 03 '20 06:07 sitsofe

Hello @sitsofe ,

Yes，I use latest fio release 3.2.0，FIO version information is as follows: root@wz02:/jetlake_test# fio --version fio-3.20

Attach write_xx_log: write_log_20200707.tar.gz

derek-wan avatar Jul 07 '20 03:07 derek-wan

Yes，I use latest fio release 3.2.0

I see you meant 3.20 (the absence of the extra point is important :-) ) Thanks for following up.

sitsofe avatar Jul 07 '20 06:07 sitsofe

@derek-wan in that case can you cut your job file down such that it contains the bare minimum options that reproduce the file? Also can you make all parameters static and not use environment variables so the jobfile is standalone. Thanks!

sitsofe avatar Jul 07 '20 06:07 sitsofe

(e.g. does a job like:

[global]
group_reporting

[small]
rw=write
size=1M

reproduce the problem?)

sitsofe avatar Jul 07 '20 06:07 sitsofe

Hello @derek-wan,

Are you really using fio 3.2.0? If so can you reproduce the problem with the latest fio because we (upstream) only support the latest fio. See https://github.com/axboe/fio/releases for which version we're up to.

derek-wan avatar Jul 07 '20 09:07 derek-wan

Hello @sitsofe

The simplified job file is as follows: [global] directory=/jetlake_test per_job_logs=0 group_reporting

[small] rw=write size=10M numjobs=16 iodepth=8 write_iops_log=write

The command is as follows: /usr/local/bin/fio --client=192.168.1.188 job.file

The results are as follows： root@wz02:/jetlake_test# /usr/local/bin/fio --client=192.168.1.188 job.file hostname=wz02, be=0, 64-bit, os=Linux, arch=x86-64, fio=fio-3.20, flags=0 small: (g=0): rw=write, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=psync, iodepth=8 ... Starting 16 processes small: Laying out IO file (1 file / 10MiB) small: Laying out IO file (1 file / 10MiB) small: Laying out IO file (1 file / 10MiB) small: Laying out IO file (1 file / 10MiB) small: Laying out IO file (1 file / 10MiB) small: Laying out IO file (1 file / 10MiB) small: Laying out IO file (1 file / 10MiB) small: Laying out IO file (1 file / 10MiB) small: Laying out IO file (1 file / 10MiB) small: Laying out IO file (1 file / 10MiB) small: Laying out IO file (1 file / 10MiB) small: Laying out IO file (1 file / 10MiB) small: Laying out IO file (1 file / 10MiB) small: Laying out IO file (1 file / 10MiB) small: Laying out IO file (1 file / 10MiB) small: Laying out IO file (1 file / 10MiB) 6 (f=16) small: (groupid=0, jobs=16): err= 0: pid=5885: Tue Jul 7 09:39:54 2020 write: IOPS=129k, BW=503MiB/s (528MB/s)(160MiB/318msec); 0 zone resets clat (usec): min=46, max=817, avg=117.82, stdev=53.14 lat (usec): min=47, max=818, avg=118.10, stdev=53.16 clat percentiles (usec): | 1.00th=[ 60], 5.00th=[ 68], 10.00th=[ 73], 20.00th=[ 81], | 30.00th=[ 88], 40.00th=[ 95], 50.00th=[ 103], 60.00th=[ 113], | 70.00th=[ 127], 80.00th=[ 147], 90.00th=[ 182], 95.00th=[ 221], | 99.00th=[ 318], 99.50th=[ 367], 99.90th=[ 482], 99.95th=[ 537], | 99.99th=[ 652] iops : min= 16, max= 16, avg=16.00, stdev= 0.00, samples=40960 lat (usec) : 50=0.01%, 100=47.19%, 250=49.74%, 500=2.99%, 750=0.07% lat (usec) : 1000=0.01% cpu : usr=2.26%, sys=10.13%, ctx=41188, majf=0, minf=549 IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued rwts: total=0,40960,0,0 short=0,0,0,0 dropped=0,0,0,0 latency : target=0, window=0, percentile=100.00%, depth=8

Run status group 0 (all jobs): WRITE: bw=503MiB/s (528MB/s), 503MiB/s-503MiB/s (528MB/s-528MB/s), io=160MiB (168MB), run=318-318msec root@wz02:/jetlake_test# ls 192.168.1.188.small.0.0 192.168.1.188.small.11.0 192.168.1.188.small.14.0 192.168.1.188.small.3.0 192.168.1.188.small.6.0 192.168.1.188.small.9.0 192.168.1.188.small.1.0 192.168.1.188.small.12.0 192.168.1.188.small.15.0 192.168.1.188.small.4.0 192.168.1.188.small.7.0 job.file 192.168.1.188.small.10.0 192.168.1.188.small.13.0 192.168.1.188.small.2.0 192.168.1.188.small.5.0 192.168.1.188.small.8.0 write_iops.log.192.168.1.188

write_iops_log20200707.tar.gz

derek-wan avatar Jul 07 '20 09:07 derek-wan

Hi @derek-wan . Initially you mentioned the group_reporting wasn't valid could you elaborate on just how it is not valid?

sitsofe avatar Jul 07 '20 16:07 sitsofe

Hi @derek-wan . Initially you mentioned the group_reporting wasn't valid could you elaborate on just how it is not valid?

Using group_ Reporting, when numjob is 16, the parameter write_ iops_ Log generated file write_ iops.log.192.168.1.188 will contain the raw data of all jobs, but the file actually contains data of only one job。
The file write_ iops.log.192.168.1.188 is packaged as write_ iops_ log20200707. tar.gz。

derek-wan avatar Jul 08 '20 01:07 derek-wan

Is there any progress on this issue? I meet the same problem for this parameter.

[root@localhost AutoDiskTest]# fio -v
fio-3.16
  1. fio command is {0} -direct=1 -filename={1} -iodepth={2} -bs={3} -rw={4} -runtime={5} --numjobs={6} --time_based --group_reporting --thread -name={7} -ioengine={8} --per_job_logs=0 --write_iops_log={9} --log_avg_msec=2000 > {9}.log
  2. fio result files: 1. sdb_libaio_randread_128k_32_4_iops.log, 2. sdb_libaio_randread_128k_32_4.log

sdb_libaio_randread_128k_32_4_iops.log content

2000, 40, 0, 0 4000, 46, 0, 0 6000, 47, 0, 0 8000, 48, 0, 0 10000, 45, 0, 0 12000, 44, 0, 0 14000, 44, 0, 0 ... 2000, 48, 0, 0 4000, 47, 0, 0 6000, 41, 0, 0 8000, 48, 0, 0 10000, 45, 0, 0 12001, 44, 0, 0 14001, 46, 0, 0 16000, 45, 0, 0 18000, 45, 0, 0 20000, 44, 0, 0 ...

use --per_job_logs=0, four jobs iops record in one file, But not 4 jobs IOPS summation. Pls help make sure whether have a parameter to record all jobs' iops summation. I just want to use fio2gnuplot to gnerate png.

hualong1009 avatar Apr 30 '21 02:04 hualong1009

@hualong1009 I'm not aware of anyone actively working on this but would you like to have a try?

sitsofe avatar Apr 30 '21 05:04 sitsofe

still encounter this issue on 3.35

(2023.10.06)(10:21 AM)[BASH]
jqt@repo:[~/performance-deltas] $
>> fio --version
fio-3.35
(2023.10.06)(10:22 AM)[BASH]
jqt@repo:[~/performance-deltas] $
>> cat seq-read.json | grep -A 20 128KQ32
      "jobname" : "128KQ32",
      "groupid" : 50,
      "error" : 0,
      "eta" : 0,
      "elapsed" : 101460,
      "job options" : {
        "numjobs" : "8",
        "iodepth" : "4",
        "bs" : "128K",
        "ba" : "128K",
        "runtime" : "30m",
        "write_bw_log" : "2217379BCB08/seq-read/Q32/128K",
        "write_iops_log" : "2217379BCB08/seq-read/Q32/128K",
        "write_lat_log" : "2217379BCB08/seq-read/Q32/128K",
        "write_hist_log" : "2217379BCB08/seq-read/Q32/128K"
      },
      "read" : {
        "io_bytes" : 10090103046144,
        "io_kbytes" : 9853616256,
        "bw_bytes" : 5605609689,
        "bw" : 5474228,

(2023.10.06)(10:22 AM)[BASH]
jqt@repo:[~/performance-deltas] $
>> head -n 10 seq-read/Q32/128K_bw.log
1003, 682113, 0, 0, 0
2003, 693045, 0, 0, 0
3003, 690738, 0, 0, 0
4003, 681897, 0, 0, 0
5004, 687744, 0, 0, 0
6003, 687279, 0, 0, 0
7004, 675968, 0, 0, 0
8004, 674722, 0, 0, 0
9003, 682794, 0, 0, 0
10004, 685568, 0, 0, 0


(2023.10.06)(10:27 AM)[BASH]
jqt@repo:[~/performance-deltas] $
>> head -n 20 seq-read.fio
[global]
max_latency=8s
percentile_list=1:5:10:20:30:40:50:60:70:80:90:95:99:99.9:99.99:99.999:99.9999
readwrite=read
ioengine=libaio
randrepeat=0
norandommap
refill_buffers=0
direct=1
group_reporting=1
log_avg_msec=1000
log_hist_msec=1000
bwavgtime=1000
iopsavgtime=1000
per_job_logs=0
disk_util=1
time_based
ramp_time=10
[128KQ32]
stonewall
numjobs=8
iodepth=4
bs=128K
ba=128K
runtime=30m
write_bw_log=seq-read/Q32/128K
write_iops_log=seq-read/Q32/128K
write_lat_log=seq-read/Q32/128K
write_hist_log=seq-read/Q32/128K

chencyu avatar Oct 06 '23 02:10 chencyu

The problem is in client.c:fio_client_handle_iolog(). When per_job_logs=0, the log files all have the same filename for each job. The data for each job is transferred from the server to the client, but is overwritten with each subsequent transmission. So the resulting log contains only the measurements for the last job. To fix this we need to add an append flag to the protocol so that the client opens log files in append mode.

vincentkfu avatar Nov 03 '23 19:11 vincentkfu

The patch at https://git.kernel.dk/cgit/fio/commit/?id=9af6c387191423eefee821e4087987350eaa5e6a should fix the original issue described in 2020. It's not clear to me that the subsequent reports are the same issue.

vincentkfu avatar Nov 06 '23 20:11 vincentkfu