Very slow writing to network drive

Hi folks

I'm having a performance problem with writing to file on a networked drive. Writing out a biggish (4001x4001) array to file, it's taking over half an hour going to shared storage on a NAS box. Going to a local HDD, it takes about 37 seconds. (File size about 150MB.)

It's not network speed. We use gigabit networking and copying the file from local disk to NAS box takes about 4 seconds.

It's not the fact that the NAS box isn't running Windows. The same test done to a genuine Windows share on another PC came in only very slightly faster.

Both the file opening and the write are buried in fairly large libraries, but the operative bits of code are nothing unusual:

      OPEN(IFILE,FILE=NAMEF,STATUS='NEW',
     &     ACTION='WRITE',ERR=10,IOSTAT=IERROR)
      
      ...

      DO J = MINROW,NZROW
             WRITE(IFILE,'(6(F0.3,'' ''))',ERR=9000)
     &              (ZMAT(I,J),I=MINCOL,NZCOL)
      END DO

The compile options are likewise nothing special. Libraries are built with -mklib but otherwise all compile options are as default. I use -undef and -check during testing, but these timings were obtained with those switched off. The big array is in a common block but passed to the library routine that does the writing as an argument. Linking is done with virtualcommon.

However, there is nothing fundamentally wrong with performance as the timing to a local drive demonstrates. The issue is network performance. Test code written in VB.NET and Perl doesn't have this performance issue, which suggests there isn't anything much wrong with my network connection.

From what I can observe of the behaviour, I believe there is a lot of unnecessarily frequent flushing to disk going on writing to the NAS box. Can anyone offer any ideas if this diagnosis makes sense and, if so, what to do about it? Any useful compile options I should be using? Any cunning wheezes about opening files?

