On Thu, Feb 29, 2024 at 08:52:48AM -0600, John Groves wrote: > On 24/02/29 01:15PM, Dave Chinner wrote: > > On Mon, Feb 26, 2024 at 08:05:58PM -0600, John Groves wrote: > > > bw ( MiB/s): min= 5085, max=27367, per=100.00%, avg=14361.95, stdev=165.61, samples=719 > > > iops : min= 2516, max=13670, avg=7160.17, stdev=82.88, samples=719 > > > lat (usec) : 4=0.05%, 10=0.72%, 20=2.23%, 50=2.48%, 100=3.02% > > > lat (usec) : 250=1.54%, 500=2.37%, 750=1.34%, 1000=0.75% > > > lat (msec) : 2=3.20%, 4=43.10%, 10=23.05%, 20=14.81%, 50=1.25% > > > > Most of the IO latencies are up round the 4-20ms marks. That seems > > kinda high for a 2MB IO. With a memcpy speed of 10GB/s, the 2MB > > should only take a couple of hundred microseconds. For Famfs, the > > latencies appear to be around 1-4ms. > > > > So where's all that extra time coming from? > > Below, you will see two runs with performance and latency distribution > about the same as famfs (the answer for that was --fallocate=native). Ah, that is exactly what I suspected, and was wanting profiles because that will show up in them clearly. > > > lat (msec) : 100=0.08% > > > cpu : usr=10.18%, sys=0.79%, ctx=67227, majf=0, minf=38511 > > > > And why is system time reporting at almost zero instead of almost > > all the remaining cpu time (i.e. up at 80-90%)? > > Something weird is going on with the cpu reporting. Sometimes sys=~0, but other times > it's about what you would expect. I suspect some sort of measurement error, > like maybe the method doesn't work with my cpu model? (I'm grasping, but with > a somewhat rational basis...) > > I pasted two xfs runs below. The first has the wonky cpu sys value, and > the second looks about like what one would expect. > > > > > Can you run call-graph kernel profiles for XFS and famfs whilst > > running this workload so we have some insight into what is behaving > > differently here? > > Can you point me to an example of how to do that? perf record --call-graph ... pref report --call-graph ... > I'd been thinking about the ~2x gap for a few days, and the most obvious > difference is famfs files must be preallocated (like fallocate, but works > a bit differently since allocation happens in user space). I just checked > one of the xfs files, and it had maybe 80 extents (whereas the famfs > files always have 1 extent here). Which is about 4MB per extent. Extent size is not the problem for zero-seek-latency storage hardware, though. Essentially what you are seeing is interleaving extent allocation between all the files because they are located in the same directory. The locality algorithm is trying to place the data extents close to the owner inode, but the indoes are also all close together because they are located in the same AG as the parent directory inode. Allocation concurrency is created by placing new directories in different allocation groups, so we end up with workloads in different directories being largely isolated from each other. However, that means when you are trying to write to many files in the same directory at the same time, they are largely all competing for the same AG lock to do block allocation during IO submission. That creates interleaving of write() sized extents between different files. We use speculative preallocation for buffered IO to avoid this, and for direct IO the application needs to use extent size hints or preallocation to avoid this contention based interleaving. IOWs, by using fallocate() to preallocate all the space there will be no allocation during IO submission and so the serialisation that occurs due to competing allocations just goes away... > FWIW I ran xfs with and without io_uring, and there was no apparent > difference (which makes sense to me because it's not block I/O). > > The prior ~2x gap still seems like a lot of overhead for extent list > mapping to memory, but adding --fallocate=native to the xfs test brought > it into line with famfs: As I suspected. :) As for CPU usage accounting, the number of context switches says it all. "Bad": > cpu : usr=15.48%, sys=1.17%, ctx=62654, majf=0, minf=22801 "good": > cpu : usr=14.43%, sys=78.18%, ctx=5272, majf=0, minf=15708 I'd say that in the "bad" case most of the kernel work is being shuffled off to kernel threads to do the work and so it doesn't get accounted to the submission task. In comparison, in the "good" case the work is being done in the submission thread and hence there's a lot fewer context switches and the system time is correctly accounted to the submission task. Perhaps an io_uring task accounting problem? Cheers, Dave. -- Dave Chinner david@xxxxxxxxxxxxx
