yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1691545] Re: Significant increase in DB connections with cells

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: OpenStack Infra <1691545@xxxxxxxxxxxxxxxxxx>
Date: Fri, 19 May 2017 21:24:12 -0000
Reply-to: Bug 1691545 <1691545@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Reviewed:  https://review.openstack.org/465042
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=47fa88d94754fcdad6bb132b45196b4d44c0f4cd
Submitter: Jenkins
Branch:    master

commit 47fa88d94754fcdad6bb132b45196b4d44c0f4cd
Author: melanie witt <melwittt@xxxxxxxxx>
Date:   Tue May 16 10:25:42 2017 +0000

    Cache database and message queue connection objects
    
    Recently in the gate we have seen a trace on some work-in-progress
    patches:
    
      OperationalError: (pymysql.err.OperationalError)
                        (1040, u'Too many connections')
    
    and at least one operator has reported that the number of database
    connections increased significantly going from Mitaka to Newton.
    
    It was suspected that the increase was caused by creating new oslo.db
    transaction context managers on-the-fly when switching database
    connections for cells. Comparing the dstat --tcp output of runs of the
    gate-tempest-dsvm-neutron-full-ubuntu-xenial job with and without
    caching of the database connections showed a difference of 445 active
    TCP connections and 1495 active TCP connections, respectively [1].
    
    This adds caching of the oslo.db transaction context managers and the
    oslo.messaging transports to avoid creating a large number of objects
    that are not being garbage-collected as expected.
    
    Closes-Bug: #1691545
    
    [1] https://docs.google.com/spreadsheets/d/1DIfFfX3kaA_SRoCM-aO7BN4IBEShChXLztOBFeKryt4/edit?usp=sharing
    
    Change-Id: I17e0eb836dd87aac5859f506e7d771d42753d31a


** Changed in: nova
       Status: In Progress => Fix Released

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1691545

Title:
  Significant increase in DB connections with cells

Status in OpenStack Compute (nova):
  Fix Released
Status in OpenStack Compute (nova) newton series:
  Confirmed
Status in OpenStack Compute (nova) ocata series:
  Confirmed

