Unexpected pause in fio operation for a random short period of time

[it800]

Checked on the following fio versions: 3.12, 3,36, 3,39. Test environment:
2 enterprise all-flash SAN storages (SSD), iSCSI connectivity. There are 2 LUNs created on both storages and mapped to the 2 test hosts independently.
1 host: bare metal Debian linux server, 8 paths discovered to the LUN, /dev/dm-0 multipathd device created to be tested with fio
2 host: Centos 9 virtual machine under Vmware ESXi, the LUN is presented to VM as a 2TB block device /dev/sdb

The fio test configuration is the same for both hosts, the configuration is shown below. Fio runs on the hosts along with “iostat -tx 1” to independently monitor latency and queue depth. The problem we observe is random unexpected pauses in fio's operation: it seems that at some point fio just stops generating IO for a while. The pause can last up to a minute (but usually takes less time), after which fio continues to generate IO operations with an initial spike in IOPS above a configured rated_iops value. I raised the issue of IO burst in another thread here, but in the end there was no clear answer about the nature of this effect, we accept it “as is”.
We thoroughly checked the storage, checked the iostat output, and came to the conclusion that the problem is most likely in the fio itself. According to the iostat output, the pause was not preceded by any I/O latency problems, the queue depth did not exceed half of the configured value. It was just fio stopping I/O. There are no entries in the fio logs during this period. At the operating system level at the moment of pause - no problems with block devices, no problems with paths, nothing in messages.

We assume that a single thread of fio cannot handle a certain load for a long time. We tried changing the configuration by halving rated_iops and running fio in two-job mode. This configuration variant showed more stable performance, but fio can still stop unexpectedly. Such stops do not allow us to perform a full-fledged testing of the storage, because we cannot distinguish between real problems on the storage and fio problems.

Right now we're stuck because at this point we still have no idea what else we can test to see what exactly is causing the problem. If 50K IOPS is indeed too much for a single fio process - we would really appreciate it if this could be confirmed. Any advice and help would be greatly appreciated

[global]
iodepth=64 (tried 128 as well, didn't help)
direct=1
buffered=0
ioengine=libaio
group_reporting=1
time_based=1
runtime=24h
numjobs=1
rw=randrw
rwmixread=50
write_lat_log=test1
log_avg_msec=1000
write_iops_log=test1
disable_slat=1
disable_clat=1
log_unix_epoch=1

[job-test01]
bs=32k,32k
rate_iops=25k,25k
filename=/dev/dm-0

[it800]

We are still conducting tests. At this point, we are no longer testing the storage itself as much as we are testing how fio behaves in different test scenarios. It is now quite clear that the issue is neither caused by the storage nor the SAN.

We have identified at least one pattern, confirmed through multiple tests (each lasting between 15 and 60 minutes). Specifically, we found that if numjobs=1 and rated_iops is relatively high (25k/25k), the issue occurs within 10–15 minutes after the test starts. However, if numjobs=2, we do not observe the issue, even if the rated_iops value remains unchanged. In other words, as long as at least two jobs are running, fio remains stable—even while generating twice the expected IOPS.

We have varied the rated_iops value multiple times, but it seems that the key factor is the numjobs setting. Once it is greater than 1, fio operates stably, generating the expected I/O stream.

Please note that we used two different bare-metal servers with different Linux distributions, as well as a virtual machine (CentOS 8 running on VMware ESXi). The results were consistent across all test environments.

I am still awaiting any feedback on the issue we are encountering. Thanks!

[sitsofe]

I can't (and don't) speak for Jens so the following is personal explanation as to why you haven't received a response thus far:

@it800 You're "strongly requesting" the time of unpaid volunteer to investigate your issue but the nature of open source is that there is no obligation stating volunteers have to respond within a certain time frame (or at all). I understand that this unlikely to be the response you're looking for and I have no doubt the problem is important to you but I want you to be aware that not all issues are investigated and of those that are, not all issues are resolved. Unpaid time is limited and totally at the discretion of the owner...

Please don't take the following as commitment that I will investigate the problem but here are some questions to get going with: does this issue happen when you run against a purely local disk on your bare metal machine? Does the problem happen when you remove the rate_iops option? What is the totally minimal job file that still reproduces the problem - can you remove EVERY job option that doesn't impact the problem (I can already see job options that will have zero impact)? Can you reproduce this problem against Linux's null_blk device ? How long does it take for the problem to happen and how much I/O has been done at that point?

[it800]

I absolutely don’t insist that any volunteer spend their personal unpaid time on my issues. I reported this situation thinking it might be useful for the project since the problem is reproducible and could potentially affect more than just my storage systems. In any case, I appreciate your feedback and will now answer your questions to the point.

