Cache recent points for get_next_point speedup

[benfitzpatrick]

This addresses part of #1053.

I did have a more elegant partial solution, which this pull request is too small to contain.
This one is OK.

@arjclark, please review and test.
@hjoliver, please review 2.

[arjclark]

Initial testing looking like an improvement, moving to profiling stage (ref #1751)

[hjoliver]

I did have a more elegant partial solution,...

Can you explain what this is/was, for the record?

[benfitzpatrick]

It was:

benfitzpatrick@e7dcf9e

[arjclark]

Looks OK to me. No problems from the test-battery in my environment. Profiling re #1751 looks better (sadly hasn't made the problem go away completely but certainly moved it from this end of the code).

Over to you @hjoliver

[hjoliver]

I agree with @arjclark's assessment.

My test suite:

[scheduling]
    initial cycle point = 2010-01-01T00
    final cycle point = 2011-01-01T12
    [[dependencies]]
        [[[PT1H]]]
            graph = foo[-PT1H] => foo
[runtime]
    [[foo]]
        script = true

Warm start this at 2011-01-01T00, i.e. ~8760 cycle points from the start.

master:

$ grep next master.log
   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       65    0.255    0.004   50.786    0.781 /home/oliverh/cylc/cylc.clone.git/lib/cylc/cycling/iso8601.py:419(get_next_point)
   245491    0.410    0.000   37.580    0.000 /home/oliverh/cylc/cylc.clone.git/lib/isodatetime/data.py:235(get_next)
       26    0.000    0.000    0.000    0.000 /home/oliverh/cylc/cylc.clone.git/lib/cylc/task_proxy.py:1549(next_point)
       51    0.000    0.000    0.000    0.000 /usr/lib64/python2.7/sre_parse.py:183(__next)
       13    0.000    0.000    0.000    0.000 /home/oliverh/cylc/cylc.clone.git/lib/cylc/task_proxy.py:124(next)

This branch:

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
$ grep next ben.log 
   131520    0.223    0.000   20.147    0.000 /home/oliverh/cylc/cylc.clone.git/lib/isodatetime/data.py:235(get_next)
       65    0.033    0.001    6.757    0.104 /home/oliverh/cylc/cylc.clone.git/lib/cylc/cycling/iso8601.py:421(get_next_point)
       26    0.000    0.000    0.021    0.001 /home/oliverh/cylc/cylc.clone.git/lib/cylc/cycling/iso8601.py:467(get_next_point_on_sequence)
       15    0.000    0.000    0.001    0.000 /home/oliverh/cylc/cylc.clone.git/lib/cylc/cycling/iso8601.py:446(_check_and_cache_next_point)
       26    0.000    0.000    0.000    0.000 /home/oliverh/cylc/cylc.clone.git/lib/cylc/task_proxy.py:1549(next_point)
       51    0.000    0.000    0.000    0.000 /usr/lib64/python2.7/sre_parse.py:183(__next)
       13    0.000    0.000    0.000    0.000 /home/oliverh/cylc/cylc.clone.git/lib/cylc/task_proxy.py:124(next)

v.s. cold-start at the same point (on master):

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
$ grep next master-cold.log 
       65    0.001    0.000    0.102    0.002 /home/oliverh/cylc/cylc.clone.git/lib/cylc/cycling/iso8601.py:419(get_next_point)
      211    0.001    0.000    0.057    0.000 /home/oliverh/cylc/cylc.clone.git/lib/isodatetime/data.py:235(get_next)
       26    0.000    0.000    0.000    0.000 /home/oliverh/cylc/cylc.clone.git/lib/cylc/task_proxy.py:1549(next_point)
       51    0.000    0.000    0.000    0.000 /usr/lib64/python2.7/sre_parse.py:183(__next)
       13    0.000    0.000    0.000    0.000 /home/oliverh/cylc/cylc.clone.git/lib/cylc/task_proxy.py:124(next)

And, I still get a significant amount of >100% cpu load in the warm start case on this branch.

The cold-start case shows almost no load, which implies other places we're repeatedly iterating from T0. is_valid, is_on_sequence? Can these be given the same treatment?

$ grep iso8601 ben.log 
       13    0.000    0.000   57.106    4.393 /home/oliverh/cylc/cylc.clone.git/lib/cylc/cycling/iso8601.py:375(is_valid)
       13    0.000    0.000   57.106    4.393 /home/oliverh/cylc/cylc.clone.git/lib/cylc/cycling/iso8601.py:371(is_on_sequence)
       65    0.033    0.001    6.757    0.104 /home/oliverh/cylc/cylc.clone.git/lib/cylc/cycling/iso8601.py:421(get_next_point)
  592/400    0.001    0.000    0.031    0.000 /home/oliverh/cylc/cylc.clone.git/lib/cylc/cycling/iso8601.py:80(_wrapper)
      327    0.001    0.000    0.023    0.000 /home/oliverh/cylc/cylc.clone.git/lib/cylc/cycling/iso8601.py:110(__cmp__)
       70    0.000    0.000    0.022    0.000 /home/oliverh/cylc/cylc.clone.git/lib/cylc/cycling/iso8601.py:150(_iso_point_cmp)
       26    0.000    0.000    0.021    0.001 /home/oliverh/cylc/cylc.clone.git/lib/cylc/cycling/iso8601.py:467(get_next_point_on_sequence)
      207    0.001    0.000    0.012    0.000 /home/oliverh/cylc/cylc.clone.git/lib/cylc/cycling/iso8601.py:737(point_parse)
...

[benfitzpatrick]

Just added more speedup for is_valid/is_on_sequence. This is now reduced to a small fraction of the percentage use in Hilary's example above with a longer final cycle time (you do still get the one time penalty).

[hjoliver]

All good now; tests passing.