on a 64 bit SLC6 Corei7@3GhZ machine I see (with ROOT5):
On a RAM drive:
time to write = 12.6441s
time to flush = 2.86102e-06s
time to close = 0.16864s
time to delete = 6.50883e-05s
On a SATA disk
time to write = 13.2336s
time to flush = 0.578267s
time to close = 339.894s
time to delete = 8.29697e-05s
The ramdrive result is (more or less) compatible with what I see on my Laptop with SSD:
time to write = 5.72622s
time to flush = 0.0159581s
time to close = 1.15454s
time to delete = 2.90871e-05s
Analogous results can be measured with ROOT6. A detailed performance measurement will follow.
Hopefully this is a useful data point and not just noise.
On my MacBook Pro (late 2011), with a 2.2GHz Core i7 Intel, 8GB ram, Mac OS 10.9.2, ROOT 5.34/18, compiling with the system clang++ from XCode (clang 5.1), I get these results:
time to write = 4.26822s
time to flush = 0.0455468s
time to close = 4.73587s
time to delete = 4.88758e-05s
Oh, this is writing to the local SATA drive with 35GB empty space remaining.
So, we have something stinky here.
Me and Matt use CentOS 6 / x86_64 but, when writing to a local disk, I get “time to close” = 2 s, while he gets hundreds of seconds (which seems to be consistent with Danilo’s SLC6 result).
One possible reason can be that my CentOS 6 / x86_64 machine uses a “DELL PERC 6/i Adapter” (with 2 SATA disks, most probably configured as RAID 0), while all another test machines seem to use motherboards’ built-in SATA adapters (this is also the case for my Ubuntu / i686 machine which also gives hundreds of seconds “time to close”).
(Well, MacOS results do not necessarily need to be consistent with results from Linux machines.)
The core of the issue is that a TFile::Flush (i.e. a call to fsync) is issue for every single dictionary (there is 5000ish in this example) during the TFile::Close. This is a slow operation (especially when repeated so fast) on some disk system. To work-around the problem you can call:fout->SetBit(TFile::kDevNull);which disable all calls to fsync.
The problem has been resolved in the v5.34 patch branch and the master branch by issuing only one call to Flush (fsync) during a TFile::Close.
I downloaded the newest v5-34-00-patches and I can confirm that this problem disappeared for me. In both cases, when writing to a local SATA disk and to a NFS located one (about 10 MB/s transfer rate), I now get about 4 seconds “time to close”, while on a “lazy” NFS disk (about 5 MB/s transfer rate), I get about 24 seconds “time to close”.
Adding “fout->SetBit(TFile::kDevNull);” (after each of the two “TFile::Open” statements in “many_histograms.cc”) can reduce this time significantly. On a local SATA disk from 4 seconds to about 0.3 second (so it’s more than 10 times faster) while on a “lazy” NFS disk (about 5 MB/s transfer rate) from 24 seconds to about 6 seconds (so it’s about 4 times faster). No significant change was observed for the NFS disk with 10 MB/s transfer rate.
thanks very much for all the contributions and for the solution. I will try updating to the latest patch and, once tested, I’ll mark the thread solved.