Bugfix: ManagedOptimisation creates op at every iteration for ScipyOptimizer

[rhaps0dy]

The gpflow.train.ScipyOptimizer doesn't come with an operation that increments the global_step by default. The solution in here is to create the operation ourselves and then run it in the callback that is passed to it.

Unfortunately the current code both creates and runs the operation inside the callback.

Minimum failing example:

import matplotlib
matplotlib.use('Agg')  # gpflow_monitor imports matplotlib
import gpflow_monitor as gpfm
import gpflow
import tensorflow as tf
import numpy as np
import itertools

N = 200
M = 40
X = np.linspace(-2, 2, N)[:, None]
Y = 1/(np.exp(-5*X) + 1) - .5  # centered sigmoid

m = gpflow.models.SVGP(X, Y, gpflow.kernels.RBF(1),
                       gpflow.likelihoods.Gaussian(),
                       Z=np.random.rand(M, 1)*4-2)
with m.enquire_session().graph.as_default():
    global_step = tf.Variable(0, trainable=False, name="global_step")
    m.enquire_session().run(global_step.initializer)
    optimizer = gpflow.train.ScipyOptimizer()
    opt_method = gpfm.ManagedOptimisation(m, optimizer, global_step)
    opt_method.tasks += [
        gpfm.PrintTimings((x * 100 for x in itertools.count()),
                          gpfm.Trigger.ITER),
        # make a newline after every timings print
        gpfm.FunctionCallback((x * 100 for x in itertools.count()),
                              gpfm.Trigger.ITER, lambda _: print())
    ]
    opt_method.minimize(maxiter=100000)

Output without a fix: the optimisation is slow and gets slower at every iteration.
(lines manually aligned)

1, 1:         1.65 optimisation iter/s     1.65 total iter/s    0.00 last iter/s
100, 100:    37.01 optimisation iter/s    36.99 total iter/s   47.18 last iter/s
200, 200:    38.76 optimisation iter/s    38.73 total iter/s   40.66 last iter/s
300, 300:    37.67 optimisation iter/s    37.64 total iter/s   35.65 last iter/s
400, 400:    35.84 optimisation iter/s    35.82 total iter/s   31.26 last iter/s
500, 500:    33.99 optimisation iter/s    33.97 total iter/s   28.15 last iter/s
600, 600:    32.19 optimisation iter/s    32.17 total iter/s   25.46 last iter/s
700, 700:    30.38 optimisation iter/s    30.36 total iter/s   22.70 last iter/s
800, 800:    28.79 optimisation iter/s    28.78 total iter/s   21.09 last iter/s
900, 900:    27.39 optimisation iter/s    27.38 total iter/s   19.71 last iter/s
1000, 1000:  26.04 optimisation iter/s    26.03 total iter/s   18.02 last iter/s
1032, 1033:  25.34 optimisation iter/s    25.33 total iter/s   13.79 last iter/s

(etc.)

Output with a fix: the optimiser is fast.

1, 1:          1.67 optimisation iter/s     1.67 total iter/s    0.00 last iter/s
100, 100:     97.26 optimisation iter/s    97.08 total iter/s  229.23 last iter/s
200, 200:    137.63 optimisation iter/s   137.30 total iter/s  234.58 last iter/s
300, 300:    161.22 optimisation iter/s   160.77 total iter/s  244.46 last iter/s
400, 400:    175.22 optimisation iter/s   174.69 total iter/s  236.10 last iter/s
500, 500:    184.34 optimisation iter/s   183.75 total iter/s  232.02 last iter/s
600, 600:    191.69 optimisation iter/s   191.04 total iter/s  238.58 last iter/s
700, 700:    197.55 optimisation iter/s   196.86 total iter/s  241.05 last iter/s
800, 800:    201.65 optimisation iter/s   200.93 total iter/s  235.12 last iter/s
900, 900:    205.83 optimisation iter/s   205.08 total iter/s  245.87 last iter/s
1000, 1000:  208.54 optimisation iter/s   207.78 total iter/s  235.77 last iter/s
1100, 1100:  210.79 optimisation iter/s   210.00 total iter/s  235.37 last iter/s
1200, 1200:  213.10 optimisation iter/s   212.30 total iter/s  241.50 last iter/s
1254, 1254:  209.75 optimisation iter/s   208.97 total iter/s  155.08 last iter/s

A possible good practice for the future would be to call tf.graph.finalize() before running the optimization. Unfortunately, some new operations are created at the beginning of optimisation in the normal course of GPflow usage. For example, gpflow.core.Node.initialize calls misc.initialize_variables which creates variable initializer operations, causing an error in a finalised graph.

[markvdw]

Ah damn, so essentially the issue is that so many operations get created in the graph, that it slows the entire thing down? Thanks for spotting this. I'll merge, and make sure this gets into the version we're working on inside GPflow as well.

[rhaps0dy]

You're welcome! Though in an anticlimactic twist, once I fixed this I saw that for the model I'm working on Adam is faster (than LBFGS) in both iterations/sec (it doesn't have to go back to python and then to Fortran) and number of iterations to convergence.