Degraded PP load times in later Iris versions

[wjbenfold]

📰 Custom Issue

Iris has got slower at loading pp files into cubes (though not noticeably in realising them). There was a massive slowdown in realisation in the default-current environment, but that seems to have resolved in default-next.

x-axis is number of time steps in the pp file
y-axis is time in seconds

[wjbenfold]

pstats from profile

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000  512.351  512.351 profile:0(main())
      3/1    0.000    0.000  512.350  512.350 :0(exec)
        1    0.004    0.004  512.350  512.350 <string>:1(<module>)
        1    0.000    0.000  512.347  512.347 profiler.py:9(main)
    42645    0.240    0.000  375.892    0.009 .../lib/python3.6/site-packages/iris/_data_manager.py:192(data)
    34119    0.095    0.000  375.784    0.011 .../lib/python3.6/site-packages/iris/_lazy_data.py:233(as_concrete_data)
        1    0.000    0.000  375.537  375.537 .../lib/python3.6/site-packages/iris/cube.py:2067(data)
        1    0.007    0.007  375.514  375.514 .../lib/python3.6/site-packages/iris/_lazy_data.py:199(_co_realise_lazy_arrays)
        1    0.001    0.001  375.507  375.507 .../lib/python3.6/site-packages/dask/base.py:506(compute)
        1    0.004    0.004  365.301  365.301 .../lib/python3.6/site-packages/dask/base.py:321(collections_to_dsk)
        1    0.020    0.020  365.149  365.149 .../lib/python3.6/site-packages/dask/array/optimization.py:24(optimize)
        1    0.171    0.171  362.583  362.583 .../lib/python3.6/site-packages/dask/highlevelgraph.py:801(cull)
    12795   48.627    0.004  287.514    0.022 .../lib/python3.6/_collections_abc.py:712(_from_iterable)
     4265    0.029    0.000  192.411    0.045 .../lib/python3.6/_collections_abc.py:474(__and__)
    12793   52.623    0.004  192.303    0.015 .../lib/python3.6/_collections_abc.py:477(<genexpr>)
 36376184   90.005    0.000  139.714    0.000 .../lib/python3.6/_collections_abc.py:716(__contains__)
        1    0.064    0.064  136.809  136.809 .../lib/python3.6/site-packages/iris/__init__.py:279(load)
        1    1.554    1.554   96.829   96.829 .../lib/python3.6/site-packages/dask/highlevelgraph.py:687(get_all_external_keys)
     4265    0.040    0.000   95.219    0.022 .../lib/python3.6/_collections_abc.py:488(__or__)
        1    0.000    0.000   91.725   91.725 .../lib/python3.6/site-packages/iris/cube.py:144(merged)

[wjbenfold]

pstats from profile for default-next for comparison

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000  143.879  143.879 profile:0(main())
   1066/1    0.039    0.000  143.878  143.878 :0(exec)
    288/1    0.005    0.000  143.878  143.878 <string>:1(<module>)
        1    0.000    0.000  143.874  143.874 profiler.py:9(main)
        1    0.044    0.044  131.555  131.555 .../lib/python3.7/site-packages/iris/__init__.py:278(load)
        1    0.000    0.000   84.038   84.038 .../lib/python3.7/site-packages/iris/cube.py:142(merged)
        1    0.000    0.000   84.038   84.038 .../lib/python3.7/site-packages/iris/cube.py:155(<listcomp>)
        1    0.003    0.003   84.038   84.038 .../lib/python3.7/site-packages/iris/cube.py:84(merged)
        1    0.063    0.063   84.036   84.036 .../lib/python3.7/site-packages/iris/cube.py:408(merge)
     4263    0.101    0.000   81.865    0.019 .../lib/python3.7/site-packages/iris/_merge.py:1330(register)
     4264    0.948    0.000   71.788    0.017 .../lib/python3.7/site-packages/iris/_merge.py:1758(_extract_coord_payload)
    34112    0.325    0.000   64.963    0.002 .../lib/python3.7/site-packages/iris/cube.py:1411(coord_dims)
    34112    0.426    0.000   64.546    0.002 .../lib/python3.7/site-packages/iris/cube.py:1785(coord)
    34112    0.817    0.000   64.002    0.002 .../lib/python3.7/site-packages/iris/cube.py:1585(coords)
    34112    0.800    0.000   57.509    0.002 .../lib/python3.7/site-packages/iris/cube.py:1742(<listcomp>)
   230250    1.131    0.000   56.270    0.000 .../lib/python3.7/site-packages/iris/common/metadata.py:1253(__eq__)
   230250    0.892    0.000   54.801    0.000 .../lib/python3.7/site-packages/iris/common/metadata.py:910(__eq__)
   230250    3.408    0.000   53.909    0.000 .../lib/python3.7/site-packages/iris/common/metadata.py:159(__eq__)
        1    0.000    0.000   47.473   47.473 .../lib/python3.7/site-packages/iris/__init__.py:265(_load_collection)
        1    0.021    0.021   41.664   41.664 .../lib/python3.7/site-packages/iris/cube.py:105(from_cubes)

[github-actions]

In order to maintain a backlog of relevant issues, we automatically label them as stale after 500 days of inactivity.

If this issue is still important to you, then please comment on this issue and the stale label will be removed.

Otherwise this issue will be automatically closed in 28 days time.

[github-actions]

This stale issue has been automatically closed due to a lack of community activity.

If you still care about this issue, then please either:

• Re-open this issue, if you have sufficient permissions, or
• Add a comment pinging @SciTools/iris-devs who will re-open on your behalf.