taskotron / resultsdb

#84 /results/latest endpoint is very slow because it issues N queries where N = number of matching test cases
Closed: Fixed Opened by dcallagh.

Closed: Fixed
Reopen Issue

The /results/latest endpoint is used by Bodhi to show latest test results, but it's very slow. For example, on this update:

https://bodhi.fedoraproject.org/updates/FEDORA-2017-eae0de7a03

my browser tells me that this AJAX request takes 27 seconds to come back:

https://taskotron.fedoraproject.org/resultsdb_api//api/v2.0/results/latest?item=python-sphinxcontrib-httpdomain-1.5.0-4.fc26&type=koji_build&testcases:like=dist.*&callback=jQuery110208478052653092084_1506323733047&_=1506323733048

I grabbed a production dump and loaded it in my dev environment and repeated the same API call, and I can reproduce the slow response (well, 7 seconds instead of 27... I guess the difference is due to load on the production ResultsDB instance).

I turned on logging for sqlalchemy.engine to show all database queries, and the first thing I noticed is that when ResultsDB handles /results/latest it does a very large number of roundtrips to Postgres, like this:

[base.py:912] 2017-09-25 17:24:24 INFO    SELECT result.id AS result_id, result.testcase_name AS result_testcase_name, result.submit_time AS result_submit_time, result.outcome AS result_outcome, result.note AS result_note, result.ref_url AS result_ref_url 
FROM result JOIN result_data AS result_data_1 ON result.id = result_data_1.result_id JOIN result_data AS result_data_2 ON result.id = result_data_2.result_id 
WHERE result.testcase_name IN (%(testcase_name_1)s) AND result_data_1.key = %(key_1)s AND result_data_1.value IN (%(value_1)s) AND result_data_2.key = %(key_2)s AND result_data_2.value IN (%(value_2)s) ORDER BY result.submit_time DESC 
 LIMIT %(param_1)s
[base.py:915] 2017-09-25 17:24:24 INFO    {'param_1': 1, 'value_1': u'python-sphinxcontrib-httpdomain-1.5.0-4.fc26', 'value_2': u'koji_build', 'key_1': 'item', 'testcase_name_1': u'dist.modulemd.check_modulemd.ModulemdTest.test_debugdump;run-e9c4', 'key_2': 'type'}
[base.py:912] 2017-09-25 17:24:24 INFO    SELECT result.id AS result_id, result.testcase_name AS result_testcase_name, result.submit_time AS result_submit_time, result.outcome AS result_outcome, result.note AS result_note, result.ref_url AS result_ref_url 
FROM result JOIN result_data AS result_data_1 ON result.id = result_data_1.result_id JOIN result_data AS result_data_2 ON result.id = result_data_2.result_id 
WHERE result.testcase_name IN (%(testcase_name_1)s) AND result_data_1.key = %(key_1)s AND result_data_1.value IN (%(value_1)s) AND result_data_2.key = %(key_2)s AND result_data_2.value IN (%(value_2)s) ORDER BY result.submit_time DESC 
 LIMIT %(param_1)s
[base.py:915] 2017-09-25 17:24:24 INFO    {'param_1': 1, 'value_1': u'python-sphinxcontrib-httpdomain-1.5.0-4.fc26', 'value_2': u'koji_build', 'key_1': 'item', 'testcase_name_1': u'dist.modulemd.check_modulemd.ModulemdTest.test_debugdump;run-ea7c', 'key_2': 'type'}
[base.py:912] 2017-09-25 17:24:24 INFO    SELECT result.id AS result_id, result.testcase_name AS result_testcase_name, result.submit_time AS result_submit_time, result.outcome AS result_outcome, result.note AS result_note, result.ref_url AS result_ref_url 
FROM result JOIN result_data AS result_data_1 ON result.id = result_data_1.result_id JOIN result_data AS result_data_2 ON result.id = result_data_2.result_id 
WHERE result.testcase_name IN (%(testcase_name_1)s) AND result_data_1.key = %(key_1)s AND result_data_1.value IN (%(value_1)s) AND result_data_2.key = %(key_2)s AND result_data_2.value IN (%(value_2)s) ORDER BY result.submit_time DESC 
 LIMIT %(param_1)s
[base.py:915] 2017-09-25 17:24:24 INFO    {'param_1': 1, 'value_1': u'python-sphinxcontrib-httpdomain-1.5.0-4.fc26', 'value_2': u'koji_build', 'key_1': 'item', 'testcase_name_1': u'dist.modulemd.check_modulemd.ModulemdTest.test_debugdump;run-ecd3', 'key_2': 'type'}

The slow response time seems to be dominated by roundtrip time to the database due to the huge number of queries being issued (even though most of them don't match anything).

The fact that there are a large number of different test cases with that strange ;run-XXXX suffix does not seem right but it's a separate problem anyway, and the data is in there now, so ResultsDB really needs to be able to handle it.

Instead of selecting all test cases, and then issuing a query for every test case, we can use the subquery join trick: #85

Note that this also fixes the _sort parameter for /results/latest as a side effect, which is why the test cases have all the ordering flipped around.

With that patch, a request for:

/api/v2.0/results/latest?item=python-sphinxcontrib-httpdomain-1.5.0-4.fc26&type=koji_build&testcases:like=dist.*

goes from 7-8 seconds down to 400-450ms on my dev server.

taskotron/resultsdb#85 has been merged, it seems that this ticket can be closed? @dcallagh @jskladan

Indeed it has, although it hasn't appeared in any release yet... Not sure if the preferred approach is to close issues as soon as they are fixed on develop, or to close them when a release is made?

@dcallagh When merged is the best.
My bad here - I'm still mentally used to how awesome Phabricator was with worflow like this, automagically closing tickets relevant to merged patches..

Closing

Metadata Update from @jskladan:
- Issue close_status updated to: Fixed
Metadata
None
None
None
None
None
Static archive. pagure.io was sunset in 2026; this is a read-only snapshot.
Red Hat Logo

Fedora is sponsored by Red Hat. Learn more about the relationship between Red Hat and Fedora »

© Red Hat, Inc. and others.