MySQL tests significantly slower than PostgreSQL tests

[Clark Boylan]

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.

[Colleen Murphy (krinkle)]

This is not specific to keystone. For example nova has the same problem:

  $ tox -epy27 TestNovaMigrationsMySQL -- --concurrency 1
  <snip>
  {0} nova.tests.unit.db.test_migrations.TestNovaMigrationsMySQL.test_innodb_tables [89.743165s] ... ok
  {0} nova.tests.unit.db.test_migrations.TestNovaMigrationsMySQL.test_migration_267 [63.138206s] ... ok
  {0} nova.tests.unit.db.test_migrations.TestNovaMigrationsMySQL.test_models_sync [90.889299s] ... ok
  {0} nova.tests.unit.db.test_migrations.TestNovaMigrationsMySQL.test_walk_versions [94.463895s] ... ok
  <snip>

  $ tox -epy27 TestNovaMigrationsPostgreSQL -- --concurrency 1
  <snip>
  {0} nova.tests.unit.db.test_migrations.TestNovaMigrationsPostgreSQL.test_migration_267 [35.031418s] ... ok
  {0} nova.tests.unit.db.test_migrations.TestNovaMigrationsPostgreSQL.test_models_sync [43.472909s] ... ok
  {0} nova.tests.unit.db.test_migrations.TestNovaMigrationsPostgreSQL.test_walk_versions [52.898358s] ... ok
  <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
  import unittest
  suite = unittest.TestLoader().loadTestsFromName('keystone.tests.unit.identity.backends.test_sql.MySQLOpportunisticIdentityDriverTestCase.test_check_user_in_group')
  unittest.TextTestRunner().run(suite)
  $ cat pgtest.py
  import unittest
  suite = unittest.TestLoader().loadTestsFromName('keystone.tests.unit.identity.backends.test_sql.PostgreSQLOpportunisticIdentityDriverTestCase.test_check_user_in_group')
  unittest.TextTestRunner().run(suite)

We can profile these snippets:

  $ cat myprofile.py
  code = """
  import unittest
  suite = unittest.TestLoader().loadTestsFromName('keystone.tests.unit.identity.backends.test_sql.MySQLOpportunisticIdentityDriverTestCase.test_check_user_in_group')
  unittest.TextTestRunner().run(suite)
  """
  import cProfile
  import pstats

  cProfile.run(code, 'mystats')
  pstats.Stats('mystats').sort_stats('tottime').print_stats(5)
  $ cat pgprofile.py
  code = """
  import unittest
  suite = unittest.TestLoader().loadTestsFromName('keystone.tests.unit.identity.backends.test_sql.PostgreSQLOpportunisticIdentityDriverTestCase.test_check_user_in_group')
  unittest.TextTestRunner().run(suite)
  """
  import cProfile
  import pstats
  cProfile.run(code, 'pgstats')
  pstats.Stats('pgstats').sort_stats('tottime').print_stats(5)

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)
        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/dev/keystone/.tox/py27/lib...

[Colleen Murphy (krinkle)]

The mysql-connector engine from Oracle seems to have the same behavior as pymysql, spending most of its time in the socket.recv method, and also does not seem to be configurable. https://github.com/mysql/mysql-connector-python/blob/master/lib/mysql/connector/network.py

[Steve Martinelli (stevemar)]

Thanks for the in-depth analysis Colleen!

I agree that this is definitely not a keystone bug. I think it would be helpful to open an issue against pymysql to get their feedback on this topic [1]. From an openstack perspective, i'm not sure what we could do at the oslo.db layer to get around this, either.

[1] https://github.com/PyMySQL/PyMySQL/issues

[Steve Martinelli (stevemar)]

Leaving this as incomplete while I try to figure out which project to file this under...

[Launchpad Janitor (janitor)]

[Expired for OpenStack Identity (keystone) because there has been no activity for 60 days.]