Re: efficiency of addfiles

From: Gerry Creager <gerry.creager_at_nyahnyahspammersnyahnyah>
Date: Thu, 04 Sep 2008 08:42:04 -0500

Marcus,

I note that Dennis has also responded by now. These comments are
supportive of his, as well.

As a general rule of thumb, bandwidth monitors that report in 'MB/s'
are, in fact, looking at megabytes per second. Most network engineers,
rather than being explicit and precise, will simply multiply that number
by 10 to get the data rate in megabits.

According to what you present, you're saturating your network connection
(100Mb/s).

It appears that the readfiles (reading from disk into memory) takes ~600
sec, and that subsequent re-reads through memory take about the same.
You appear to be getting good addfiles bandwidth, but it's taking a
finite period to reread the arrays from memory. All of the reserved
memory for your files (12.5GB).

I will admit that 10 min does seem a bit excessive. How much physical
memory do you have on the machine processing this script? I suspect
you're swapping a lot out to disk here. That's time consuming.

Saturating your network bandwdith (12MB/s ~= 100Mb/s when one includes
packet overhead) means you are looking at a LONG time to read a 12.5GB
file across the network. Nearly 18 minutes assuming no network retries.
  You're accomplishing it, somehow, in less than 10 min. What this
suggests to me is that it's identifying the files and variables, and
going back and reading them on the fly (I'm gonna have to spend some
quality time in the source code to be sure). I don't know how it could
subset the files held remotely, though, so I suspect there's a problem
with your use of 'date' to get your timings.

I'd suggest you try to do this as a multi-part experiment using the
'time' command, and do it in the following manner (pseudocode, rather
than NCL script):
"time ncl script1.ncl"
script1.ncl-PCode
begin
        f = addfiles( files, "r" )
        printFileVarSummary( f[0], "ui_yz" )
end

"time net script2.ncl"
script2.ncl-PCode
begin
        f = addfiles( files, "r" )
        printFileVarSummary( f[0], "ui_yz" )
        u = f[:]->ui_yz( :, (/25,33,65/), (/47,135,164/), 0 )
end

"time ncl script3.ncl
script3.ncl-PCode
begin
        f = addfiles( files, "r" )
        printFileVarSummary( f[0], "ui_yz" )
        u = f[:]->ui_yz( :, (/25,33,65/), (/47,135,164/), 0 )
        v = f[:]->vi_yz( :, (/25,33,65/), (/47,135,164/), 0 )
        w = f[:]->wi_yz( :, (/25,33,65/), (/47,135,164/), 0 )
        z = f[0]->zu
        t = f[:]->time
end

These will give a better indication of actual system time used.

gerry

Marcus Letzel wrote:
> Dear All,
>
> the below snippets of an NCL script and its output show that it takes
> NCL quite some time to execute the "addfiles" command on a set of four
> NetCDF files of a total size of 12.5 GB. The bandwidth of file data
> access is limited by a 100Mbps network connection, and consistently
> the monitored data transfer during execution of the NCL script rates at
> 12 MB/s. To access 12.5GB @ 12MB/s requires about 1100s. Each of the
> following four commands requires about 600 seconds (cf. script output
> below):
> f = addfiles( files, "r" )
> u = f[:]->ui_yz( :, (/25,33,65/), (/47,135,164/), 0 )
> v = f[:]->vi_yz( :, (/25,33,65/), (/47,135,164/), 0 )
> w = f[:]->wi_yz( :, (/25,33,65/), (/47,135,164/), 0 )
>
> Question 1:
> What does "addfiles" do that requires so much time? Can I somehow avoid
> this?
>
> Question 2:
> I understand that reading a subarray of dimension 16000 x 3 x 3 of the
> files is not very CPU time-efficient method because it saves only less
> than 50% of the CPU time that would be required to read one full array
> (2.5 GB).
> Yet, does someone know how I could possibly improve my data input CPU
> time-efficiency here?
>
> Kind wishes,
> Marcus
>
>
> NCL code snippet
> ================
> begin
>
> [...]
>
> wc0 = systemfunc("date")
>
> ;
> ; open input file(s)
> f = addfiles( files, "r" )
> ;
> ; data input
> wallClockElapseTime(wc0,"initialization",0)
> wc1 = systemfunc("date")
>
> printFileVarSummary( f[0], "ui_yz" )
> wallClockElapseTime(wc1,"FileVarSummary(ui_yz)",0)
> wc2 = systemfunc("date")
>
> u = f[:]->ui_yz( :, (/25,33,65/), (/47,135,164/), 0 )
> wallClockElapseTime(wc2,"read u",0)
> printVarSummary( u )
> wc3 = systemfunc("date")
>
> v = f[:]->vi_yz( :, (/25,33,65/), (/47,135,164/), 0 )
> wallClockElapseTime(wc3,"read v",0)
> wc4 = systemfunc("date")
>
> w = f[:]->wi_yz( :, (/25,33,65/), (/47,135,164/), 0 )
> wallClockElapseTime(wc4,"read w",0)
> wc5 = systemfunc("date")
>
> z = f[0]->zu
> t = f[:]->time
> wallClockElapseTime(wc5,"read z,time",0)
> wc6 = systemfunc("date")
>
> [...]
>
> end
>
>
> NCL output snippet
> ==================
>
> [...]
>
> (0)
> =====> Wall Clock Elapsed Time: initialization: 565 seconds <=====
>
>
>
> Variable: ui_yz
> Type: float
> Total Size: 11925792 bytes
> 2981448 values
> Number of Dimensions: 4
> Dimensions and sizes: [time | 72] x [zu | 129] x [y | 321] x [x_yz | 1]
> Coordinates:
> time: [48005.23199999911..48431.59199999907]
> zu: [ -1.. 255]
> y: [ 0.. 640]
> x_yz: [ 48.. 48]
> Number of Attributes: 2
> long_name : ui_yz
> units : m/s
>
> (0)
> =====> Wall Clock Elapsed Time: FileVarSummary(ui_yz): 0 seconds <=====
>
> (0)
> =====> Wall Clock Elapsed Time: read u: 621 seconds <=====
>
>
>
> Variable: u
> Type: float
> Total Size: 576000 bytes
> 144000 values
> Number of Dimensions: 3
> Dimensions and sizes: [16000] x [3] x [3]
> Coordinates:
> (0)
> =====> Wall Clock Elapsed Time: read v: 627 seconds <=====
>
> (0)
> =====> Wall Clock Elapsed Time: read w: 629 seconds <=====
>
>
> [...]
>
> _______________________________________________
> ncl-talk mailing list
> ncl-talk_at_ucar.edu
> http://mailman.ucar.edu/mailman/listinfo/ncl-talk

-- 
Gerry Creager -- gerry.creager_at_tamu.edu
Texas Mesonet -- AATLT, Texas A&M University	
Cell: 979.229.5301 Office: 979.458.4020 FAX: 979.862.3983
Office: 1700 Research Parkway Ste 160, TAMU, College Station, TX 77843
Received on Thu Sep 04 2008 - 07:42:04 MDT

This archive was generated by hypermail 2.2.0 : Mon Sep 08 2008 - 14:49:02 MDT