Bug 718408

Summary: NFSv3 UPD low performance using dump
Product: [Fedora] Fedora Reporter: Alessandro Selli <alessandroselli>
Component: nfs-utilsAssignee: Steve Dickson <steved>
Status: CLOSED NOTABUG QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 15CC: bfields, jlayton, steved
Target Milestone: ---   
Target Release: ---   
Hardware: i686   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2011-07-06 10:46:48 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Attachments:
Description Flags
wireshark-generated libcap file none

Description Alessandro Selli 2011-07-02 14:30:37 UTC 
Description of problem:
Running dump to backup partitions over an NFSv3 volume (using protocol UDP, but TCP was also tested with like results) yields a very low trasfer rate to the server (about 400KB/sec on a 100mbps LAN). The trasfer rate however is as expected using other comands on the same NFS mount point, such as dd or cat.

Version-Release number of selected component (if applicable):
nfs-utils-1.2.3-11.fc15.i686

How reproducible:
Always upon running dump to create a dump file on a remote NFS volume.

Steps to Reproduce:
1. mount /mnt/nfs/whale/dump_backup
2. dump -D /mnt/nfs/whale/dump_backup/krill_dumpdates -u3f /mnt/nfs/whale/dump_backup/krill_usr_2011-07-02_3.dump -A /mnt/nfs/whale/dump_backup/krill_usr_2011-07-02_3.toc /usr
3.
  
Actual results:
  DUMP: Date of this level 3 dump: Sat Jul  2 15:33:36 2011
  DUMP: Date of last level 2 dump: Thu Jun 16 14:31:26 2011
  DUMP: Dumping /dev/sda5 (/usr) to /mnt/nfs/whale/dump_backup/krill_usr_2011-07-02_3.dump
  DUMP: Label: /usr
  DUMP: Writing 10 Kilobyte records
  DUMP: mapping (Pass I) [regular files]
  DUMP: mapping (Pass II) [directories]
  DUMP: estimated 937184 blocks.
  DUMP: Volume 1 started with block 1 at: Sat Jul  2 15:33:54 2011
  DUMP: dumping (Pass III) [directories]
  DUMP: dumping (Pass IV) [regular files]
  DUMP: 12.94% done at 404 kB/s, finished in 0:33
  DUMP: 25.97% done at 405 kB/s, finished in 0:28
  DUMP: 39.01% done at 406 kB/s, finished in 0:23
  DUMP: 51.82% done at 404 kB/s, finished in 0:18
  DUMP: 65.02% done at 406 kB/s, finished in 0:13
  DUMP: 78.38% done at 408 kB/s, finished in 0:08
  DUMP: 91.27% done at 407 kB/s, finished in 0:03
  DUMP: Closing /mnt/nfs/whale/dump_backup/krill_usr_2011-07-02_3.dump
  DUMP: Volume 1 completed at: Sat Jul  2 16:12:13 2011
  DUMP: Volume 1 935530 blocks (913.60MB)
  DUMP: Volume 1 took 0:38:19
  DUMP: Volume 1 transfer rate: 406 kB/s
  DUMP: 935530 blocks (913.60MB) on 1 volume(s)
  DUMP: finished in 2298 seconds, throughput 407 kBytes/sec
  DUMP: Date of this level 3 dump: Sat Jul  2 15:33:36 2011
  DUMP: Date this dump completed:  Sat Jul  2 16:12:13 2011
  DUMP: Average transfer rate: 406 kB/s
  DUMP: Archiving dump to /mnt/nfs/whale/dump_backup/krill_usr_2011-07-02_3.toc
  DUMP: DUMP IS DONE

