Use gallery as basis for performance testing (2 man days' effort)

[DPeterK]

Compare runtime for running the gallery examples in the master branch and the dask.

Record methods and results and provide a recommendation on further work, if any.

As an extension also compare memory usage.

[corinnebosley]

This is the code I have used; a description of my actions is at the top:

# I have made a copy of all the example files, put them in this directory and
# removed the plt.show() line from them all.  This script then works out where
# it lives, makes a list of all the example files and runs them all in turn,
# collating the time taken to run each one as it goes.

import time
import os
import imp


EXAMPLE_DIRECTORY = os.path.join(os.path.dirname(os.path.dirname(__file__)),
                                 'iris_timings/example_code')
EXAMPLE_DIRECTORIES = [os.path.join(EXAMPLE_DIRECTORY, the_dir)
                       for the_dir in os.listdir(EXAMPLE_DIRECTORY)
                       if the_dir.endswith('.py')]

examples = []
times = []
for i in EXAMPLE_DIRECTORIES:
    example = i[62:-3]
    mod = imp.load_source(example, i[:57]+'code/'+i[62:])
    print 'Loaded ', example, '; Running main'
    start = time.clock()
    mod.main()
    elapsed = time.clock() - start
    examples.append(example)
    times.append(elapsed)

print('printing lists of examples and times taken to run them (in seconds, presumably):')
print zip(examples, times)

[corinnebosley]

Here are some results without dask:

('anomaly_log_colouring', 0.43000000000000016)
('custom_aggregation', 0.3700000000000001)
('custom_file_loading', 4.880000000000001)
('SOI_filtering', 3.4499999999999993)
('atlantic_profiles', 1.1799999999999997)
('COP_1d_plot', 0.4800000000000004)
('COP_maps', 4.299999999999999)
('coriolis_plot', 0.1700000000000017)
('cross_section', 0.5799999999999983)
('deriving_phenomena', 5.5)
('lineplot_with_legend', 0.05000000000000071)
('global_map', 1.990000000000002)
('inset_plot', 1.0800000000000018)
('projections_and_annotations', 0.41000000000000014)
('orca_projection', 1.1999999999999993)
('polar_stereo', 1.0199999999999996)
('polynomial_fit', 0.11000000000000298)
('rotated_pole_mapping', 1.4799999999999969)
('hovmoller', 1.4400000000000048)
('TEC', 1.4599999999999937)
('lagged_ensemble', 52.160000000000004)
('wind_speed', 0.5599999999999881)

[corinnebosley]

Here are some results with dask:

('anomaly_log_colouring', 0.7699999999999996)
('custom_aggregation', 0.35000000000000053)
('custom_file_loading', 4.79)
('SOI_filtering', 3.49)
('atlantic_profiles', 1.3100000000000005)
('COP_1d_plot', 0.46999999999999886)
('COP_maps', 4.34)
('coriolis_plot', 0.16999999999999815)
('cross_section', 0.5)
('deriving_phenomena', 5.57)
('lineplot_with_legend', 0.060000000000002274)
('global_map', 2.0199999999999996)
('inset_plot', 1.1199999999999974)
('projections_and_annotations', 0.41000000000000014)
('orca_projection', 1.3200000000000003)
('polar_stereo', 1.0199999999999996)
('polynomial_fit', 0.14000000000000057)
('rotated_pole_mapping', 1.490000000000002)
('hovmoller', 1.3999999999999986)
('TEC', 1.6400000000000006)
('lagged_ensemble', 52.43)
('wind_speed', 0.9899999999999949)

[corinnebosley]

After a first glance, it looks like the timings for the gallery examples are consistently just a tiny bit slower on the dask branch. I have not yet run diagnostics, so this is purely a qualitative observation, but from the results above I can't see any glaring issues with performance.

Diagnostics to follow.

[corinnebosley]

Difference in seconds (i.e. examples in dask branch - examples in master branch):

[['anomaly_log_colouring' '0.34']
['custom_aggregation' '-0.02']
['custom_file_loading' '-0.09']
['SOI_filtering' '0.04']
['atlantic_profiles' '0.13']
['COP_1d_plot' '-0.01']
['COP_maps' '0.04']
['coriolis_plot' '-3.5527136788e-15']
['cross_section' '-0.08']
['deriving_phenomena' '0.07']
['lineplot_with_legend' '0.01']
['global_map' '0.03']
['inset_plot' '0.04']
['projections_and_annotations' '0.0']
['orca_projection' '0.12']
['polar_stereo' '0.0']
['polynomial_fit' '0.03']
['rotated_pole_mapping' '0.01']
['hovmoller' '-0.04']
['TEC' '0.18']
['lagged_ensemble' '0.27']
['wind_speed' '0.43']]

[corinnebosley]

Difference factor (i.e. how much longer the examples take with dask than without):

[['anomaly_log_colouring' '1.79069767442']
['custom_aggregation' '0.945945945946']
['custom_file_loading' '0.981557377049']
['SOI_filtering' '1.0115942029']
['atlantic_profiles' '1.11016949153']
['COP_1d_plot' '0.979166666667']
['COP_maps' '1.00930232558']
['coriolis_plot' '1.0']
['cross_section' '0.862068965517']
['deriving_phenomena' '1.01272727273']
['lineplot_with_legend' '1.2']
['global_map' '1.01507537688']
['inset_plot' '1.03703703704']
['projections_and_annotations' '1.0']
['orca_projection' '1.1']
['polar_stereo' '1.0']
['polynomial_fit' '1.27272727273']
['rotated_pole_mapping' '1.00675675676']
['hovmoller' '0.972222222222']
['TEC' '1.12328767123']
['lagged_ensemble' '1.00517638037']
['wind_speed' '1.76785714286']]

Looking at the differences this way, it is a bit more evident that some examples (particularly the first and last) take almost twice as long with dask than without.

Next I would like to look at whether there is anything that these examples have in common, and whether this is causing a specific problem.

[corinnebosley]

I think maybe the slowness is due to a cube.coord('whatever').points call... Which examples have this command?

[['anomaly_log_colouring' '1.79069767442'] Yes
['custom_aggregation' '0.945945945946'] No
['custom_file_loading' '0.981557377049'] Yes
['SOI_filtering' '1.0115942029'] No
['atlantic_profiles' '1.11016949153'] Yes
['COP_1d_plot' '0.979166666667'] No
['COP_maps' '1.00930232558'] Yes
['coriolis_plot' '1.0'] No
['cross_section' '0.862068965517'] No
['deriving_phenomena' '1.01272727273'] No
['lineplot_with_legend' '1.2'] Yes
['global_map' '1.01507537688'] No
['inset_plot' '1.03703703704'] Yes
['projections_and_annotations' '1.0'] Yes
['orca_projection' '1.1'] No
['polar_stereo' '1.0'] No
['polynomial_fit' '1.27272727273'] Yes
['rotated_pole_mapping' '1.00675675676'] No
['hovmoller' '0.972222222222'] No
['TEC' '1.12328767123'] No
['lagged_ensemble' '1.00517638037'] Yes
['wind_speed' '1.76785714286']] Yes

[corinnebosley]

[['anomaly_log_colouring' '1.79069767442'] Yes - whole array
['custom_file_loading' '0.981557377049'] Yes - one point only
['atlantic_profiles' '1.11016949153'] Yes - whole array
['COP_maps' '1.00930232558'] Yes - one point only
['lineplot_with_legend' '1.2'] Yes - one point only
['inset_plot' '1.03703703704'] Yes - max of array
['projections_and_annotations' '1.0'] Yes - min and max of array
['polynomial_fit' '1.27272727273'] Yes - whole array
['lagged_ensemble' '1.00517638037'] Yes - one point only
['wind_speed' '1.76785714286']] Yes - whole array, more than once

Clearly iris will now take a little extra processing time when a points array is realized, but this is minimal if you only call one point (e.g. to get a label or date format or max/min, etc.).

What is a little more interesting (although predictable, I suppose) is the example 'TEC', which is more than 10% slower using dask than not using dask, but does not call a coordinate points array anywhere. It does, however, contain this line:

cube.data = ma.masked_less(cube.data, 0)

[corinnebosley]

CONCLUSIONS:

• The main sticking point for performance is calling cube.coord.points
• This has a knock-on effect for certain other functions (such as rolling_window) which call a points array
• If you only need one point from the points array, the lag is greatly reduced
• Any command which realises the data (assigning or plotting, etc.) is slower using dask, but by less than 10%.

THEREFORE:

• Our biggest problem is cube.coord('something').points.
• Everything else (so far) seems either faster or less than 10% slower when using dask.
• Users will have to be more aware of whether their data is lazy or not and when they might realise it.

[corinnebosley]

Update:

In looking into the suggestion that calling a points array was very slow, I realized that this assumption may be misleading, as I found no reference to that task in the kompare block diagram. This suggests that actually this task may be very fast, and it is actually something else that is the problem.

I have therefore decided to update my timing script to give me more accurate results and output them to a text file.

Here is where to find the new script I am using:
/home/h06/cbosley/toybox/dask_stuff/iris_timings/gallery_timings_3a.py

Output is in text files in this folder:
/home/h06/cbosley/toybox/dask_stuff/iris_timings/results

[corinnebosley]

Here are some new results from a recent and repeated run on the dask branch compared with the pre-dask branch:

anomaly_log_colouring 1.04512448133
custom_aggregation 1.00460829493
custom_file_loading 0.998407389712
SOI_filtering 1.00693902575
atlantic_profiles 0.995316681534
COP_1d_plot 1.00679420704
COP_maps 0.999090454318
coriolis_plot 1.00525131283
cross_section 0.890522409363
deriving_phenomena 1.00392136359
lineplot_with_legend 0.995857988166
global_map 1.00563041386
inset_plot 1.00102888801
projections_and_annotations 1.04287775716
orca_projection 1.01405438436
polar_stereo 1.00341845968
polynomial_fit 1.02389937107
rotated_pole_mapping 1.00026488312
hovmoller 1.01434693497
TEC 1.0279770691
wind_speed 1.04396223757

These are time increase factors, so numbers > 1 indicate run-times slower than those using pre-dask iris.

The fact that nearly all these numbers are > 1 is not great, and generally says that iris will be a bit slower with dask than with Biggus. But conversely, the fact that all the numbers are < 1.05 indicates that daskified iris is < 5% slower than pre-daskified iris.

So we can say 'We have worked very hard for a long time with the outcome of making Iris slower by a little bit.'

Result!