weird lock contention problem during parallel writes to different files

[Mateusz Guzik]

On Thu, Oct 16, 2014 at 07:04:21PM +0200, Mateusz Guzik wrote:
> Hello,
> 
> There is some weird stuff going on. I'm writing this down in case
> someone is interested in figuring out what's up.
> 
> I run the same microbenchmark on an empty dataset. I remove files, but
> don't recreate the set. The test consists of 16 threads writing to
> different files in a loop.
> 
> When the run is good, I get:
> https://people.freebsd.org/~mjg/zfs-write-contention/zfs-bad-run.svg
> 
> But when it's bad...:
> https://people.freebsd.org/~mjg/zfs-write-contention/zfs-good-run.svg
> 
> You can see test program here:
> https://people.freebsd.org/~mjg/zfs-write-contention/write-diff.c
> 
> (As a side note, for vn_start_write & friends from good run see
> https://reviews.freebsd.org/D952 .)
> 
> pool was created with:
> mdconfig -a -t malloc -s 10G
> zpool create zmeh /dev/md0
> 
> Test machine is:
> CPU: Intel(R) Xeon(R) CPU E5-2643 0 @ 3.30GHz (3300.07-MHz K8-class CPU)
> real memory  = 34376515584 (32784 MB)
> avail memory = 33235132416 (31695 MB)
> FreeBSD/SMP: Multiprocessor System Detected: 16 CPUs
> FreeBSD/SMP: 2 package(s) x 4 core(s) x 2 SMT threads
> 

Forgot to note:
it's head r273122 with invariants etc disabled.

.svg files are flamegraphs, see
http://www.brendangregg.com/FlameGraphs/cpuflamegraphs.html for more
info.

I generated them with:
dtrace -x stackframes=100 -n 'profile-997 { @[stack()] = count(); }
tick-60s { exit(0); }' -o out.kern_stacks

while on tmpfs.

and then

cat out.kern_stacks | ./stackcollapse.pl | ./flamegraph.pl > out.svg

You can find repo here: https://github.com/brendangregg/FlameGraph.git

> Console output is as follows:
> 
> [16:50] fox2:/zmeh # /ufs/mjgtmp/write-diff -s 80 -n 16 test
> threads:16 sleep:80 pinned:1
> total operations: 40295308, ops/sec 503691
> 40295308
> [16:51] fox2:/zmeh # rm *                                   
> zsh: sure you want to delete all the files in /zmeh [yn]? y
> [16:52] fox2:/zmeh # /ufs/mjgtmp/write-diff -s 80 -n 16 test
> threads:16 sleep:80 pinned:1
> total operations: 19705569, ops/sec 246319
> 19705569
> [16:53] fox2:/zmeh # rm *                                   
> zsh: sure you want to delete all the files in /zmeh [yn]? y
> [16:53] fox2:/zmeh # /ufs/mjgtmp/write-diff -s 80 -n 16 test
> threads:16 sleep:80 pinned:1
> total operations: 41942052, ops/sec 524275
> 41942052
> [16:54] fox2:/zmeh # rm *                                   
> zsh: sure you want to delete all the files in /zmeh [yn]? y
> [16:55] fox2:/zmeh # /ufs/mjgtmp/write-diff -s 80 -n 16 test
> threads:16 sleep:80 pinned:1
> total operations: 19168019, ops/sec 239600
> 19168019
> [16:56] fox2:/zmeh # rm *                                   
> zsh: sure you want to delete all the files in /zmeh [yn]? y
> [16:56] fox2:/zmeh # /ufs/mjgtmp/write-diff -s 80 -n 16 test
> threads:16 sleep:80 pinned:1
> total operations: 41453784, ops/sec 518172
> 41453784
> [16:58] fox2:/zmeh # rm *                                   
> zsh: sure you want to delete all the files in /zmeh [yn]? y
> [16:58] fox2:/zmeh # /ufs/mjgtmp/write-diff -s 80 -n 16 test
> threads:16 sleep:80 pinned:1
> total operations: 18988638, ops/sec 237357
> 18988638
> 
> -- 
> Mateusz Guzik <mjguzik gmail.com>

-- 
Mateusz Guzik <mjguzik gmail.com>