KeyError: 'directory' when making `--loggraph`

[rkleinem]

I see a KeyError: 'directory'.

Bug description

Whether it happens or not seems to depend on the dataset that you want to plot.
As such the error appears more-or-less randomly in my test setup.
However, it seems like it only affects --loggraph plots, but it is not specific to a --type or a --filter.

Traceback (most recent call last):
  File "<frozen runpy>", line 198, in _run_module_as_main
  File "<frozen runpy>", line 88, in _run_code
  File "/usr/local/lib/python3.13/site-packages/fio_plot/__main__.py", line 4, in <module>
    fio_plot.main()
    ~~~~~~~~~~~~~^^
  File "/usr/local/lib/python3.13/site-packages/fio_plot/__init__.py", line 41, in main
    routing_dict[graphtype]["function"](settings, data)
    ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.13/site-packages/fio_plot/fiolib/graph2d.py", line 100, in chart_2d_log_data
    "maxlabelsize": support2d.get_max_label_size(settings, data),
                    ~~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.13/site-packages/fio_plot/fiolib/graph2dsupporting.py", line 50, in get_max_label_size
    label = create_label(settings, item)
  File "/usr/local/lib/python3.13/site-packages/fio_plot/fiolib/graph2dsupporting.py", line 41, in create_label
    mydir = f"{item['directory']}"
               ~~~~^^^^^^^^^^^^^
KeyError: 'directory'

Observations

I printed the data in graph2d.py before it gets passed to support2d.get_max_label_size:

{'datatypes': ['bw'], 'dataset': [{'read': [(1000.75, 156569), (2000, 117876), (3000.25, 112640), (4000, 49200), (5000, 636928), (6000, 479710), (7000, 462283), (8000, 90112), (9000, 118784), (10000, 116851), (11000.5, 88064), (12000, 126076), (13000, 75776), (14000.5, 80896), (15000, 111725), (16000, 121975), (17000, 110592), (18000.75, 80896), (19000, 96350), (20000.5, 109568), (21000, 94300), (22000, 78848), (22999.75, 102500), (24750, 107520), (25750, 90182), (27000.5, 77876), (28249.75, 134276), (29250, 274614)], 'write': {'xvalues': [1.00075, 2.0, 3.0005, 4.0, 5.0, 6.0, 7.0, 8.0, 9.0, 10.0, 11.0005, 12.0, 13.0, 14.0005, 15.0, 16.0, 17.0, 18.00075, 19.0, 20.0005, 21.0, 22.0, 22.99975, 24.75, 25.75, 27.0005, 27.99975, 29.0], 'yvalues': [184.873046875, 111.109375, 95.0, 55.0537109375, 670.0, 464.462890625, 507.5068359375, 82.0, 105.0, 120.1181640625, 77.0, 135.1328125, 102.0, 65.0, 102.099609375, 122.119140625, 98.0, 102.0, 104.1025390625, 110.0, 99.0966796875, 77.0, 109.107421875, 106.0, 106.0712890625, 79.0546875, 103.1005859375, 233.1533203125], 'ylabel': 'MB/s', 'max': np.float64(670.0), 'mean': 154, 'stdv': np.float64(92.63), 'percentile': 670}, 'hostname': None, 'type': 'bw', 'iodepth': 1, 'numjobs': 4, 'directory': '1M', 'xlabel': 'Time (s)'}, {'read': [(1750.125, 14181), (2000.875, 13492), (2001.875, 13492), (2002.875, 13492), (3252.875, 24888), (3253.875, 24888), (4378.75, 15420), (4379.75, 15420), (6878.625, 23331), (8877.75, 45907), (9753.5, 12601), (12628, 8605), (12878.75, 44071), (14753.75, 28312), (14879.625, 31890), (16004.625, 131607), (19627.5, 156227), (22375.75, 264379)], 'write': [], 'hostname': None}]}

Note the empty records. Sometimes it's only read or only write that is empty and sometimes it is both.

I don't have a good overview of the inner workings here, but I think I narrowed it down to
4a769b4
(1.1.15 seems to be the last version without the bug)
With that intendation the if len(record[rw]) > 0 check does not apply.

How to reproduce

To make the benchmarks I ran

python -m bench_fio --target=/app --output=/tmp/results/results --type=directory --destructive --size=50m --time-based --runtime=30 --mode=randrw --rwmixread=50 --block-size=1M --iodepth=1 --numjobs=4 --engine=psync --direct=0 --loginterval=1000
python -m bench_fio --target=/app --output=/tmp/results/results --type=directory --destructive --size=50m --time-based --runtime=30 --mode=randrw --rwmixread=50 --block-size=1M --iodepth=1 --numjobs=8 --engine=psync --direct=0 --loginterval=1000

I attached the outputs.

The call that fails is

python -m fio_plot --input-directory /tmp/results/results/app/randrw50/1M --title log-app-bw-randrw-bs1M --rw randrw --numjobs 4 8 --loggraph --filter write --xlabel-parent 0 --type bw

results.zip

[louwrentius]

Thanks for your extensive report including test data + steps to reproduce the issue.

