Tracking down performance bottlenecks in PYDAP-powered ZPTs

Like this example. I've eliminated several possible sources of the slowness (see below). What remains is PYDAP itself, our NetCDF file reader, or maybe our NetCDF file structure?

Issue: this page takes 5~7 seconds to load initially and then ~4 seconds thereafter

I added code to the python script called by the ZPT to print out some load times (via time.time() differencing). The last line of the ZPT as it now renders is this output. Elements are:

DAP open	AP loop	AT loop	DT loop	RH loop	RD loop	Loop total	Script total
1.13s (dap open)	0.54s (loop)	0.53s (loop)	0.53s (loop)	0.54s (loop)	0.52s (loop)	2.66s (loop total)	3.79s (total)
1.20s (dap open)	0.55s (loop)	0.55s (loop)	0.55s (loop)	0.54s (loop)	0.55s (loop)	2.75s (loop total)	3.95s (total)

Is script efficiency the issue?

• Accessing a single data value directly via a browser is 500-550 ms for JPIER data, same as each loop within the script.

Is JPIER dataset the issue?

• Accessing Stones for comparison directly via a browser is 500-550 ms, same as each loop within the script.

Could file over NFS be the issue?

• I added a symlink to /seacoos/data/ to point to a local directory on whewell with the baseline jpier file (jpier_met_2008_09.nc).
• Access times via the script and direct OpenDAP calls to locally stored file is similar to NFS served files.
• Maybe NFS still slow things down via the symlink? Seems unlikely.

Apache and Zope access logs

These are from an initial hit of the ZPT. The ZPT does its DAP-thing first (~4 secs) and then Plone serves the rest of the page (1-2 secs more). This confirms the script load timing.

Apache log
127.0.0.1 - - [15/Sep/2008:13:55:42 -0400] "GET /dods/nccoos/level1/jpier/met/jpier_met_2008_09.nc.dds HTTP/1.1" 200 2177 "-" "pydap/2.2.6.5"
127.0.0.1 - - [15/Sep/2008:13:55:43 -0400] "GET /dods/nccoos/level1/jpier/met/jpier_met_2008_09.nc.das HTTP/1.1" 200 4534 "-" "pydap/2.2.6.5"
127.0.0.1 - - [15/Sep/2008:13:55:44 -0400] "GET /dods/nccoos/level1/jpier/met/jpier_met_2008_09.nc.dods?air_pressure.air_pressure[2051:1:2051] HTTP/1.1" 200 138 "-" "pydap/2.2.6.5"
127.0.0.1 - - [15/Sep/2008:13:55:44 -0400] "GET /dods/nccoos/level1/jpier/met/jpier_met_2008_09.nc.dods?air_temp.air_temp[2051:1:2051] HTTP/1.1" 200 126 "-" "pydap/2.2.6.5"
127.0.0.1 - - [15/Sep/2008:13:55:45 -0400] "GET /dods/nccoos/level1/jpier/met/jpier_met_2008_09.nc.dods?dew_temp.dew_temp[2051:1:2051] HTTP/1.1" 200 126 "-" "pydap/2.2.6.5"
127.0.0.1 - - [15/Sep/2008:13:55:45 -0400] "GET /dods/nccoos/level1/jpier/met/jpier_met_2008_09.nc.dods?humidity.humidity[2051:1:2051] HTTP/1.1" 200 126 "-" "pydap/2.2.6.5"
127.0.0.1 - - [15/Sep/2008:13:55:46 -0400] "GET /dods/nccoos/level1/jpier/met/jpier_met_2008_09.nc.dods?rainfall_day.rainfall_day[2051:1:2051] HTTP/1.1" 200 138 "-" "pydap/2.2.6.5"