Does this issue happen when you run against a purely local disk on your bare metal machine?

Such a test has not been conducted. The issue occurs under high IOPS load, so we felt that testing on a local disk wouldn’t be very accurate—it might not handle the load, whereas the SAN storage is guaranteed to withstand even higher IOPS levels.

Does the problem happen when you remove the rate_iops option?

We haven’t tested without rate_iops because it’s important for us to achieve a stable IOPS value, and using this option is critical.

What is the totally minimal job file that still reproduces the problem - can you remove EVERY job option that doesn't impact the problem (I can already see job options that will have zero impact)?

We can run any test, in principle. However, I'm not entirely sure which specific job parameters need to be removed.

Can you reproduce this problem against Linux's null_blk device ? How long does it take for the problem to happen and how much I/O has been done at that point?

I’ll try to run this test and will get back to you with the results.

[sitsofe]

Does this issue happen when you run against a purely local disk on your bare metal machine?

Such a test has not been conducted. The issue occurs under high IOPS load, so we felt that testing on a local disk wouldn’t be very accurate—it might not handle the load, whereas the SAN storage is guaranteed to withstand even higher IOPS levels.

This was more of a "can it be reproduced in smaller environments" question. I know it's unrealistic for you but could you give it a go and report your findings? If it only reproduces in scenarios where you have to have particular hardware then them's the breaks but it rules out a passer-by such as myself trying to debug the issue (as I definitely don't have such hardware).

Does the problem happen when you remove the rate_iops option?

We haven’t tested without rate_iops because it’s important for us to achieve a stable IOPS value, and using this option is critical.

Again this is more about trying to narrow down where the issue lies. Yes, it moves away from the scenario you're interested but it provides more information about where the problem lies. Right now I don't know if what you see is related to the rate limiting code in fio...

We can run any test, in principle. However, I'm not entirely sure which specific job parameters need to be removed.

When you're not sure just which parameters are necessary you can minimise the job file through brute force:

1. Remove next parameter
2. See if problem still reproduces
3. If problem does reproduce leave parameter out of future runs otherwise put parameter back and move go to step 1.

This is helpful because when you have the minimal jobfile/test case it means there are less places in the code to look for the problem. I can tell by looking that some of your parameters are unnecessary (e.g. did you know that direct=1/buffered=0 are just synonyms of each other and putting both is specifying the same thing twice) but there are others where I'd hope they don't have an influence but I'd like to rule it out (imagine if the filesystem where fio writes its iologs to can't keep up and due to how fio is written, fio ends up not generating new writes until the iolog backlog is cleared). Obviously those are examples so please don't stop there.

Can you reproduce this problem against Linux's null_blk device ? How long does it take for the problem to happen and how much I/O has been done at that point?

I’ll try to run this test and will get back to you with the results.

Thanks. Just to be clear those were two disjoint questions; even if you don't get null_blk testing going it would be good to know how long it takes before the problem you describe is seen.

Does the above make sense?

[it800]

Does this issue happen when you run against a purely local disk on your bare metal machine?

Such a test has not been conducted. The issue occurs under high IOPS load, so we felt that testing on a local disk wouldn’t be very accurate—it might not handle the load, whereas the SAN storage is guaranteed to withstand even higher IOPS levels.

This was more of a "can it be reproduced in smaller environments" question. I know it's unrealistic for you but could you give it a go and report your findings? If it only reproduces in scenarios where you have to have particular hardware then them's the breaks but it rules out a passer-by such as myself trying to debug the issue (as I definitely don't have such hardware).

It's not just about the issue occurring under high load, which the local disk of the test server is unlikely to handle. The problem is that the disk already has a file system, and I don’t have the option to modify the test environment to add a disk that could be used for tests directly without a file system.

Does the problem happen when you remove the rate_iops option?

We haven’t tested without rate_iops because it’s important for us to achieve a stable IOPS value, and using this option is critical.

Again this is more about trying to narrow down where the issue lies. Yes, it moves away from the scenario you're interested but it provides more information about where the problem lies. Right now I don't know if what you see is related to the rate limiting code in fio...

I'll do my best to run this test.

We can run any test, in principle. However, I'm not entirely sure which specific job parameters need to be removed.

When you're not sure just which parameters are necessary you can minimise the job file through brute force:

1. Remove next parameter

2. See if problem still reproduces

3. If problem does reproduce leave parameter out of future runs otherwise put parameter back and move go to step 1.

This is helpful because when you have the minimal jobfile/test case it means there are less places in the code to look for the problem. I can tell by looking that some of your parameters are unnecessary (e.g. did you know that direct=1/buffered=0 are just synonyms of each other and putting both is specifying the same thing twice) but there are others where I'd hope they don't have an influence but I'd like to rule it out (imagine if the filesystem where fio writes its iologs to can't keep up and due to how fio is written, fio ends up not generating new writes until the iolog backlog is cleared). Obviously those are examples so please don't stop there.

