Finding and improving slow Galaxy code
This is a short howto on how one can find slow code in Galaxy (but this should apply to other projects as well).
I will walk through how I have improved the tool form building speed in https://github.com/galaxyproject/galaxy/pull/4541.
Identifying the problem
@bgruening mentioned that loading the tool form was slow on his server, and I checked ours and saw that for certain tools it took around 2-3 seconds to load the tool form, while for others this was significantly faster.
Identifying a rough entrypoint for profiling the code
If you know the part in the UI that is slow, you can identify the corresponding API endpoint (assuming the backend is slow) by looking at the network tab in Chrome’s JavaScript console while doing the operation that is slow. When I clicked on HISAT2 in the tool menu, I saw that there was a GET request to http://127.0.0.1:8080/api/tools/toolshed.g2.bx.psu.edu/repos/iuc/hisat2/hisat2/2.0.5.2/build?tool_version=2.0.5.2 that took 3 seconds to complete. Looking into Galaxy’s API documentation we can match this URL to the actual code in lib/galaxy/webapps/galaxy/api/tools.py.
Profiling
I like the profilehooks library, which provides a decorator for
profiling specific functions like our build function. To use it,
install profilehooks into Galaxy’s Python environment ( sourcing
Galaxy’s virtualenv and running pip install profilehooks should be
enough) and import the profile function at the top of the file that
contains the function you would like to profile
(from profilehooks import profile), and then add an additional
@profile decorator just above the build function. You can now
start Galaxy, hit the API endpoint a few times and shut down galaxy
again. You should see profilehooks output in your logs. This is the
output I saw
6585515 function calls (6497718 primitive calls) in 9.560 seconds
Ordered by: cumulative time, internal time, call count
List reduced from 997 to 40 due to restriction <40>
ncalls tottime percall cumtime percall filename:lineno(function)
4 0.000 0.000 9.572 2.393 decorators.py:227(decorator)
4 0.000 0.000 9.567 2.392 tools.py:89(build)
4 0.000 0.000 9.566 2.391 __init__.py:1786(to_json)
116/4 0.005 0.000 8.973 2.243 __init__.py:1877(populate_model)
27312 0.063 0.000 8.110 0.000 dataset_matcher.py:74(hda_match)
2184 0.005 0.000 6.426 0.003 dataset_matcher.py:163(hdca_match)
100/56 0.001 0.000 6.389 0.114 grouping.py:625(to_dict)
300/168 0.001 0.000 6.388 0.038 grouping.py:628(nested_to_dict)
3720/2184 0.014 0.000 6.387 0.003 dataset_matcher.py:170(dataset_collection_match)
768/324 0.002 0.000 6.386 0.020 {map}
200/112 0.001 0.000 6.384 0.057 grouping.py:643(to_dict)
468/308 0.001 0.000 6.381 0.021 grouping.py:646(input_to_dict)
5376/2760 0.018 0.000 5.949 0.002 dataset_matcher.py:146(__valid_element)
104 0.016 0.000 5.451 0.052 basic.py:1775(to_dict)
27312 0.076 0.000 4.980 0.000 dataset_matcher.py:34(hda_accessible)
328 0.011 0.000 4.965 0.015 query.py:2700(one)
3840 0.009 0.000 4.825 0.001 dataset_matcher.py:106(__can_access_dataset)
176 0.001 0.000 4.797 0.027 context.py:119(get_current_user_roles)
176 0.004 0.000 4.796 0.027 __init__.py:237(all_roles)
508 0.003 0.000 4.379 0.009 query.py:2756(__iter__)
10680 0.042 0.000 3.028 0.000 dataset_matcher.py:47(valid_hda_match)
32 0.002 0.000 2.975 0.093 basic.py:1943(to_dict)
208 0.015 .000 2.924 0.014 basic.py:1480(get_initial_value)
8144 0.021 0.000 2.645 0.000 __init__.py:2204(find_conversion_destination)
8144 0.010 0.000 2.584 0.000 data.py:611(find_conversion_destination)
8144 0.035 0.000 2.573 0.000 registry.py:818(find_conversion_destination_for_dataset_by_extensions)
508 0.009 0.000 2.534 0.005 query.py:3204(_compile_context)
8144 0.451 0.000 2.360 0.000 registry.py:798(get_converters_by_datatype)
508 0.003 0.000 2.083 0.004 query.py:3568(setup_context)
1580/508 0.054 0.000 2.080 0.004 loading.py:224(_setup_entity_query)
20660/9712 0.062 0.000 2.056 0.000 interfaces.py:498(setup)
1072/360 0.011 0.000 1.997 0.006 strategies.py:1114(setup_query)
816 0.004 0.000 1.928 0.002 basic.py:208(to_dict)
508 0.004 0.000 1.842 0.004 query.py:2770(_execute_and_instances)
508 0.002 0.000 1.786 0.004 base.py:846(execute)
508 0.001 0.000 1.783 0.004 elements.py:322(_execute_on_connection)
508 0.005 0.000 1.782 0.004 base.py:975(_execute_clauseelement)
128 0.002 0.000 1.781 0.014 basic.py:1878(match_multirun_collections)
13308 0.064 0.000 1.716 0.000 visitors.py:199(traverse)
13308 0.088 0.000 1.651 0.000 visitors.py:304(replacement_traverse)
I loaded the tool form 4 times, as you can see on the second line of the
output (ncalls=4). The table is sorted by the cumulative time that the
functions ran while build was being evaluated.
Optimizing the slow function calls
The most valuable targets for optimization therefore should be relatively high in the table. I have seen two functions that I would not think of as expensive and that should not be that high in the table:
get_current_user_roles, which took 4.8 seconds out of 9.5 seconds
total and is being called 176 times and get_converters_by_datatype
which took 2.4 seconds out the 9.5 seconds total.
get_current_user_roles is called in the context of
hda_accessible and hda_accessible (these are also in our table)
in
https://github.com/galaxyproject/galaxy/blob/release_17.05/lib/galaxy/tools/parameters/dataset_matcher.py#L109
We can see that the current_user_roles attribute of
DatasetMatcher instances are already being cached, however during
the course of filling in parameters in the tool building process a new
DatasetMatcher instance is being created for each
DataToolParameter in
https://github.com/galaxyproject/galaxy/blob/release_17.05/lib/galaxy/tools/parameters/basic.py#L1456.
This means that the cached roles will be lost for the next
DataToolParameter that we need to fill in. It would be great if we
didn’t need to redo this expensive operation for each data input.
When building the tool interface we deal with a WorkRequestContext
instance, which inherits from ProvidesUserContext in
https://github.com/galaxyproject/galaxy/blob/dev/lib/galaxy/managers/context.py#L119.
ProvidesUserContext defines a get_current_user_roles method that
gets the current users’ roles from the database. We can implement a
cached variant of this in WorkRequestContext, which will be used
when building the tool form. You can find this change in
https://github.com/galaxyproject/galaxy/pull/4541/commits/d1a2007275f128fea051ead55fb47d2c2686abf5
The slowness in get_converters_by_datatype can be circumvented by
caching the result of this function, which I have done in
https://github.com/galaxyproject/galaxy/pull/4541/commits/471707bd7dfa048a412aad9cdcc1d0b4aea70bc7
(and fixed a mistake in
https://github.com/galaxyproject/galaxy/pull/4541/commits/2d8b242e697a08775879fc873578b5f244d4d5cb)
Checking how the changes affect the speed
After these changes we can verify that the code is faster now and that the key functions we targeted are not as high anymore in the profiling table output:
1384317 function calls (1363256 primitive calls) in 2.215 seconds
Ordered by: cumulative time, internal time, call count
List reduced from 991 to 40 due to restriction <40>
ncalls tottime percall cumtime percall filename:lineno(function)
4 0.000 0.000 2.220 0.555 decorators.py:227(decorator)
4 0.000 0.000 2.215 0.554 tools.py:89(build)
4 0.000 0.000 2.214 0.554 __init__.py:1786(to_json)
116/4 0.004 0.000 1.861 0.465 __init__.py:1877(populate_model)
100/56 0.000 0.000 1.578 0.028 grouping.py:625(to_dict)
300/168 0.000 0.000 1.577 0.009 grouping.py:628(nested_to_dict)
768/324 0.001 0.000 1.576 0.005 {map}
200/112 0.001 0.000 1.574 0.014 grouping.py:643(to_dict)
468/308 0.001 0.000 1.572 0.005 grouping.py:646(input_to_dict)
2184 0.003 0.000 1.055 0.000 dataset_matcher.py:163(hdca_match)
153436 0.147 0.000 1.048 0.000 attributes.py:229(__get__)
3720/2184 0.010 0.000 1.019 0.000 dataset_matcher.py:170(dataset_collection_match)
32 0.002 0.000 0.956 0.030 basic.py:1943(to_dict)
1924/964 0.005 0.000 0.901 0.001 attributes.py:561(get)
960 0.006 0.000 0.875 0.001 strategies.py:492(_load_for_state)
27312 0.051 0.000 0.860 0.000 dataset_matcher.py:74(hda_match)
324 0.001 0.000 0.857 0.003 <string>:1(<lambda>)
324 0.009 0.000 0.855 0.003 strategies.py:565(_emit_lazyload)
104 0.012 0.000 0.807 0.008 basic.py:1775(to_dict)
336 0.002 0.000 0.803 0.002 query.py:2756(__iter__)
208 0.011 0.000 0.752 0.004 basic.py:1480(get_initial_value)
180 0.004 0.000 0.666 0.004 query.py:2607(all)
5376/2760 0.014 0.000 0.612 0.000 dataset_matcher.py:146(__valid_element)
336 0.002 0.000 0.606 0.002 query.py:2770(_execute_and_instances)
336 0.001 0.000 0.570 0.002 base.py:846(execute)
336 0.001 0.000 0.569 0.002 elements.py:322(_execute_on_connection)
336 0.003 0.000 0.568 0.002 base.py:975(_execute_clauseelement)
10680 0.031 0.000 0.526 0.000 dataset_matcher.py:47(valid_hda_match)
128 0.001 0.000 0.525 0.004 basic.py:1878(match_multirun_collections)
156 0.003 0.000 0.446 0.003 query.py:2700(one)
816 0.004 0.000 0.426 0.001 basic.py:208(to_dict)
336 0.006 0.000 0.348 0.001 base.py:1061(_execute_context)
152 0.003 0.000 0.342 0.002 loading.py:161(load_on_ident)
44/4 0.001 0.000 0.324 0.081 __init__.py:219(populate_state)
16360 0.052 0.000 0.307 0.000 data.py:713(matches_any)
1300 0.007 0.000 0.302 0.000 loading.py:30(instances)
60/40 0.001 0.000 0.294 0.007 grouping.py:608(get_initial_value)
6168/3720 0.012 0.000 0.270 0.000 __init__.py:3222(populated)
336 0.001 0.000 0.268 0.001 default.py:449(do_execute)
336 0.262 0.001 0.267 0.001 {method 'execute' of 'psycopg2.extensions.cursor' objects}
As before I hit the build endpoint 4 times. Both functions have disappeared from the table of the 40 longest running function calls, and the total time required has decreased from 9.5 seconds to 2.2 seconds.