Zope log
152.2.175.228 - Anonymous [15/Sep/2008:13:55:46 -0400] "GET /Plone/platformPage HTTP/1.1" 200 16377 "" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.1) Gecko/2008070208 Firefox/3.0.1"
152.2.175.228 - Anonymous [15/Sep/2008:13:55:47 -0400] "GET /Plone/portal_javascripts/Plone Default/jquery-cachekey7049.js HTTP/1.1" 200 52068 "http://whewell.marine.unc.edu:9080/Plone/platformPage" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.1) Gecko/2008070208 Firefox/3.0.1"
152.2.175.228 - Anonymous [15/Sep/2008:13:55:47 -0400] "GET /Plone/portal_javascripts/Plone Default/jquery-cachekey7049.js HTTP/1.1" 200 52068 "" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.1) Gecko/2008070208 Firefox/3.0.1"
152.2.175.228 - Anonymous [15/Sep/2008:13:55:47 -0400] "GET /Plone/portal_javascripts/Plone Default/resourcebase2-dom-fp-cachekey9429.js HTTP/1.1" 200 39654 "http://whewell.marine.unc.edu:9080/Plone/platformPage" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.1) Gecko/2008070208 Firefox/3.0.1"
152.2.175.228 - Anonymous [15/Sep/2008:13:55:47 -0400] "GET /Plone/portal_javascripts/Plone Default/resourcebase2-dom-fp-cachekey9429.js HTTP/1.1" 200 39654 "" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.1) Gecko/2008070208 Firefox/3.0.1"
152.2.175.228 - Anonymous [15/Sep/2008:13:55:47 -0400] "GET /Plone/portal_css/Plone Default/base-cachekey9631.css HTTP/1.1" 200 45997 "http://whewell.marine.unc.edu:9080/Plone/platformPage" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.1) Gecko/2008070208 Firefox/3.0.1"
152.2.175.228 - Anonymous [15/Sep/2008:13:55:47 -0400] "GET /Plone/info_icon.gif HTTP/1.1" 200 1227 "http://whewell.marine.unc.edu:9080/Plone/platformPage" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.1) Gecko/2008070208 Firefox/3.0.1"
152.2.175.228 - Anonymous [15/Sep/2008:13:55:47 -0400] "GET /Plone/spinner.gif HTTP/1.1" 200 2337 "http://whewell.marine.unc.edu:9080/Plone/platformPage" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.1) Gecko/2008070208 Firefox/3.0.1"
152.2.175.228 - Anonymous [15/Sep/2008:13:55:47 -0400] "GET /Plone/favicon.ico HTTP/1.1" 200 2529 "" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.1) Gecko/2008070208 Firefox/3.0.1"
152.2.175.228 - Anonymous [15/Sep/2008:13:55:47 -0400] "GET /Plone/logo.jpg HTTP/1.1" 200 5457 "http://whewell.marine.unc.edu:9080/Plone/platformPage" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.1) Gecko/2008070208 Firefox/3.0.1"
152.2.175.228 - Anonymous [15/Sep/2008:13:55:47 -0400] "GET /Plone/input_background.gif HTTP/1.1" 200 759 "http://whewell.marine.unc.edu:9080/Plone/portal_css/Plone%20Default/base-cachekey9631.css" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.1) Gecko/2008070208 Firefox/3.0.1"
152.2.175.228 - Anonymous [15/Sep/2008:13:55:47 -0400] "GET /Plone/search_icon.gif HTTP/1.1" 200 732 "http://whewell.marine.unc.edu:9080/Plone/portal_css/Plone%20Default/base-cachekey9631.css" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.1) Gecko/2008070208 Firefox/3.0.1"
152.2.175.228 - Anonymous [15/Sep/2008:13:55:47 -0400] "GET /Plone/user.gif HTTP/1.1" 200 1223 "http://whewell.marine.unc.edu:9080/Plone/platformPage" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.1) Gecko/2008070208 Firefox/3.0.1"
152.2.175.228 - Anonymous [15/Sep/2008:13:55:47 -0400] "GET /Plone/linkTransparent.gif HTTP/1.1" 200 402 "http://whewell.marine.unc.edu:9080/Plone/portal_css/Plone%20Default/base-cachekey9631.css" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.1) Gecko/2008070208 Firefox/3.0.1"