On Tue, Oct 12, 2021 at 03:42:55PM +0200, Jan Kara wrote: > On Fri 08-10-21 10:44:30, Dave Chinner wrote: > > On Thu, Oct 07, 2021 at 02:03:57PM +0200, Jan Kara wrote: > > > On Thu 07-10-21 08:58:51, Dave Chinner wrote: > > > > On Wed, Oct 06, 2021 at 08:10:01PM +0200, Jan Kara wrote: > > > > Hmmm, I didn't see this at first. What's the filesystem layout > > > > (xfs_info) and the CLI for the test that you ran? How many CPUs was > > > > the test run on? > > > > > > The machine has 24 cores, each core has 2 SMT siblings, so 48 logical CPUs. > > > That's why I've run stress-unlink with 48 processes. > > > > > > xfs_info is: > > > > > > meta-data=/dev/sdb1 isize=512 agcount=4, agsize=29303104 blks > > > = sectsz=512 attr=2, projid32bit=1 > > > = crc=1 finobt=1, sparse=0, rmapbt=0 > > > = reflink=0 > > > data = bsize=4096 blocks=117212416, imaxpct=25 > > > = sunit=0 swidth=0 blks > > > naming =version 2 bsize=4096 ascii-ci=0, ftype=1 > > > log =internal log bsize=4096 blocks=57232, version=2 > > > > OK, default log is ~230MB, fs size is ~400GB? > > Yep. > > <snip log analysis> > > > > We can see big differences in the amount of log writes as well as logged > > > blocks. defaults-before logged 76 MB, defaults-after logged 262 MB, > > > highag-before logged 113 MB, highag-after logged 148 MB. Given data writes > > > for this test are 750 MB (16k * 48 processes * 1000 loops), the difference > > > of 186 MB of log IO matches well with the observed difference in the amount > > > of writes in block traces. > > > > > > I'm not sure why the amount of logged blocks differs so much. > > > > fsync() interactions. > > > > On the original code, the two unlink transactions are temporally > > adjacent as both are in unlinkat() syscall context. One is directly > > run by the syscall, the other in task_run context at syscall exit > > when processing the last reference of the file being dropped. > > > > In general, that means the objects modified (inode cluster, AGI, > > inode, etc) are captured by the same CIL context and so aggregate in > > memory as a single change (essentially log dedupe). Then the next > > fsync() from some other context runs, pushing the CIL to disk and > > we only log those objects modified in unlink to the journal once. > > > > With deferred activation, the two phases of unlink are temporally > > decoupled. We get a bunch of inodes running the first phase in > > unlink() context, but the second phase is run later in a tight loop > > from workqueue context. But this means that fsync()s occur between > > the two pahses, and hence the objects modified in the two phases of > > unlink are modified in two separate CIL contexts. Hence they get > > written to the log twice. > > > > Depending on the way things work out, deferred inactivation also > > results in longer unlinked inode chains, resulting in more objects > > being logged per unlink than without deferred inactivation, as the > > inodes are added to the unlink chain and then immediately removed > > before any others are added. Hence deferred inode inactivation will > > increase the amount written to the log per unlink if the two phases > > of unlink as split across journal checkpoints. > > > > IOWs, an increase in log writes for open-write-fsync-close-unlink > > workloads is not unexpected. But this workload isn't really a real > > world workload in any way - we generally don't do data integrity > > writes only to immediately throw the data away. :/ > > > > Remove the fsync and we do have a real world workload - temporary > > files for compiles, etc. Then everything should mostly get logged > > in the same CIL context because all transactions are run > > asynchronously and aggregate in memory until the CIL is full and > > checkpoints itself. Hence log writes shouldn't change very much at > > all for such workloads. > > OK, that makes sense. Thanks for explanation. So to verify your theory, > I've removed fsync(2) from the test program. So now it is pure create, > write, unlink workload. Results of "stress-unlink 48 /mnt", now for 5000 > loops of create-unlink to increase runtime (but the workload does barely > any writes so it should not matter wrt log): > > default mkfs params: > AVG STDDEV > before 2.0380 0.1597 > after 2.7356 0.4712 > > agcount=96, log size 512M > AVG STDDEV > before 1.0610 0.0227 > after 1.2508 0.0218 > > So still notable regression with the async inactivation. With default mkfs > params we'd need more runs to get more reliable results (note the rather > high standard deviation) but with high AG count results show pretty stable > 20% regression - so let's have a look at that. > > Looking at xfs stats there are barely any differences between before & > after - 'after' writes a bit more to the log but it is ~1.5 MB over the > whole benchmark run, altogether spending some 8ms doing IO so that's not > it. Generally the workload seems to be CPU / memory bound now (it does > barely any IO). Perf shows we are heavily contending on some spinlock in > xfs_cil_commit() - I presume this is a xc_cil_lock. Yes, and I have patches that fix this. It got reverted a before release because it exposed a bunch of underlying zero-fay bugs in the log code, and I haven't had time to run it through the review cycle again even though it's pretty much unchanged from commits 26-39 in this series: https://lore.kernel.org/linux-xfs/20210603052240.171998-1-david@xxxxxxxxxxxxx/ The profiles in this patch demonstrate the problem and the fix: https://lore.kernel.org/linux-xfs/20210603052240.171998-35-david@xxxxxxxxxxxxx/ I did all my perf testing of inode inactivation with the CIL scalability patches also installed, because deferred inode inactivation only made contention on the CIL lock worse in my perf tests. We simply can't evaluate the benefit of a change when the system is easily driven into catastrophic lock breakdown by user level operational concurrency. IOWs, the CIL lock is the global limiting factor for async transaction commit rates on large CPU count machines, and things that remove bottlenecks in higher layers often just increase contention on this lock and drive it into breakdown. That makes perf go backwards, not forwards, and it's not the fault of the high level change being made. That doesn't make the high level change wrong, it just means we need to peel the onion further before the improvements are fully realised. > This actually happens > both before and after, but we seem to spend some more time there with async > inactivation. Likely this is related to work being done from worker > threads. Perf stats for comparison: > > before > 51,135.08 msec cpu-clock # 47.894 CPUs utilized > 4,699 context-switches # 0.092 K/sec > 382 cpu-migrations # 0.007 K/sec > 1,228 page-faults # 0.024 K/sec > 128,884,972,351 cycles # 2.520 GHz > 38,517,767,839 instructions # 0.30 insn per cycle > 8,337,611,468 branches # 163.051 M/sec > 39,749,736 branch-misses # 0.48% of all branches > 25,225,109 cache-misses > > 1.067666170 seconds time elapsed > > after > 65,353.43 msec cpu-clock # 47.894 CPUs utilized > 43,737 context-switches # 0.669 K/sec > 1,824 cpu-migrations # 0.028 K/sec > 1,953 page-faults # 0.030 K/sec > 155,144,150,867 cycles # 2.374 GHz > 45,280,145,337 instructions # 0.29 insn per cycle > 10,027,567,384 branches # 153.436 M/sec > 39,554,691 branch-misses # 0.39% of all branches > 30,203,567 cache-misses > > 1.364539400 seconds time elapsed > > So we can see huge increase in context-switches, notable increase in > cache-misses, decrease in cycles/s so perhaps we are bouncing cache more? > Anyway I guess this is kind of expected due to the nature of async > inactivation, I just wanted to highlight that there are regressions without > fsync in the game as well. Context switches are largely noise - they are most likely just AGI locks being bounced a bit more. It's the spinlock contention that is the likely issue here. For example, on my 32p machine with vanilla 5.15-rc4 with a fsync-less, 5000 iteration test run: $ sudo perf_5.9 stat ./stress-unlink 32 /mnt/scratch Processes started. 1.290 Performance counter stats for './stress-unlink 32 /mnt/scratch': 16,856.61 msec task-clock # 12.595 CPUs utilized 48,297 context-switches # 0.003 M/sec 4,219 cpu-migrations # 0.250 K/sec 1,373 page-faults # 0.081 K/sec 39,254,798,526 cycles # 2.329 GHz 16,460,808,349 instructions # 0.42 insn per cycle 3,475,251,228 branches # 206.166 M/sec 12,129,889 branch-misses # 0.35% of all branches 1.338312347 seconds time elapsed 0.186554000 seconds user 17.247176000 seconds sys And with 5.15-rc4 + CIL scalability: $ sudo perf_5.9 stat ./stress-unlink 32 /mnt/scratch Processes started. 0.894 Performance counter stats for './stress-unlink 32 /mnt/scratch': 12,917.93 msec task-clock # 13.805 CPUs utilized 39,680 context-switches # 0.003 M/sec 2,737 cpu-migrations # 0.212 K/sec 1,402 page-faults # 0.109 K/sec 30,920,293,752 cycles # 2.394 GHz 14,472,067,501 instructions # 0.47 insn per cycle 2,700,978,247 branches # 209.087 M/sec 9,287,754 branch-misses # 0.34% of all branches 0.935710173 seconds time elapsed 0.192467000 seconds user 13.245977000 seconds sys Runtime of the fsync-less, 5,000 iteration version drops from 1.29s to 0.89s, IPC goes up, branches and branch-misses go down, context switches only go down slightly, etc. IOWs, when you take away the CIL lock contention, we get back all that perf loss and then some... FWIW, let's really hammer it for a long while. Vanilla 5.14-rc4: $ sudo perf_5.9 stat ./stress-unlink 1000 /mnt/scratch Processes started. 38.881 Performance counter stats for './stress-unlink 1000 /mnt/scratch': 733,741.06 msec task-clock # 16.004 CPUs utilized 13,131,968 context-switches # 0.018 M/sec 1,302,636 cpu-migrations # 0.002 M/sec 40,720 page-faults # 0.055 K/sec 1,195,192,185,398 cycles # 1.629 GHz 643,382,890,656 instructions # 0.54 insn per cycle 129,065,409,600 branches # 175.900 M/sec 768,146,988 branch-misses # 0.60% of all branches 45.847750477 seconds time elapsed 11.194020000 seconds user 758.762376000 seconds sys And the transaction rate is pinned at 800,000/s for the entire test. We're running at the limit of the CIL lock here. With CIL scalbility patchset: $ sudo perf_5.9 stat ./stress-unlink 1000 /mnt/scratch Processes started. 28.263 Performance counter stats for './stress-unlink 1000 /mnt/scratch': 450,547.80 msec task-clock # 15.038 CPUs utilized 5,949,268 context-switches # 0.013 M/sec 868,887 cpu-migrations # 0.002 M/sec 41,570 page-faults # 0.092 K/sec 836,933,822,425 cycles # 1.858 GHz 536,132,522,275 instructions # 0.64 insn per cycle 99,264,579,180 branches # 220.320 M/sec 506,921,132 branch-misses # 0.51% of all branches 29.961492616 seconds time elapsed 7.796758000 seconds user 471.990545000 seconds sys 30% reduction in runtime because the transaction rate is now running at 1.1M/s. Improvements in code execution across the board here, so the problem clearly isn't the deferred inode inactivation. IOWs, I'm largely not concerned about the high CPU count perf regressions that we are seeing from log code these days - the fix is largely ready, it's just lacking in available engineering time to get it over the line and merged right now... Cheers, Dave. -- Dave Chinner david@xxxxxxxxxxxxx