(For completeness FTN95 V5.50; compiling and linking on WinXP 32 Pro; also testing on Vista 64 and Win7 64; no 3rd party libraries involved - only stuff I've written and compiled myself.)

Thanks

Ian[/code]

Ian,

By testing on the local HDD and getting 4 mbyte/second; this is a bit slow but not dramatic. I would hope for about 10 mb/sec. This establishes that the program run time is sensible.

The difference between your copy to NAS box (4 seconds) and the Fortran Write, is that for each of the J loops, you are doing a write which is extending the size of the file. Each of these may be making additional requests to the FAT on this drive. I would suggest the problem is between the fortran writes allocating extended file size on the NAS for each write.

I would suggest you could:

1. Do a single write of the whole array and see if that is any faster ( this would have fewer file extension calls to the NAS, although the fortran I/O disk buffering may cover for this)

   WRITE (IFILE,'(6(F0.3,'' ''))',ERR=9000) 
   

   & ((ZMAT(I,J),I=MINCOL,NZCOL) ,J = MINROW,NZROW)

2. Similarly, write only half the file and see if it takes half as long. If it takes a lot less than half, it could be the delays in extending the file on the NAS.

3. I do not know of a way to control the fortran writes into a memory buffer and only update the file on disk when all writes are complete. Check what buffering interface is nominated for the disk drive. You may be able to change this.

4. Changing the write to binary may help, as this could reduce the file size (4 bytes for a real4 or 8 bytes for a real8 ) but this depends on the future use of the file. I always prefer a text file as it is easier to look at with notepad.

I'd be interested if my assumption of the problem is correct.

John

John

Useful food for thought there.

By testing on the local HDD and getting 4 mbyte/second; this is a bit slow but not dramatic. I would hope for about 10 mb/sec. This establishes that the program run time is sensible.

It has to be said that my development box isn't the latest or greatest - it's the one I do emails on and compile Fortran on - I have a newer and nicer one for actually running things on. However, it establishes that the program run time is reasonable.

1. Do a single write of the whole array and see if that is any faster ( this would have fewer file extension calls to the NAS, although the fortran I/O disk buffering may cover for this)

I'll try this for testing purposes to see what happens. However the outer loop is separate for a reason - to ensure that each row of the array starts at the beginning of a new line in the file for compatibility with other programs that have to read it. (Also to facilitate hacking with text editor!)

2. Similarly, write only half the file and see if it takes half as long. If it takes a lot less than half, it could be the delays in extending the file on the NAS.

Array size is data set dependent (it's actually a DTM) - I'll knock up a 4000x2000 and get some metrics on that too.

I always prefer a text file as it is easier to look at with notepad.

And for machine independence. We still have data files kicking around that go back to the early 1980s. (We were building on Prime, DecSystem10, VAX/VMS, Sun3 and Sun4 before we ended up on PCs!)

I'll go play and report back.

Ian

Result of a quick experiment in Perl:

The code (for those interested in languages with semicolons) is as follows:

# Test speed of writing 4001x4001 array to file

use FileHandle;

$nzrow=4000;
$nzcol=4000;
#$outfile = 'c:\\temp\\perl-test.txt';
$outfile = 'perl-test.txt';

# Random data
for $i (0..$nzcol) {
	for $j (0..$nzrow) {
		$zmat[$i][$j] = rand;
	}
}

# Timer
$starttime = time;

# Open file
$fhout = new FileHandle '> $outfile';

# Write array
for $i (0..$nzcol) {
	for $j (0..$nzrow) {
		printf $fhout '%0.3f\\n', $zmat[$i][$j];
	}
}

# Close file
$fhout->close;

# Elapsed time
$elapsed = time-$starttime;
print 'Time to write file = $elapsed s\\n';

The timings were 75 seconds to local HDD and 108 seconds to NAS. Given that I have a separate call to printf for every element of the array, it's about as inefficiently coded as it could be. Also, nothing here knows how big the file is going to be, so every bufferful to disk must extend the file.

Whatever FTN95 is doing in my program, it must be less efficient than what Perl does here. Back to Fortran to do some more tests next.

Ian

OK, lots of testing done. Here's the results:

First test was to replace a write statement inside a loop with a write statement with one more layer of implied-do (as John suggested). No measurable difference in performance.

Next test was to write a minimal FTN95 program to try to exhibit the same behaviour as my real application. Here it is:

       program fortrantest

       !character(len=*),parameter :: filename='c:\\temp\\fortran-test.txt'
       !character(len=*),parameter :: filename='fortran-test.txt'
       character(len=*),parameter :: filename='z:\\junk\\fortran-test.txt'
       integer,parameter :: nzcol = 4000
       integer,parameter :: nzrow = 4000
       real,dimension(0:nzcol,0:nzrow) :: zmat
       integer :: i
       integer :: j
       real :: starttime
       real :: endtime
       real :: elapsed
       integer,parameter :: ifile = 7

       call random_number(zmat)

       call clock@(starttime)

       open(ifile,file=filename,action='write')

       do j = 0,nzrow
           write(ifile,'(6(f0.3,'' ''))') (zmat(i,j),i=0,nzcol)
       end do

       close(ifile)

       call clock@(endtime)
       elapsed = endtime-starttime
       print '(a,f0.3,a)','Time to write file = ',elapsed,' s'

       end program

The FTN95 results were interesting:

Writing to local disk drive: 28 secs Writing to shared drive on another PC on the office LAN: 562 secs (9 mins) Writing to NAS (Infrant ReadyNAS NV+): 1929 seconds (32 mins)

As a comparison, I tried the same program in C (built with SCC):

Writing to local drive: 31 secs: Writing to shared drive on another PC: 34 secs Writing to NAS: 51 secs

In an attempt to destroy the performance of the C version, I put an fflush() straight after the fprintf() that outputs each element of the array:

Writing to local drive: 92 secs Writing to shared drive on another PC: 74 secs Writing to NAS: 90 secs

(No, I don't understand this group of results either!)

Even flushing after writing each element of the array (ie something over 16 million flushes), the C version still comes in faster than FTN95 by a factor of 20 when writing to the NAS box.

Any bright ideas?

Ian

Sorry, no bright ideas ! I changed your program to see if the writes were not uniform. See if that shows something.

Code updated below

I did notice run time changes on rerun if the file already existed. There has to be something in how the fortran I/O buffering is interfacing to this disk type. Does the disk time out between accesses ? Try 'open (ifile,file=filename)' and see what the defaults do

John

I tried modifying the OPEN statement and got significant improvement in the run time for my C: drive. I would expect that 'open (ifile,file=filename)' will probably have a siginificant effect on your run times also.

       character(len=*),parameter :: file_name='c:\\temp\\fortran-test.txt' 
!       character(len=*),parameter :: file_name='fortran-test.txt' 
!       character(len=*),parameter :: file_name='z:\\junk\\fortran-test.txt' 
! 
       integer,parameter :: nzcol = 4000 
       integer,parameter :: nzrow = 4000 
       real,dimension(0:nzcol,0:nzrow) :: zmat 
       integer :: i 
       integer :: j 
       real :: starttime 
       real :: endtime 
       real :: elapsed 
       character string*60 
       integer,parameter :: ifile = 7 

       open ( unit=98, file='write_test.log', position='append')
       write (98,9000) 
9000   format (/80('=')/1x)
       call pnou ('Test for action=write for new file')

       call pnou ('Deleting file '//file_name)     !  did not have a significant effect
       call open_file (ifile, file_name) 
       close (ifile, status='delete') 

       call pnou ('Intitalising array') 
       call random_number (zmat) 

       call clock@ (starttime) 

       call pnou ('Opening file '//file_name) 
       call open_file (ifile, file_name) 

       do j = 0,nzrow 
           if (mod(j,200)==0) then 
             write (string,'(a,i0)') ' Writing row ',j 
             call pnou (string) 
           end if 
           write (ifile,'(6(f0.3,'' ''))') (zmat(i,j),i=0,nzcol) 
       end do 

       close (ifile) 

       call clock@ (endtime) 
       elapsed = endtime-starttime 
       write ( *,1001) ' Time to write file = ',elapsed,' sec' 
       write (98,1001) ' Time to write file = ',elapsed,' sec' 
1001   format (a,f0.3,a) 

       call pnou ('Deleting file '//file_name) 
       call open_file (ifile, file_name) 
       close (ifile, status='delete') 
  
       call pnou ('Opening file '//file_name//' again') 
       call open_file (ifile, file_name) 

       call pnou ('now single write to new file') 
       write (ifile,'(6(f0.3,'' ''))') ((zmat(i,j),i=0,nzcol),j=0,nzrow) 
       call pnou ('single write to new file complete') 

       end program 

       subroutine pnou (string) 
       character string*(*) 
       real start, now, last 
       data start, last / 2*-1 / 
! 
       call clock@ (now) 
       if (start < 0) then 
          start = now 
          last  = now 
       end if 
       write ( *,1001) trim (string), now-start, now-last 
       write (98,1001) trim (string), now-start, now-last 
       last = now 
1001   format (1x,a,t70,f7.2,f7.3) 
       end

       subroutine open_file (ifile, file_name)
       integer*4 ifile, iostat
       character file_name*(*)
       character string*60 
!
       open ( unit   = ifile,         &
              file   = file_name,     &
              access = 'sequential',  &
              form   = 'formatted',   &
! bad              action = 'write',       &
              action = 'readwrite',   &
              status = 'unknown',     &
              iostat = iostat)
!   
       write (string,1001) trim(file_name),ifile, iostat
1001   format ('File ',a,' opened on unit ',i0,': status = ',i0)
       call pnou (string)
       return
       end

With this program, changing to 'readwrite' reduces run time by a factor of 7

John

I did a few tests over the weekend, when time permitted ! The revised program reduces the run time by a factor of 7 on the c: drive if access='readwrite'. I would expect this could apply to other drives also.

John

John

Thanks for your detective work. I didn't bother with my test program - I just went straight to the production code. Knocking out ACTION='WRITE' dropped the save time for the test file I've been using from 32 minutes to 28 seconds (going to the NAS box).

I like to think I would have got there eventually, but it would have taken me a very long time to think of tinkering with the read/write mode of the file. Thanks for taking the time to fiddle.

The upside of this is that the open statement is in a library, so having got things working for one application, I just have a lot of relinking to do now.

So much for naively expecting that telling the compiler what I want to do with the file would give the best chance of optimising the object code!

Ian

Ian,

It may be that when selecting the action='write', FTN95 may assume that another process may be opening the file with action='readonly' and as such the buffers must always be 'flushed' after each write. Someone may be able to comment on this. I don't know of a detailed description of the difference between different options for OPEN iolist specifiers. Whatever the reason, I have found it is always a good principal with OPEN to use the default settings where possible.

John