Add timers to YATM

[nichannah]

I’m going to put three new timers into YATM: 1) field read from disk 2) wait for ice 3) remap runoff

OK, I think we need a 4th timer: time to build k-d tree. That is happening once for every run

These are needed to help understand the variance in model timestep timing. e.g. @marshallward reported that in the 0.1 deg config:

{ timer-ice_step time(  0.000):   1.442 }
 { timer-ice_step time(  0.000):   1.443 }
 { timer-ice_step time(  0.000):   1.509 }
 { timer-ice_step time(  0.000):   1.441 }
 { timer-ice_step time(  0.000):  48.172 }
 { timer-ice_step time(  0.000):   0.023 }
 { timer-ice_step time(  0.000):  18.663 }
 { timer-ice_step time(  0.000):   1.440 }
 { timer-ice_step time(  0.000):   1.458 }
 { timer-ice_step time(  0.000):   1.440 }
 { timer-ice_step time(  0.000):   1.453 }

[marshallward]

Another sample output from the 1 degree:

 { timer-coupling_step time(  28   ):   0.182 }                                 
 { timer-coupling_step time(  29   ):   0.182 }                                 
 { timer-coupling_step time(  30   ):   0.182 }                                 
 { timer-coupling_step time(  31   ):  36.765 }                                 
 { timer-coupling_step time(  32   ):   0.191 }                                 
 { timer-coupling_step time(  33   ):   0.179 }                                 
 { timer-coupling_step time(  34   ):   0.178 }                                 

AFAIK this anomalous slowdown happens at timestep 32 (note removal of step 1 by the timer) but does not happen again over the next ~900 steps.

[marshallward]

In the 0.1 degee results @nichannah cites above, this is observed every 216 steps (=1 day) so it's a repeating issue. The 1-degree results above are (as best I can tell) a one-time event.

[nichannah]

Here is some output from a 1 month 1deg run:

{ timer-field_read min:   0.001 }
 { timer-field_read max:   0.035 }
 { timer-field_read mean:   0.002 }
 { timer-field_read variance:   0.000 }
 { timer-field_read count: 0002190 }
 { timer-ice_wait min:   0.100 }
 { timer-ice_wait max:   5.266 }
 { timer-ice_wait mean:   0.290 }
 { timer-ice_wait variance:   0.105 }
 { timer-ice_wait count: 0000240 }
 { timer-init_runoff min:   0.082 }
 { timer-init_runoff max:   0.082 }
 { timer-init_runoff mean:   0.082 }
 { timer-init_runoff variance:   0.000 }
 { timer-init_runoff count: 0000001 }
 { timer-remap_runoff min:   0.016 }
 { timer-remap_runoff max:   0.020 }
 { timer-remap_runoff mean:   0.017 }
 { timer-remap_runoff variance:   0.000 }
 { timer-remap_runoff count: 0000030 }

The notable things I can see are:

• big difference between min and max field read times.
• a small ice_wait time is probably bad because increased likelihood that ice was waiting on YATM
• runoff numbers look ok.

These numbers look OK to me, I'm curious to see what the 0.1 looks like.