Expected results:
  DUMP: Date of this level 3 dump: Sat Jul  2 16:15:34 2011
  DUMP: Date of last level 2 dump: Thu Jun 16 14:31:26 2011
  DUMP: Dumping /dev/sda5 (/usr) to /tmp/dump_pipe
  DUMP: Label: /usr
  DUMP: Writing 10 Kilobyte records
  DUMP: mapping (Pass I) [regular files]
  DUMP: mapping (Pass II) [directories]
  DUMP: estimated 937184 blocks.
  DUMP: Volume 1 started with block 1 at: Sat Jul  2 16:15:50 2011
  DUMP: dumping (Pass III) [directories]
  DUMP: dumping (Pass IV) [regular files]
  DUMP: 78.56% done at 2454 kB/s, finished in 0:01
  DUMP: Closing /tmp/dump_pipe
  DUMP: Volume 1 completed at: Sat Jul  2 16:21:46 2011
  DUMP: Volume 1 935530 blocks (913.60MB)
  DUMP: Volume 1 took 0:05:56
  DUMP: Volume 1 transfer rate: 2627 kB/s
  DUMP: 935530 blocks (913.60MB)
  DUMP: finished in 356 seconds, throughput 2627 kBytes/sec
  DUMP: Date of this level 3 dump: Sat Jul  2 16:15:34 2011
  DUMP: Date this dump completed:  Sat Jul  2 16:21:46 2011
  DUMP: Average transfer rate: 2627 kB/s
  DUMP: Archiving dump to /mnt/nfs/whale/dump_backup/krill_usr_2011-07-02_3.toc
  DUMP: DUMP IS DONE


Additional info:
On NFS server (whale):
grep krill /etc/exports
/mnt/dump_backup/krill  192.168.11.2/32(rw,no_root_squash,sync,no_subtree_check)

On NFS client (krill):
grep ^whale /etc/fstab
whale:/mnt/dump_backup/krill   /mnt/nfs/whale/dump_backup     nfs     nfsvers=3,proto=udp,rsize=8192,wsize=8192,soft,intr,noauto,user,nodev,nosuid,noexec   0 0

The dump output in the "Expected results:" section is the output of an actual dump of the same filesystem (on the NFS client) to the same NFS volume (on the NFS server) with these setup changes:
a) a named pipe was created onthe client machine:
   mkfifo /tmp/dump_pipe
b) a cat command was run in the background reading from the named pipe and writing to the dump file in the NFS volume:
   [root@krill ~]# cat /tmp/dump_pipe > /mnt/nfs/whale/dump_backup/krill_usr_2011-07-02_3.dump &
   [2] 3896
c) the /mnt/nfs/whale/dump_backup/krill_dumpdates was edited to erase the date of the previous level 3 dump;
d) the dump command was run with the named pipe as it's output dump file and everything else unchanged:
   dump -D /mnt/nfs/whale/dump_backup/krill_dumpdates -u3f /tmp/dump_pipe -A /mnt/nfs/whale/dump_backup/krill_usr_2011-07-02_3.toc /usr
Comment 1 Steve Dickson 2011-07-05 11:55:30 UTC 
The writes are probably synchronous... Could you please post 
and trace of the over the wire traffic? Here is how:
   yum install wireshark
   tshark -w /tmp/data.pcap host <server>
   bzip2 /tmp/data.pcap

Also it the client and server both Fedora 15?
Comment 2 Alessandro Selli 2011-07-06 05:19:58 UTC 
Created attachment 511433 [details]
wireshark-generated libcap file

Here is the data requested (bzip2-compressed file of the first 10MB of data).  I confirm both the NFS client and the NFS server are Fedora15 boxes.
Comment 3 Steve Dickson 2011-07-06 10:44:28 UTC 
(In reply to comment #2)
> Created attachment 511433 [details]
> wireshark-generated libcap file
> 
> Here is the data requested (bzip2-compressed file of the first 10MB of data). 
> I confirm both the NFS client and the NFS server are Fedora15 boxes.

Well as expected the dump application is doing synchronous writes,
note the FILE_SYNC flag set in all the WRITEs that are going over
the wire. The last bullet in http://nfs.sourceforge.net/#faq_a1
has a good explanation FILE_SYNC writes.

Do end the end there is not much can be done about the slowness,
at least from an NFS point of view.
Comment 4 Steve Dickson 2011-07-06 10:46:48 UTC 
I'm going to close this for now. If more information comes up please 
feel free to reopen it.