From: Park Heesob <phasis@...>
Date: 2002-11-18T13:08:28+09:00
Subject: Re: Not really a ruby question, but this is a smart group.  Win32 file.write timing.

Hi,
"MetalOne" <jcb@iteris.com> wrote in message
news:92c59a2c.0211161530.1c8a8de0@posting.google.com...
> I am trying to write non-compressed video to a file at 40 fps.
> My write times under Win32 are highly erratic.
> The following ruby script will demonstrate this.
> I have the same problem in C++, with the Win32 APIs, so it is not a
> Ruby issue.
>
> The script does the following:
> 1) Writes 4000 frames at 640x240.  614MB total. Each frame is just a
> bunch of zeroes.
> 2) Times each frame write.
> 3) Writes a log file, listing the time for each frame and the
> corresponding
> frame number.  The file is in descending order of write times.
>
> Observations:
> For my computer system(866Mhz PIII, 100 ATA IDE drive), the log file
> will show write times between less than 10ms and greater than 150ms.
> In C++ using tick counts I see writes between 1.5ms and 160ms.
>
> I don't understand the reason for the huge timing difference.
> I have tried defragging the drive first.
> I have even tried overwriting an existing file, after defragging.
> Is this just the nature of drives, does seek time kill me?
> Still seek + latency should be around 10ms + 5ms?  Way less than
> 150ms.
> Do the Win32 write API's suck?
>
> Here is the script.
> Could somebody run it on a Linux box and report, whether it has the
> same issue.
>
> #####################################
> #dummy data for the frame to write
> s = '0'*640*240
>
> # A nested list of [frameNo, usecs to write frame]
> l = []
>
> timeStart = Time.new
> File.open("test.dat", "w") do |file|
> 4000.times do |frameNo|
> t0 = Time.new
> file.write s
> tdelta = Time.at(Time.new - t0)
> l << [frameNo, tdelta.usec]
> end
> end
> timeEnd = Time.new
> timeDelta = Time.at(timeEnd-timeStart)
> puts "total time: #{timeDelta.min}:#{timeDelta.sec}.#{timeDelta.usec}"
>
> #sort the list using usecs descending
> sortedList = l.sort { |a,b| b[1] <=> a[1] }
> File.open("log.txt", "w") do |logfile|
> sortedList.each { |frameNo, usecs| logfile.puts "#{usecs}:
> #{frameNo}" }
> end

I think it's due to Ruby's GC behavior and time object.

Try this:

#####################################
#dummy data for the frame to write
s = '0'*640*240

# A nested list of [frameNo, usecs to write frame]
l = []

GC.disable  ## disable GC

timeStart = Time.new
File.open("test.dat", "w") do |file|
4000.times do |frameNo|
t0 = Time.new  ## Creates a new time object
file.write s
tdelta = Time.at(Time.new - t0)  ## Creates a new time object
l << [frameNo, tdelta.usec]
end
end

GC.enable  ## enable GC

timeEnd = Time.new
timeDelta = Time.at(timeEnd-timeStart)
puts "total time: #{timeDelta.min}:#{timeDelta.sec}.#{timeDelta.usec}"

#sort the list using usecs descending
sortedList = l.sort { |a,b| b[1] <=> a[1] }
File.open("log.txt", "w") do |logfile|
sortedList.each { |frameNo, usecs| logfile.puts "#{usecs}:#{frameNo}" }
end


Park Heesob