MySQL tests significantly slower than PostgreSQL tests
Bug #1602407 reported by
Clark Boylan
This bug affects 1 person
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
OpenStack Identity (keystone) |
Expired
|
Undecided
|
Unassigned |
Bug Description
Running the keystone opportunistic mysql and postgresql tests locally I noticed that the mysql tests run in 18-19seconds each and the postgresql tests run in 4-5seconds each. This may be a performance issue in keystone itself, in mysql, or in the test framework but it is likely a good idea to sort it out.
My setup is an Ubuntu Xenial virtual machine running mysql 5.7 and postgres 9.5. I am running the tests serially so that they do not interfere with each other.
To reproduce make sure you have mysql and postgresql configured as in the gate and run:
tox -epy27 -- --concurrency 1
Then compare the test run times.
To post a comment you must log in.
This is not specific to keystone. For example nova has the same problem:
$ tox -epy27 TestNovaMigrati onsMySQL -- --concurrency 1 unit.db. test_migrations .TestNovaMigrat ionsMySQL. test_innodb_ tables [89.743165s] ... ok unit.db. test_migrations .TestNovaMigrat ionsMySQL. test_migration_ 267 [63.138206s] ... ok unit.db. test_migrations .TestNovaMigrat ionsMySQL. test_models_ sync [90.889299s] ... ok unit.db. test_migrations .TestNovaMigrat ionsMySQL. test_walk_ versions [94.463895s] ... ok
<snip>
{0} nova.tests.
{0} nova.tests.
{0} nova.tests.
{0} nova.tests.
<snip>
$ tox -epy27 TestNovaMigrati onsPostgreSQL -- --concurrency 1 unit.db. test_migrations .TestNovaMigrat ionsPostgreSQL. test_migration_ 267 [35.031418s] ... ok unit.db. test_migrations .TestNovaMigrat ionsPostgreSQL. test_models_ sync [43.472909s] ... ok unit.db. test_migrations .TestNovaMigrat ionsPostgreSQL. test_walk_ versions [52.898358s] ... ok
<snip>
{0} nova.tests.
{0} nova.tests.
{0} nova.tests.
<snip>
I think the problem is in PyMySQL but I'm not sure it can be fixed. I'll post my findings so someone else can shortcut to a solution.
This is the minimum reproduceable example that we can use to profile each fixture:
$ cat mytest.py TestLoader( ).loadTestsFrom Name('keystone. tests.unit. identity. backends. test_sql. MySQLOpportunis ticIdentityDriv erTestCase. test_check_ user_in_ group') TextTestRunner( ).run(suite) TestLoader( ).loadTestsFrom Name('keystone. tests.unit. identity. backends. test_sql. PostgreSQLOppor tunisticIdentit yDriverTestCase .test_check_ user_in_ group') TextTestRunner( ).run(suite)
import unittest
suite = unittest.
unittest.
$ cat pgtest.py
import unittest
suite = unittest.
unittest.
We can profile these snippets:
$ cat myprofile.py TestLoader( ).loadTestsFrom Name('keystone. tests.unit. identity. backends. test_sql. MySQLOpportunis ticIdentityDriv erTestCase. test_check_ user_in_ group') TextTestRunner( ).run(suite)
code = """
import unittest
suite = unittest.
unittest.
"""
import cProfile
import pstats
cProfile. run(code, 'mystats') Stats(' mystats' ).sort_ stats(' tottime' ).print_ stats(5) TestLoader( ).loadTestsFrom Name('keystone. tests.unit. identity. backends. test_sql. PostgreSQLOppor tunisticIdentit yDriverTestCase .test_check_ user_in_ group') TextTestRunner( ).run(suite) run(code, 'pgstats') Stats(' pgstats' ).sort_ stats(' tottime' ).print_ stats(5)
pstats.
$ cat pgprofile.py
code = """
import unittest
suite = unittest.
unittest.
"""
import cProfile
import pstats
cProfile.
pstats.
The results of profiling each fixture:
$ python myprofile.py ------- ------- ------- ------- ------- ------- ------- ------- ------- --
.
-----
Ran 1 test in 11.863s
OK
Sun Jul 24 17:48:46 2016 mystats
1183677 function calls (1161483 primitive calls) in 12.776 seconds
Ordered by: internal time
List reduced from 8185 to 5 due to restriction <5>
ncalls tottime percall cumtime percall filename: lineno( function) dev/keystone/ .tox/py27/ lib...
401 11.076 0.028 11.076 0.028 {method 'recv_into' of '_socket.socket' objects}
20815 0.055 0.000 0.055 0.000 {posix.lstat}
2235/486 0.053 0.000 0.155 0.000 /home/krinkle/