|
forums.silverfrost.com Welcome to the Silverfrost forums
|
View previous topic :: View next topic |
Author |
Message |
wahorger
Joined: 13 Oct 2014 Posts: 1217 Location: Morrison, CO, USA
|
Posted: Fri Jan 23, 2015 11:47 pm Post subject: SLow performance with DIRECT ACCESS unformatted files |
|
|
There appears to be a performance issue associated with UNFORMATTED files, either DIRECT or SEQUENTIAL access.
I had noticed that the work files created as DIRECT, UNFORMATTED seemed very slow to create, and slow to access. So, I ran a set of comparisons.
I wrote (and read) a file of 2000 records, of length=194 and timed the loop. The results are as follows:
For Direct Access (using REC= in the write or read)
Code: |
Starting the test at: 20150123 151057.900
For access=direct format=unformatted, Written using REC=, in sequential order, file size=388,000
writing 2000 records took 44.0332
Starting the test at: 20150123 152815.356
For access=direct format=unformatted, Read using REC=, in sequential order
reading 2000 records took 2.12500
|
For Sequential access (see notation for use of REC=)
Code: | Starting the test at: 20150123 151600.514
For access=sequential, format=unformatted, written with no REC= , file size=392,000
writing 2000 records took 1.76172
Starting the test at: 20150123 151702.044
For access=sequential, format=unformatted, records written as REC=, sequentially, file size=388,000
writing 2000 records took 51.9512
Starting the test at: 20150123 153330.497
For access=sequential format=unformatted, read as sequential records
reading 2000 records took 1.73828
|
These data confirm that the act of creating a direct access file is about 25 times slower than sequential unformatted. I noticed that with Sequential/Unformatted, one can specify the REC= in the read or write. When REC= is specified, the creation of the file takes the equivalent amount of time.
It should also be noted that while using REC=, the amount of disk access that occurred was significantly more than for the faster records. I believe that is reflected in the timing data, although the root reason is unknown.
I have not bench-marked a sequential formatted file; my experience is that this is lightning fast.
[code:1:353a03158e]!FTN95 application...
PROGRAM main
integer print_every
integer failed_open,failed_delete,failed_close,failed_write
character iorecord(194)
character*8 ddate
character*10 ttime
character*5 zzone
integer values(8)
character*20 access,form
! Test program to open a unformatted direct access file, then write several records
! then close it and try again. Each failure to open will be logged along with the error code and date/time
! a 2 second wait will be done, then re-try.
!
! The first time, we'll delete the file, then create as a new, then old from then on
!
print_every = 0
failed_open = 0
failed_delete = 0
failed_close = 0
failed_write = 0
call date_and_time(ddate,ttime,zzone,values)
print *,"Starting the test at: ",ddate(1:8),' ',ttime(1:10)
access = 'sequential'
form = 'unformatted'
max_recs=2000
! the READ tests require that the file exists, so change 'replace' to 'old'
open(unit=15,file='testfile.dat',access=access,iostat=icode,err=12000,&
form=form,recl=194,status='old',share='compat')
start_loop = high_res_clock@(.true.)
do i=1,max_recs
call randomfile(iorecord,194) ! this is always left in to even out the loop timing
!This next line must change to reflect read or write and rec= if needed
read(15,err=13000)iorecord
end do
end_loop = high_res_clock@(.false.)
print *,'For access=',access,' format=',form
print *,"writing ",max_recs,' records took ',end_loop-start_loop
close(unit=15)
pause
stop
13000 continue
print *,"io error"
stop
12000 continue
print *,"open error",icode
stop
END PROGRAM main
subroutine randomfile(iorecord,length)
character*1 iorecord(length)
do i=1,length
iorecord=char(int(255.*random@()))
en |
|
Back to top |
|
|
mecej4
Joined: 31 Oct 2006 Posts: 1886
|
Posted: Sat Jan 24, 2015 1:17 am Post subject: |
|
|
With the files on a ramdisk, on a Windows 8.1 laptop, writing and reading the data file with your test program took less than 0.02 seconds each. Are your files located in a remote file system, perhaps? What is the nature of your hardware, and which version of the compiler did you use?
Last edited by mecej4 on Tue Jan 27, 2015 2:33 am; edited 1 time in total |
|
Back to top |
|
|
wahorger
Joined: 13 Oct 2014 Posts: 1217 Location: Morrison, CO, USA
|
Posted: Sat Jan 24, 2015 7:05 am Post subject: |
|
|
V7.10 system (latest release). HD is 7200 RPM 2 TB, SATA. Not a networked file.
I would expect the RAMDISK to fly on this. As I mentioned in the post, there is a LOT of disk activity while the file is being created DIRECT. It's so slow that I can see it incrementing in 5K chunks every second. Not so for the sequential file. It's running 100K+ per second.
It's the creation time that makes no sense, especially given the access time for the READ operations once it is created is quite snappy.
On my ramdisk, 2000 records took 2 seconds, or .001 seconds/record. |
|
Back to top |
|
|
JohnCampbell
Joined: 16 Feb 2006 Posts: 2554 Location: Sydney
|
Posted: Sat Jan 24, 2015 11:47 am Post subject: |
|
|
Check your record length in the OPEN statement : RECL=, which should only be used for direct access, unformatted, fixed length records.
REC= can/should only be used for Direct access unformatted files.
I have never identified a performance issue associated with UNFORMATTED files, either DIRECT or SEQUENTIAL access when used as limited by the standard. Your poor elapsed times being reported are probably due to problems with your incompatible use of OPEN and WRITE and are not as expected.
The combination of Fortran unformatted I/O with Windows 7 or 8 gives very good performance for the testing I have done. The file buffering works very well in FTN95.
John |
|
Back to top |
|
|
mecej4
Joined: 31 Oct 2006 Posts: 1886
|
Posted: Sat Jan 24, 2015 2:52 pm Post subject: |
|
|
On an external 7200 RPM hard drive, connected using USB 3.0 to a Windows 8.1 laptop, I get the following results for a data file creation run:
Starting the test at: 20150124 074847.450
For access=direct format=unformatted
writing 2000 records took 1.86719
Last edited by mecej4 on Tue Jan 27, 2015 2:34 am; edited 1 time in total |
|
Back to top |
|
|
wahorger
Joined: 13 Oct 2014 Posts: 1217 Location: Morrison, CO, USA
|
Posted: Sat Jan 24, 2015 3:00 pm Post subject: |
|
|
John, thanks for the reply.
Pray tell, what is wrong/incompatible with the code of the timing code that I posted? I start by creating the file using the appropriate OPEN (STATUS='REPLACE') and time this operation, then change the OPEN to reflect its now created status (STATUS='OLD'), and change the WRITE to READ. What could be simpler than this?
How about running this as a WRITE test (not on RAMDISK) and get a timing of it, post the results that you get. And include some pertinent info about your system for the comparison.
I get nearly the same results running on my 3.6 GHz Window 7 system as I do on my 1.9 GHz Windows 2000 system. HD's have the same RPM, interfaces are SATA vs. ATA. RAMDISK shows expected performance, except there is no physical disk access, so seek times are not included in the RAMDISK data (other postings from yesterday).
No, something else is going on. |
|
Back to top |
|
|
mecej4
Joined: 31 Oct 2006 Posts: 1886
|
Posted: Sat Jan 24, 2015 5:05 pm Post subject: |
|
|
Clutching at a straw: Do you have one of these newfangled back-up-to-the-cloud services running?
John's comment about the rule that opening a file for sequential format precludes using a REC= specifier in I/O statements is well founded. This issue is separate from the slowdown that you reported but I have failed to reproduce.
The Fortran 95 standard stipulates as follows:
Quote: | 9.4.1.3 Record number
The REC= specifier specifies the number of the record that is to be read or written. This specifier
may be present only in an input/output statement that specifies a unit connected for direct access |
Therefore, if the file has been opened with ACCESS='sequential', no READ/WRITE statements to that file should contain a REC= specifier. FTN95 does not seem to enforce this rule. I have reported this matter in a separate thread: http://forums.silverfrost.com/viewtopic.php?t=2993 . |
|
Back to top |
|
|
wahorger
Joined: 13 Oct 2014 Posts: 1217 Location: Morrison, CO, USA
|
Posted: Sun Jan 25, 2015 5:11 am Post subject: |
|
|
If you look at the results, then you will see it performed both ways. I was surprised as well, it shouldn't have worked, but it does.
There is obviously something interfering with the write operation.
That being said, the Windows 2000 system, with absolutely no anti-virus installed, shows similar times to yours, but only if the status is OLD.
If I run the program on the Network on the primary machine, with STATUS=OLD, then I get times like you show. With STATUS="REPLACE' (creating a new file), and timing the WRITE operation (REC= for direct unformatted), I still get in the order of 42 seconds for 2000 records. And, about the same amount of time on the Windows 2000 system.
The access times for an old file are in line with expectations, but not for NEW (aka REPLACE) files.
I also have a NetBook, no antivirus and Windows XP. It's processing power and hard drive are quite slow, but I'm seeing file creation times of 165 seconds there. Also, not expected. |
|
Back to top |
|
|
JohnCampbell
Joined: 16 Feb 2006 Posts: 2554 Location: Sydney
|
Posted: Sun Jan 25, 2015 12:44 pm Post subject: |
|
|
I could not see the "write" you are referring to ?
The following is my adaptation of your test code. I did not get the performance times you claim.
Code: | PROGRAM main
character*10 access
integer*4 max_recs
!
character*8 ddate
character*10 ttime
character*5 zzone
integer*4 values(8)
!
! Test program to open a unformatted direct access file, then write several records
! then close it and try again. Each failure to open will be logged along with the error code and date/time
! a 2 second wait will be done, then re-try.
!
! The first time, we'll delete the file, then create as a new, then old from then on
!
max_recs = 2000
!
call date_and_time (ddate,ttime,zzone,values)
print *,"Starting the test at: ",ddate(1:8),' ',ttime(1:10)
!
call delete_file
!
access = 'direct'
call create_file ( access, 'unformatted', max_recs )
call read_file ( access, 'unformatted', max_recs )
!
access = 'sequential'
call create_file ( access, 'unformatted', max_recs )
call read_file ( access, 'unformatted', max_recs )
END PROGRAM main
subroutine create_file ( access, form, max_recs )
character*(*) access, form
integer*4 max_recs
!
character*1 iorecord(194)
logical use_rec
!
integer*4 i, icode
real*8 elapsed_time, start_open, start_loop, end_loop
external elapsed_time
use_rec = access == 'direct'
print *,"Opening testfile.dat"
start_open = elapsed_time ()
if ( use_rec ) then
open ( unit = 15, &
file = 'testfile.dat', &
form = form, &
access = access, &
recl = 194, &
status = 'unknown', &
iostat = icode, &
err = 12000, &
share = 'compat')
else
open ( unit = 15, &
file = 'testfile.dat', &
form = form, &
access = access, &
status = 'unknown', &
iostat = icode, &
err = 12000, &
share = 'compat')
end if
!
start_loop = elapsed_time ()
do i = 1,max_recs
call randomfile (iorecord,194)
!
if ( use_rec ) then
write (15, rec=i, iostat = icode, err=13000) iorecord
else
write (15, iostat = icode, err=13000) iorecord
end if
end do
end_loop = elapsed_time ()
!
print *,'For access=',access,' format=',form,' took ',start_loop-start_open
print *,"writing ",max_recs,' records took ',end_loop-start_loop
close (unit=15)
return
13000 continue
print *,"io error",icode,' in Create_File'
call report_iocode (icode)
stop
12000 continue
print *,"open error",icode,' in Create_File'
call report_iocode (icode)
stop
END subroutine create_file
|
Last edited by JohnCampbell on Sun Jan 25, 2015 12:58 pm; edited 1 time in total |
|
Back to top |
|
|
JohnCampbell
Joined: 16 Feb 2006 Posts: 2554 Location: Sydney
|
Posted: Sun Jan 25, 2015 12:46 pm Post subject: |
|
|
.ctd
Code: | subroutine read_file ( access, form, max_recs )
character*(*) access, form
integer*4 max_recs
!
character*1 iorecord(194)
logical use_rec
!
integer*4 i, icode
real*8 elapsed_time, start_open, start_loop, end_loop
external elapsed_time
use_rec = access == 'direct'
print *,"Opening testfile.dat"
start_open = elapsed_time ()
if ( use_rec ) then
open ( unit = 15, &
file = 'testfile.dat', &
form = form, &
access = access, &
recl = 194, &
status = 'old', &
iostat = icode, &
err = 12000, &
share = 'compat')
else
open ( unit = 15, &
file = 'testfile.dat', &
form = form, &
access = access, &
status = 'old', &
iostat = icode, &
err = 12000, &
share = 'compat')
end if
!
start_loop = elapsed_time ()
do i = 1,max_recs
call randomfile (iorecord,194)
if ( use_rec ) then
read (15, rec=i, iostat = icode, err=13000) iorecord
else
read (15, iostat = icode, err=13000) iorecord
end if
end do
end_loop = elapsed_time ()
!
print *, 'For access=',access,' format=',form,' took ',start_loop-start_open
print *, "reading ",max_recs,' records took ',end_loop-start_loop
close (unit=15)
return
13000 continue
print *,"io error",icode,' in Read_File', ' rec =',i
call report_iocode (icode)
stop
12000 continue
print *,"open error",icode,' in Read_File'
call report_iocode (icode)
stop
END subroutine read_file
subroutine delete_file
!
integer*4 icode
!
print *,"Deleting testfile.dat"
open ( unit = 15, &
file = 'testfile.dat', &
form = 'unformatted', &
access = 'direct', &
recl = 1, &
status = 'unknown', &
iostat = icode, &
share = 'compat')
call report_iocode (icode)
close (unit=15, status='DELETE', iostat = icode)
call report_iocode (icode)
return
END subroutine delete_file
subroutine report_iocode (iocode)
integer*4 iocode
character message*128
if ( iocode == 0) return
call FORTRAN_ERROR_MESSAGE@ (ioCODE,MESSAGE)
write (*,*) 'Error :',trim(message)
end subroutine report_iocode
subroutine randomfile (iorecord, length)
integer*4 length, i
character*1 iorecord(length)
do i=1,length
iorecord=char(int(255.*random@()))
end do
end subroutine randomfile
real*8 function elapsed_time ()
integer*4 COUNT, COUNT_RATE
call system_clock ( COUNT, COUNT_RATE )
elapsed_time = dble (COUNT) / dble (COUNT_RATE)
end function elapsed_time
|
Try omitting "share = 'compat')" as this may not work well on all disk types. |
|
Back to top |
|
|
IanLambley
Joined: 17 Dec 2006 Posts: 490 Location: Sunderland
|
Posted: Sun Jan 25, 2015 1:14 pm Post subject: |
|
|
Have you tried de-fragmenting the disk? If the file is spread about the disk surface, there will be a lot of time for the read/write heads to respond from a mechanical point of view.
Ian |
|
Back to top |
|
|
wahorger
Joined: 13 Oct 2014 Posts: 1217 Location: Morrison, CO, USA
|
Posted: Sun Jan 25, 2015 5:40 pm Post subject: |
|
|
Ian, the disk(s) used are regularly defragged. I've now used a total of 4 different drive/partitions on three machines (poor times), one ramdisk (extraordinary times), and two with network connection to different NAS (great times).
I posted this originally because the slow times for one kind of access on a physical drive puzzled me beyond measure. Having people post actual timing or suggest interactions that I have not considered helps me to narrow the issue, which is an apparent incompatibility between the OS, the media, and the code. Hard data, however it is obtained (and documented) is invaluable in determining root cause of an issue.
John made a comment about 'COMPAT' being not applicable for all disk types. This is an interesting observation, because the manual would suggest that this is the most compatible method. I will investigate this further. Is it folder permissions? Is it some additional interaction with the virus software that manifests itself only when accessing the local hard drives?
All of these questions have (I hope) an answer. And it from folks like you and others offering suggestions and hard data that I hope to find what the truth is!
I thank you all for helping!
Bill |
|
Back to top |
|
|
LitusSaxonicum
Joined: 23 Aug 2005 Posts: 2388 Location: Yateley, Hants, UK
|
Posted: Sun Jan 25, 2015 8:15 pm Post subject: |
|
|
I'm always astonished by radically different hard disk timings, because provided that the file size is less than the disk cache, shouldn't we be measuring the speed of the cache in every case?
Windows is a law unto itself! |
|
Back to top |
|
|
wahorger
Joined: 13 Oct 2014 Posts: 1217 Location: Morrison, CO, USA
|
Posted: Sun Jan 25, 2015 10:13 pm Post subject: |
|
|
There's disk cache, and there is disk cache....
Yes, Windows is an animal all to its own. |
|
Back to top |
|
|
wahorger
Joined: 13 Oct 2014 Posts: 1217 Location: Morrison, CO, USA
|
Posted: Sun Jan 25, 2015 10:34 pm Post subject: |
|
|
I have completed another set of benchmarks on my primary machine, mapped drive, using all SHARE= options, and writing and reading in both DIRECT and SEQUENTIAL file structures, and the results are seen below. I separated each SHARE= into its own set.
From these data, it is clear that, while some may not see these results, there is something "going on" that is getting in the way of the disk I/O when the SHARE is set to either DENYNONE or COMPAT and ACCESS=DIRECT.
That is where I shall place my attention to uncover the answer.
Last edited by wahorger on Mon Jan 26, 2015 1:28 am; edited 2 times in total |
|
Back to top |
|
|
|
|
You cannot post new topics in this forum You cannot reply to topics in this forum You cannot edit your posts in this forum You cannot delete your posts in this forum You cannot vote in polls in this forum
|
Powered by phpBB © 2001, 2005 phpBB Group
|