• I can reproduce the issue with the test data provided
• I can't reproduce the issue when testing on a SATA SSD or USB3 micro SD card

The bug you supplied is valid, in the sense that there is an important issue with fio-plot error handling.

Looking at the raw bw log data, and the error result, we can observe that data is not logged every 1000ms and this is not properly handled by fioplot. You may have noticed 'division by zero errors' when creating a plot.

I'll investigate proper error handling of this kind of issue.

[rkleinem]

Yes, it seems that fio is not reliable in what timestamps it records.
For this reason the error appears "randomly": the datasets produced by different fio runs might differ significantly.
That means it is very much possible to have 10 consecutive runs (fio + fio-plot) that don't show an error.
This is chance and I think shorter runtimes make the error more likely.

And yes, I do see some 'division by zero' errors, but they seem to be handled.
They also appear when making a few plots that don't cause the above error.

[louwrentius]

I've released 1.1.21 that allows you to generate a graph. However, that graph will not really reflect the behaviour of the storage target under test.

When benchmarking with numjobs >1, multiple files are generated and it's assumed that all log files will have the same number of lines/records. This seems to hold in most cases, unless there are severe performance issues with the storage device under test. We observe with the test data that num_jobs = 8 results in files with less than 30 records, often much less.

This means that the wrong records are summed together to calculate the bandwidth, creating an incorrect picture.

I've only seen this happen while benchmarking a 1.44MB floppy.
Edit: I can't even reproduce the issue with a slow SD card.

[rkleinem]

So, I tested on a few different machines now.
It seems the case I reported is one with a very crappy device (SSD NVMe, vendor: Solidgm model: SSDPFKNU512GZH): no dedicated DRAM, possibly with firmware problems.
Under write-pressure it has latency spikes up to 2 seconds.

BUT: You can make fio drop values on any hardware by starting enough jobs in parallel.
I started 128 jobs on a storage node that was otherwise idle:

# inxi -CSDmz
System:
  Kernel: 5.14.0-570.44.1.el9_6.x86_64 arch: x86_64 bits: 64
  Console: pty pts/0 Distro: AlmaLinux 9.6 (Sage Margay)
Memory:
  System RAM: total: 192 GiB available: 186.99 GiB used: 8.83 GiB (4.7%)
  Array-1: capacity: 9 TiB note: check slots: 24 modules: 12 EC: Single-bit ECC
CPU:
  Info: 2x 12-core model: Intel Xeon Silver 4214 bits: 64 type: MT MCP SMP cache:
    L2: 2x 12 MiB (24 MiB)
Drives:
  Local Storage: total: 680.44 TiB used: 2.4 TiB (0.4%)
  ID-1: /dev/sda model: PRAID EP420i size: 446.62 GiB
  ID-2: /dev/sdb model: ETERNUS_DXL size: 85 TiB
  ID-3: /dev/sdc model: ETERNUS_DXL size: 85 TiB
  ID-4: /dev/sdd model: ETERNUS_DXL size: 85 TiB
  ID-5: /dev/sde model: ETERNUS_DXL size: 85 TiB
  ID-6: /dev/sdf model: ETERNUS_DXL size: 85 TiB
  ID-7: /dev/sdg model: ETERNUS_DXL size: 85 TiB
  ID-8: /dev/sdh model: ETERNUS_DXL size: 85 TiB
  ID-9: /dev/sdi model: ETERNUS_DXL size: 85 TiB

And it drops even more values than my laptop.

Now, you could argue that 128 is a lot, but the point is that fio seems to drop a lot of values if there is enough write-pressure, which is not really uncommon for benchmarks.

The question is how to handle this.
The "correct solution" would probably be to map the timestamps in the log files (which are relative to the job start) to real times and then associate them with timeslots (e.g. one-second slots).
Then, only consider timeslots that have as many values as there are jobs.
But this might get cumbersome fast, I think there are quite a few cases to consider.

I saw you added some warnings.
The logic of checking mean > 1000 is probably not enough. This checks the average time between datapoints in one log, right?
If I set higher --loginterval on the benchmark, the warning will always be triggered even if no values are dropped.
If I set --loginterval much lower, it won't be triggered even if many values are dropped.
How difficult would it be to compare average time between points across log files?

[louwrentius]

• The fact that there is a hard-coded 1000 (ms) value is a clear limitation that should actually match the --loginterval parameter. I have to look into that at some point.

• The observations you make are correct, the log record drops happen when:

  1. The device is terrible
  2. the load is 'unreasonable'

In both cases, the end-result is that fio-plot will throw a message about dropped log messages, strongly indicating severe performance problems.

For the num_jobs=8 data, you can observe that some threads have < 10 records whereas there should have been 30.
It is my opinion that converting this data and generating a graph will result in misleading graphs. It would probably be better to refuse to create a graph.

I think trying to extrapolate the data, fill in the missing records with zeros probably also results in an incorrect picture.
edit: I've attempted to do what you suggested, chop a logfile in loginterval slots and map data to the appropriate slots. I could not really get this to work properly and didn't feel like debugging this further.