Issues with file operations or why is vi slower than dd?

R

r2p42

I have a FreeNAS Mini running with a jail for Nextcloud. While moving my files from Dropbox to the Nextcloud instance, I realized that there are many fastcgi timeouts happening.
In order to investigate the cause, I observed a strange behavior which I don't really understand but my hope is that my Nextcloud synchronization problem will be fixed if I fix that behavior...

So what am I talking about?

If i connect to my FreeNAS via SSH and try to quit a vi instance with saving a file ( :wq), than it takes about 3 - 4 seconds for vi to quit. That's already way to long for my taste. Especially if the file is empty.
But when I join the Nextcloud jail ( iocage exec nextcloud sh) and do the same there, vi needs not less than 9 seconds.

When writing a file with dd is super fast in comparison. Both inside and outside the jail.

Code: 
# dd if=/dev/zero of=data.dat bs=1k count=1
1+0 records in
1+0 records out
1024 bytes transferred in 0.000075 secs (13688559 bytes/sec)

I cannot make any sense of these differences and how I can speedup those simple non-dd file operations.

Thanks in advance for any hints.
 
FreeBSD people know all kinds of things, including expansion properties of various metals and vapor pressure of propane. But ..... ;)
 
The question in this case is that there are differences between FreeBSD and FreeNAS, so this behavior may not necessarily show up in FreeBSD. (Or it might, in which case, someone may see your post and give an answer.)
 
r2p42 said:
If i connect to my FreeNAS via SSH and try to quit a vi instance with saving a file ( :wq), than it takes about 3 - 4 seconds for vi to quit. ...
But when I join the Nextcloud jail ( iocage exec nextcloud sh) and do the same there, vi needs not less than 9 seconds.
Click to expand...
Agreed: 3-4 seconds to write a file to a local file system is ridiculous for most servers, and 9 seconds is right out. (I write most servers because there are rare situations where latencies of multiple seconds are actually the optimal operating condition).
Most likely, something is gravely misconfigured in your system. My educated guess would be that you are badly running out of memory; perhaps you need to set up a swap file, or perhaps ZFS is misconfigured and ate way too much memory. On a native FreeBSD installation with recent software this should not happen, except if you use ZFS on low-memory machines (GB of memory can be counted on fingers without using toes), you need to hand-configure certain memory limits. I have no idea how FreeNAS handles this stuff. It could also be that all your memory subsystem is ridiculously overstressed, and starting or ending the vi process takes many seconds (in which case, your OS needs serious help).

When writing a file with dd is super fast in comparison. Both inside and outside the jail.
Click to expand...
Two criticisms of your measurement. First, I suspect that vi not only writes the file, but also sync's it (see the fsync(2) call and the fsync(3) utility). On the other hand, dd definitely does not sync the file (and the various sync options in the dd command don't do that either, they do a completely different operation). For a fair comparison, you should probably do first dd, followed by "fsync data.dat", and time them together. That is most easily done by writing a tiny 3-line script containing the dd and fsync commands, and measuring them together with /usr/bin/time.

Once you have more and better measurements, either things will become clear, or go talk to the support mechanism for your OS configuration.
 
I don't think memory is the issue, there is plenty of it which does not seem to be used.

top:
Code: 
Mem: 227M Active, 2838M Inact, 12G Wired, 514M Free

But I executed your recommended combination of dd and fsync .

Yesterday in the evening:
Code: 
 5.94 real         0.00 user         0.00 sys
11.55 real         0.00 user         0.00 sys
 3.07 real         0.00 user         0.00 sys
 2.08 real         0.00 user         0.00 sys
 3.04 real         0.00 user         0.00 sys
 0.69 real         0.00 user         0.00 sys
 1.50 real         0.00 user         0.00 sys
 6.04 real         0.00 user         0.00 sys

Now:
Code: 
0.74 real         0.00 user         0.00 sys
1.22 real         0.00 user         0.00 sys
1.70 real         0.00 user         0.00 sys
0.02 real         0.00 user         0.00 sys
1.08 real         0.00 user         0.00 sys
2.31 real         0.00 user         0.00 sys
2.18 real         0.00 user         0.00 sys
1.53 real         0.00 user         0.00 sys
1.49 real         0.00 user         0.00 sys
1.53 real         0.00 user         0.00 sys
1.51 real         0.00 user         0.00 sys

