For this test, I used the LAP seq_id 11 data, and extracted the chipProcessedImfile dtime parameters, as well as the hostname that the processing occurred on and the n_stars parameters. I also extracted the ra and dec values from the exposure boresite. It is likely that the photometry time counts threaded time separately, so it is difficult to directly compare the photometry time to the ppImage and script times.

Detrend and Photometry

Plotting the detrend and photometry times across the sky shows the obvious influence of the galactic plane on the photometry time. However, it's also interesting that there is a clear bimodality in the detrend time, regardless of the position on the sky.

The first split to look at is the detrend time by OTA. This plot illustrates that OTA17 has a significantly smaller detrend time, likely due to the large area masked. Next, OTA27/47/57 all have larger detrend times, which reflects the expense of the PATTERN.ROW correction. These OTAs, all have 4 or 5 columns having this correction. OTA33/45/74 have two columns, and also have higher detrend times than their neighbors. The points on the left panel show the host listed as the target (green +) as well as the host that actually executed the most jobs for that OTA (blue x). For most targeting pairs, the target and actual max host correspond well. This does not always translate into the shortest execution time, however, with these points often falling around the average. The right panel shows the number of jobs executed on the targeted host for that OTA, along with the number of jobs executed on other hosts for that OTA.

Next, using the hostname parameter, we can investigate the detrend time as a function of which host ran ppImage. I've indexed the hosts such that ipp0XX have an id equal to 0 + XX; ippcYY is 100 + YY; stareZZ id 200 + ZZ. There are the standard scatters that map well with the OTA-specific causes. However, hosts ipp028/033/034 are significantly slower than the other ipp machines. This is likely the cause of the bimodality seen in the full-sky plots. ippc45 also is slower than the other machines of its class, although I do not recall any reason why this would be the case. The points are as above for the OTA separation.

Plotting the photometry time against the number of stars in the exposure shows an effectively linear relation above a certain density of objects. The x/300 line was added simply to give a scale of what the photometry time/star is.

Total and Script

As the time running ppImage is the dominant fraction of the time running the script, I've plotted the ppImage time, and the difference (script - ppImage). This shows the "overhead" time involved in running the script. This time is used to check the existence of output files, so large overhead times likely correspond to NFS slowdowns.


Chip Stage Timing

The majority of the processing time at chip stage is consumed by the photometry process (median dtime_photom = 0.64 * dtime_script). Most chips have a similar distribution of dtime_photom values, with medians less than 100 seconds. Ten of the chips show a different distribution, with median dtime_photom values larger than 100s and a large day-to-day variation in distribution shape. The plots below show selected chips, with the entire set of plots attached in pdf format.

The CDF plots show the distribution of dtime_photom values for each chip, separated by the date they were observed. Each curve is labeled with the median, non-parametric dispersion, minimum and maximum dtime_photom.

The second set of plots show for each date the fraction of total dtime_photom spent on jobs with dtime larger than the value on the x-axis. These curves are labeled with the median value (half of the time is spent on jobs with photometry times longer than this value), non-parametric sigma, and the sum of dtime_photom for this date/chip pair. This plot is somewhat skewed by a small number of points, but does show that even on good chips, the ~10% of jobs that run longer than 100s consume ~30% of the total photometry time.

The set of chips that can be considered "bad" (XY04, XY05, XY16, XY27, XY35, XY60, XY64, XY72, XY74, XY75) seem to share the same distribution of n_stars, fwhm, and sky background as the good chips. The photometry time does not correlate with any of these values, either.

Good chip Bad chip
CDF of dtime_photom values
Fraction of time spent running photometry

Dark Dependence

Re-processing a few chips using both the standard dark and the new dark shows a significant improvement in the speed of ppImage. The following table summarizes two chips:

exp_name chip dark used t_ppImage t_footprints N_peaks N_final_footprints
o5632g0062o OTA75 OLD 453.52030 341.473507 5867 1978
o5632g0062o OTA75 NEW 99.933317 2.430781 2293 1654
o5632g0516o OTA05 OLD 276.17127 170.655817 4253 2191
o5632g0516o OTA05 NEW 114.50915 12.590614 2583 2054

This shows that the difference in time between the new and old darks is almost entirely due to the footprint culling process. The final number of footprints is similar between the two runs, but the new dark cuts down the number of initial peaks, so there are fewer footprints to cull.