Bug description:
  Recently in the gate we have seen a trace [1] on some work-in-progress patches:
      
        OperationalError: (pymysql.err.OperationalError)
                          (1040, u'Too many connections')
      
  and at least one operator has reported that the number of database connections increased significantly going from Mitaka to Newton.
      
  It was suspected that the increase was caused by creating new oslo.db transaction context managers on-the-fly when switching database connections for cells. Comparing the dstat --tcp output of runs of the gate-tempest-dsvm-neutron-full-ubuntu-xenial job with and without caching of the database connections showed a difference of 445 active TCP connections and 1495 active TCP connections, respectively [1].

  [1] http://logs.openstack.org/37/458537/19/check/gate-tempest-dsvm-neutron-full-ubuntu-xenial/e290ec2/logs/screen-n-api.txt.gz?level=TRACE#_May_11_20_08_20_211256
  [2] https://docs.google.com/spreadsheets/d/1DIfFfX3kaA_SRoCM-aO7BN4IBEShChXLztOBFeKryt4/edit?usp=sharing

  Full trace:

  May 11 20:08:20.190181 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions [req-04cbf0fb-d31a-48fb-bc1a-8572b4fe1dfb tempest-AttachVolumeShelveTestJSON-2114880401 tempest-AttachVolumeShelveTestJSON-2114880401] Unexpected exception in API method
  May 11 20:08:20.194490 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions Traceback (most recent call last):
  May 11 20:08:20.194634 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/opt/stack/new/nova/nova/api/openstack/extensions.py", line 336, in wrapped
  May 11 20:08:20.194768 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     return f(*args, **kwargs)
  May 11 20:08:20.194899 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/opt/stack/new/nova/nova/api/openstack/compute/servers.py", line 439, in show
  May 11 20:08:20.195035 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     instance = self._get_server(context, req, id, is_detail=True)
  May 11 20:08:20.195171 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/opt/stack/new/nova/nova/api/openstack/compute/servers.py", line 344, in _get_server
  May 11 20:08:20.195313 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     expected_attrs=expected_attrs)
  May 11 20:08:20.195443 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/opt/stack/new/nova/nova/api/openstack/common.py", line 479, in get_instance
  May 11 20:08:20.195600 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     expected_attrs=expected_attrs)
  May 11 20:08:20.195806 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/opt/stack/new/nova/nova/compute/api.py", line 2468, in get
  May 11 20:08:20.196044 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     expected_attrs)
  May 11 20:08:20.196207 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/opt/stack/new/nova/nova/compute/api.py", line 2428, in _get_instance
  May 11 20:08:20.196350 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     context, instance_uuid, expected_attrs=expected_attrs)
  May 11 20:08:20.196488 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 184, in wrapper
  May 11 20:08:20.196629 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     result = fn(cls, context, *args, **kwargs)
  May 11 20:08:20.196760 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/opt/stack/new/nova/nova/objects/instance.py", line 463, in get_by_uuid
  May 11 20:08:20.196889 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     use_slave=use_slave)
  May 11 20:08:20.197011 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/opt/stack/new/nova/nova/db/sqlalchemy/api.py", line 235, in wrapper
  May 11 20:08:20.197173 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     with reader_mode.using(context):
  May 11 20:08:20.197361 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/contextlib.py", line 17, in __enter__
  May 11 20:08:20.197513 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     return self.gen.next()
  May 11 20:08:20.197635 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 1011, in _transaction_scope
  May 11 20:08:20.197808 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     allow_async=self._allow_async) as resource:
  May 11 20:08:20.198096 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/contextlib.py", line 17, in __enter__
  May 11 20:08:20.198299 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     return self.gen.next()
  May 11 20:08:20.198501 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 624, in _session
  May 11 20:08:20.198694 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     bind=self.connection, mode=self.mode)
  May 11 20:08:20.198884 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 394, in _create_session
  May 11 20:08:20.199084 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     self._start()
  May 11 20:08:20.199432 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 480, in _start
  May 11 20:08:20.199571 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     engine_args, maker_args)
  May 11 20:08:20.199713 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 504, in _setup_for_connection
  May 11 20:08:20.199836 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     sql_connection=sql_connection, **engine_kwargs)
  May 11 20:08:20.200109 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/engines.py", line 154, in create_engine
  May 11 20:08:20.200237 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     test_conn = _test_connection(engine, max_retries, retry_interval)
  May 11 20:08:20.200358 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/engines.py", line 329, in _test_connection
  May 11 20:08:20.200477 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     return engine.connect()
  May 11 20:08:20.200597 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 2091, in connect
  May 11 20:08:20.200911 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     return self._connection_cls(self, **kwargs)
  May 11 20:08:20.201034 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 90, in __init__
  May 11 20:08:20.201155 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     if connection is not None else engine.raw_connection()
  May 11 20:08:20.201272 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 2177, in raw_connection
  May 11 20:08:20.201393 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     self.pool.unique_connection, _connection)
  May 11 20:08:20.201512 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 2151, in _wrap_pool_connect
  May 11 20:08:20.201631 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     e, dialect, self)
  May 11 20:08:20.201750 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1461, in _handle_dbapi_exception_noconnection
  May 11 20:08:20.201869 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     util.raise_from_cause(newraise, exc_info)
  May 11 20:08:20.202104 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/util/compat.py", line 203, in raise_from_cause
  May 11 20:08:20.202263 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     reraise(type(exception), exception, tb=exc_tb, cause=cause)
  May 11 20:08:20.202391 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 2147, in _wrap_pool_connect
  May 11 20:08:20.202520 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     return fn()
  May 11 20:08:20.202646 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 328, in unique_connection
  May 11 20:08:20.202766 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     return _ConnectionFairy._checkout(self)
  May 11 20:08:20.202884 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 766, in _checkout
  May 11 20:08:20.203002 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     fairy = _ConnectionRecord.checkout(pool)
  May 11 20:08:20.203139 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 516, in checkout
  May 11 20:08:20.203356 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     rec = pool._do_get()
  May 11 20:08:20.203551 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 1138, in _do_get
  May 11 20:08:20.203677 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     self._dec_overflow()
  May 11 20:08:20.203873 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/util/langhelpers.py", line 66, in __exit__
  May 11 20:08:20.203992 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     compat.reraise(exc_type, exc_value, exc_tb)
  May 11 20:08:20.204161 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 1135, in _do_get
  May 11 20:08:20.204289 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     return self._create_connection()
  May 11 20:08:20.204648 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 333, in _create_connection
  May 11 20:08:20.204904 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     return _ConnectionRecord(self)
  May 11 20:08:20.205144 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 461, in __init__
  May 11 20:08:20.205350 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     self.__connect(first_connect_check=True)
  May 11 20:08:20.205550 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 651, in __connect
  May 11 20:08:20.205746 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     connection = pool._invoke_creator(self)
  May 11 20:08:20.205958 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/strategies.py", line 105, in connect
  May 11 20:08:20.206225 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     return dialect.connect(*cargs, **cparams)
  May 11 20:08:20.206420 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 393, in connect
  May 11 20:08:20.206643 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     return self.dbapi.connect(*cargs, **cparams)
  May 11 20:08:20.206823 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/pymysql/__init__.py", line 90, in Connect
  May 11 20:08:20.207024 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     return Connection(*args, **kwargs)
  May 11 20:08:20.207221 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 706, in __init__
  May 11 20:08:20.208932 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     self.connect()
  May 11 20:08:20.209146 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 931, in connect
  May 11 20:08:20.209358 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     self._get_server_information()
  May 11 20:08:20.209780 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 1245, in _get_server_information
  May 11 20:08:20.209983 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     packet = self._read_packet()
  May 11 20:08:20.210300 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 1014, in _read_packet
  May 11 20:08:20.210448 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     packet.check_error()
  May 11 20:08:20.210591 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 393, in check_error
  May 11 20:08:20.210718 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     err.raise_mysql_exception(self._data)
  May 11 20:08:20.210848 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions   File "/usr/local/lib/python2.7/dist-packages/pymysql/err.py", line 107, in raise_mysql_exception
  May 11 20:08:20.211044 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions     raise errorclass(errno, errval)
  May 11 20:08:20.211256 ubuntu-xenial-rax-ord-8797540 nova-api[18343]: ERROR nova.api.openstack.extensions OperationalError: (pymysql.err.OperationalError) (1040, u'Too many connections')

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1691545/+subscriptions
References

[Bug 1691545] [NEW] Significant increase in DB connections with cells
From: melanie witt, 2017-05-17