I am unsure if those times are to be expected. But I guess vi needs even longer since it writes and syncs more files under the hood? Like a swap file or maybe a command history?
 
Absolutely not. Even the good times are ridiculously large. I just ran the following script:
Code: 
> cat /tmp/dd_sync.sh
#!/bin/sh
dd if=/dev/zero of=/home/ralph/foo.test.$$ bs=1024 count=1
fsync /home/ralph/foo.test.$$
about 10 times in a row, and the longest result I saw was "0.04 real 0.00 user 0.00 sys", typical results are 0.01 or 0.02. That's on a stock FreeBSD 11.X, with ZFS file system that is running on normal spinning disks (not SSD) and mirrored, so the time should be dominated by two disk write operations running in parallel and waiting for the longer of the two, and with normal 7200 RPM near-line drives that should take 0.0083 second for the disk rotation (typically half that), and typically 0.01 second for a short seek (the head won't be moving much, my system is mostly idle), so the result makes sense. Your results are 100x slower when good, and the 11.55 seconds you saw once is ridiculous. Something is broken.

I don't know about your system (is it in production? how valuable is the data?), nor about FreeNAS. I would start with testing the IO speed of the raw disk. Start with just a few dd commands, first individual short IOs, then long IOs, then sequential IO. Obviously, you can only read, otherwise you'll destroy your disks. Then find a disk benchmark program (Bonnie, FIO, ...), and run it against the raw disk. You should be getting 0.01 seconds for individual short IOs, at least 100 IOps for random short IO, and at least 100 MByte/s for large sequential IO. If you are still good, try the same thing through the file system.
 
It seems as if it actually can be fast, I just have to figure out why its sometimes not.
Code: 
        0.02 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.03 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.03 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.28 real         0.00 user         0.00 sys
        0.04 real         0.00 user         0.00 sys
        0.27 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.03 real         0.00 user         0.00 sys
        0.19 real         0.00 user         0.00 sys
        0.03 real         0.00 user         0.00 sys
        0.03 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.14 real         0.00 user         0.00 sys
        0.04 real         0.00 user         0.00 sys
        0.15 real         0.00 user         0.00 sys
        1.17 real         0.00 user         0.00 sys
        0.08 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.02 real         0.00 user         0.00 sys
        0.06 real         0.00 user         0.00 sys
        1.79 real         0.00 user         0.00 sys
        1.54 real         0.00 user         0.00 sys
        1.42 real         0.00 user         0.00 sys
        1.51 real         0.00 user         0.00 sys
        2.20 real         0.00 user         0.00 sys
        2.25 real         0.00 user         0.00 sys
        1.92 real         0.00 user         0.00 sys

I guess I could run this all day long after adding a timestamp to crosscheck with my system logs if anything happens around those times. All I can say for sure is that no scrubs and smarts were running while I posted my first findings.

The system is my private storage which I bought to move most of my data from dropbox, google and other cloud service providers into my own hands. The data is backed up twice at different locations but I would prefer not to setup everything again. Currently it is using 4 drives in a raidz2 configuration. It should be fine if I destroy one drive in order to run some performance tests on it. But based on the fact that the current measurements show that the system is actually able to sync fast, I would assume, that the hard drives are not the issue?
 
Don't assume, measure. Do read tests on the raw disk drives. It is possible you have a problem in the IO stack (let me make a crazy but possible example: bad cable causing occasionally the device driver for your HBA go into a rare bug, been there done that got the T-shirt).

You can't do write tests on individual disk drives, because you have a file system on them. But perhaps you can find a little unallocated space in the partition table, create a small test partition there, and do write tests.

Why do I want to do these tests? Because you need to narrow down at which layer the problem occurs. By doing low-level IO tests, you can eliminate a large fraction of the IO stack.
 
You must log in or register to reply here.
Back
Top