Yes, I'm aware of direct=1/buffered=0. One of my colleagues insisted on explicitly setting all these values to "make absolutely sure that fio is working directly with the block device." Since it doesn’t affect anything, I kept this configuration to avoid revisiting these questions again.
As for log file writing, when checking the directory where fio stores logs, the file sizes change significantly either some time after fio starts or upon its completion. Either fio flushes logs to disk at certain intervals, or the operating system tells the size of an open file this way. Even if we assume there are issues with writing to disk, that wouldn’t explain why fio runs stably with numjobs=2

Can you reproduce this problem against Linux's null_blk device ? How long does it take for the problem to happen and how much I/O has been done at that point?

I’ll try to run this test and will get back to you with the results.

Thanks. Just to be clear those were two disjoint questions; even if you don't get null_blk testing going it would be good to know how long it takes before the problem you describe is seen.

Although it sometimes takes a significant amount of time (up to 30 minutes) for the issue to appear, it usually happens much sooner. In most cases, the problem almost certainly occurs within 10-15 minutes after starting the test. Below, I’ve attached a screenshot of the storage system’s graph with timestamps. I just ran the test, so you can assess how quickly the issue occurred.
As for null_blk, there might be issues since the test server's kernel was built without support for this device. I’ll check if I can rebuild the kernel and create the necessary module for it.

Does the above make sense?

Thank you, everything you wrote is very valuable.

[it800]

Again this is more about trying to narrow down where the issue lies. Yes, it moves away from the scenario you're interested but it provides more information about where the problem lies. Right now I don't know if what you see is related to the rate limiting code in fio

Interesting. I disabled rate_iops, and the very first test has already been running for 30 minutes without any issues, with fio continuing without interruptions. With iodepth=64, the read and write IOPS levels are holding steady at around 45k/45k (plus or minus). There are slight fluctuations on the graphs, but they appear to be just normal variations.
I will continue testing over the weekend to confirm or refute the hypothesis that the issue is not triggered when rate_iops is disabled.

[vincentkfu]

@sitsofe 's comment led me to think about the log_entries option. The issue it addresses does not exactly fit the pattern you have described but it is probably worth a try. The commit message explains well how it might help:

