weird lock contention problem during parallel writes to different files

[Mateusz Guzik]

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

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>