commit 0a852a50c315776de0b43185e30576f15a420a24
Author: Damien Le Moal <damien.lemoal@opensource.wdc.com>
Date:   Thu Nov 18 14:27:29 2021 +0900

    fio: Introduce the log_entries option
    
    When iops, latency, or bw logging options are used, fio will by default
    log information for any I/O that completes. The initial number of I/O
    log entries is 1024, as defined by (DEF_LOG_ENTRIES). When all log
    entries are used, new log entries are dynamically allocated by
    get_new_log(). This dynamic log entry allocation can negatively impact
    time-related statistics such as the I/O tail latencies (e.g. 99.9
    percentile completion latency) as growing the logs causes a temporary
    I/O stall (IO quiesce), which disturbs the workload steady state. The
    effect of this is especially noticeable with workloads using IO
    priorities: the tail latencies of high priority I/Os increase if the
    IO log needs to be grown.
    
    For example, running the following fio command on a SATA disk
    supporting NCQ priority:
    
    fio --name=prio-randread --filename=/dev/sdg \
        --random_generator=tausworthe64 --ioscheduler=none \
        --write_lat_log=randread.log --log_prio=1 --rw=randread --bs=128k \
        --ioengine=libaio --iodepth=32 --direct=1 --cmdprio_class=1 \
        --cmdprio_percentage=30 --runtime=900
    
    (128KB random read workload at QD=32 and 30% of commands issued with a
    high priority), with an inital number of log entries equal to the
    default of 1024, depending on the machine memory state, the completion
    latency statistics may show imprecise percentiles such as shown below.
    
    high prio (30.75%) clat percentiles (msec):
     |  1.00th=[   14],  5.00th=[   17], 10.00th=[   20], 20.00th=[   23],
     | 30.00th=[   27], 40.00th=[   32], 50.00th=[   40], 60.00th=[   53],
     | 70.00th=[   71], 80.00th=[  104], 90.00th=[  169], 95.00th=[  243],
     | 99.00th=[  514], 99.50th=[  676], 99.90th=[ 1485], 99.95th=[ 1502],
     | 99.99th=[ 1552]
    low prio (69.25%) clat percentiles (msec):
     |  1.00th=[   16],  5.00th=[   24], 10.00th=[   37], 20.00th=[   68],
     | 30.00th=[  105], 40.00th=[  146], 50.00th=[  199], 60.00th=[  255],
     | 70.00th=[  330], 80.00th=[  439], 90.00th=[  592], 95.00th=[  718],
     | 99.00th=[  885], 99.50th=[  986], 99.90th=[ 1469], 99.95th=[ 1536],
     | 99.99th=[ 1586]
    
    All completion latency percentiles above the 99.90th percentile are
    similar for the high and low priority commands, which is not consistent
    with the drive expected execution of prioritized read commands.
    
    To solve this issue and get more precise latency statistics, this patch
    introduces the new "log_entries" option to allow specifying a larger
    initial number of IO log entries to avoid run-time allocation.
    This option value defaults to DEF_LOG_ENTRIES and its maximum value is
    MAX_LOG_ENTRIES to be consistent with get_new_log() allocation. Also
    simplify get_new_log() by using calloc() instead of malloc, thus
    removing the need for the local variable new_size.
    
    Adding the "--log_entries=65536" option to the previous command line
    example, the completion latency results obtained are more stable:
    
    high prio (30.72%) clat percentiles (msec):
     |  1.00th=[   15],  5.00th=[   17], 10.00th=[   19], 20.00th=[   22],
     | 30.00th=[   24], 40.00th=[   27], 50.00th=[   32], 60.00th=[   36],
     | 70.00th=[   46], 80.00th=[   57], 90.00th=[   81], 95.00th=[  105],
     | 99.00th=[  161], 99.50th=[  188], 99.90th=[  271], 99.95th=[  275],
     | 99.99th=[  363]
    low prio (69.28%) clat percentiles (msec):
     |  1.00th=[   16],  5.00th=[   27], 10.00th=[   43], 20.00th=[   80],
     | 30.00th=[  123], 40.00th=[  176], 50.00th=[  236], 60.00th=[  313],
     | 70.00th=[  401], 80.00th=[  506], 90.00th=[  634], 95.00th=[  718],
     | 99.00th=[  844], 99.50th=[  885], 99.90th=[  953], 99.95th=[  995],
     | 99.99th=[ 1053]
    
    All completion percentiles clearly now show shorter latencies for high
    priority commands, as expected. The 99.99th percentile for low priority
    commands is also improved compared to the previous case as the
    measurements are not impacted by the log dynamic allocation.
    
    Suggested-by: Shin'ichiro Kawasaki <shinichiro.kawasaki@wdc.com>
    Signed-off-by: Damien Le Moal <damien.lemoal@opensource.wdc.com>
    Reviewed-by: Niklas Cassel <niklas.cassel@wdc.com>
    Link: https://lore.kernel.org/r/20211118052729.132423-1-damien.lemoal@opensource.wdc.com
    Signed-off-by: Jens Axboe <axboe@kernel.dk>

[it800]

@sitsofe 's comment led me to think about the log_entries option. The issue it addresses does not exactly fit the pattern you have described but it is probably worth a try. The commit message explains well how it might help:

Thank you very much for your comment. The current version of fio on the test server is 3.23, which does not have this parameter, but we will try to update it to a more recent version and we will run the test with the highest value.

[it800]

We installed and tested fio 3.36 with the --log_entries=65536 option, as suggested in the message you forwarded. Unfortunately, it didn’t resolve the issue. rate_ops was set to 25k,25k, and the problem occurred within 30 minutes after the test started.

So far, the only workaround that helps stabilize the I/O stream is disabling rate_iops and using iodepth to limit the IOPS.

[it800]

We conducted 12 tests of varying durations. All the tests can be divided into two groups:

1. Tests where the rate_iops parameter is commented out.
2. Tests where rate_iops is active.

Tests from group 1 lasted on average from 30 minutes to 3 hours. During these tests, we never observed the described issue of spontaneous and sudden I/O operation interruptions.
Tests from group 2 lasted from 10 minutes to one hour, and during these tests, there was always at least one interruption of I/O operations. This usually occurred within the first 7-15 minutes of testing, but sometimes appeared much later.

The fact is that in the tests from the second group, the interruption was observed almost always (except for one case, when everything was fine for 30 minutes, and the test was stopped). We continue the tests, but at this point, it seems that the rate_iops with the IOPS value above a certain threshold seems to be a trigger for the issue.

[it800]

What’s more, it looks like num_jobs is not even a workaround for the issue. We checked the logs for both threads and noticed that one of them interrupted during the test. It’s just harder to notice on the storage graphs because the second thread is still running, and some of the IOPS drops don’t stand out as much since they get averaged out.