neutron

remove eager subquery load for DistributedPortBinding

Bug #1973576 reported by norman shen on 2022-05-16

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	neutron	Fix Released	Undecided	Unassigned

Bug Description

We observe excessive DB calls to load DistributedPortBindings,
We have enabled DVR and have some huge virtual routers with around
60 router interfaces scheduled on around 200 compute nodes.

We saw something like

```console
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server Traceback (most recent call last):
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1193, in _execute_context
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server context)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/engine/default.py", line 509, in do_execute
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server cursor.execute(statement, parameters)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/pymysql/cursors.py", line 170, in execute
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server result = self._query(query)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/pymysql/cursors.py", line 328, in _query
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server conn.query(q)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/pymysql/connections.py", line 516, in query
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/pymysql/connections.py", line 727, in _read_query_result
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server result.read()
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/pymysql/connections.py", line 1073, in read
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server self._read_result_packet(first_packet)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/pymysql/connections.py", line 1143, in _read_result_packet
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server self._read_rowdata_packet()
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/pymysql/connections.py", line 1177, in _read_rowdata_packet
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server packet = self.connection._read_packet()
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/pymysql/connections.py", line 673, in _read_packet
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server recv_data = self._read_bytes(bytes_to_read)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/pymysql/connections.py", line 702, in _read_bytes
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server CR.CR_SERVER_LOST, "Lost connection to MySQL server during query")
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server pymysql.err.OperationalError: (2013, 'Lost connection to MySQL server during query')
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server The above exception was the direct cause of the following exception:
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server Traceback (most recent call last):
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/oslo_messaging/rpc/server.py", line 166, in _process_incoming
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server res = self.dispatcher.dispatch(message)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/oslo_messaging/rpc/dispatcher.py", line 265, in dispatch
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server return self._do_dispatch(endpoint, method, ctxt, args)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/oslo_messaging/rpc/dispatcher.py", line 194, in _do_dispatch
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server result = func(ctxt, **new_args)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/neutron/api/rpc/handlers/l3_rpc.py", line 104, in get_router_ids
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server self.l3plugin.auto_schedule_routers(context, host)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/neutron/db/l3_agentschedulers_db.py", line 472, in auto_schedule_routers
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server self.router_scheduler.auto_schedule_routers(self, context, host)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/neutron/scheduler/l3_agent_scheduler.py", line 97, in auto_schedule_routers
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server plugin, context)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/neutron/scheduler/l3_agent_scheduler.py", line 108, in _get_underscheduled_routers
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server for router, count in plugin.get_routers_l3_agents_count(context):
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/neutron/db/l3_agentschedulers_db.py", line 392, in get_routers_l3_agents_count
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server context)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/neutron/objects/router.py", line 126, in get_router_agents_count
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server return [(router, agent_count) for router, agent_count in query]
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/neutron/objects/router.py", line 126, in <listcomp>
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server return [(router, agent_count) for router, agent_count in query]
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 98, in instances
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server util.raise_from_cause(err)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 265, in raise_from_cause
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server reraise(type(exception), exception, tb=exc_tb, cause=cause)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 249, in reraise
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server raise value
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 82, in instances
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server for row in fetch]
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 82, in <listcomp>
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server for row in fetch]
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 81, in <listcomp>
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server rows = [keyed_tuple([proc(row) for proc in process])
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 511, in _instance
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server loaded_instance, populate_existing, populators)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 622, in _populate_full
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server populator(state, dict_, row)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/strategies.py", line 1237, in load_collection_from_subq
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server ()
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/strategies.py", line 1174, in get
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server self._load()
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/strategies.py", line 1182, in _load
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server lambda x: x[1:]
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/strategies.py", line 1179, in <genexpr>
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server (k, [vv[0] for vv in v])
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 98, in instances
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server util.raise_from_cause(err)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 265, in raise_from_cause
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server reraise(type(exception), exception, tb=exc_tb, cause=cause)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 249, in reraise
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server raise value
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 82, in instances
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server for row in fetch]
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 82, in <listcomp>
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server for row in fetch]
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 81, in <listcomp>
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server rows = [keyed_tuple([proc(row) for proc in process])
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 511, in _instance
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server loaded_instance, populate_existing, populators)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 622, in _populate_full
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server populator(state, dict_, row)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/strategies.py", line 1806, in load_scalar_from_joined_new_row
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server dict_[key] = _instance(row)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 511, in _instance
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server loaded_instance, populate_existing, populators)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 622, in _populate_full
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server populator(state, dict_, row)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/strategies.py", line 1237, in load_collection_from_subq
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server ()
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/strategies.py", line 1174, in get
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server self._load()
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/strategies.py", line 1182, in _load
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server lambda x: x[1:]
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/query.py", line 2988, in __iter__
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server return self._execute_and_instances(context)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/query.py", line 3011, in _execute_and_instances
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server result = conn.execute(querycontext.statement, self._params)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 948, in execute
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server return meth(self, multiparams, params)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/sql/elements.py", line 269, in _execute_on_connection
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server return connection._execute_clauseelement(self, multiparams, params)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1060, in _execute_clauseelement
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server compiled_sql, distilled_params
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1200, in _execute_context
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server context)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1409, in _handle_dbapi_exception
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server util.raise_from_cause(newraise, exc_info)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/oslo_messaging/rpc/dispatcher.py", line 194, in _do_d
ispatch
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server result = func(ctxt, **new_args)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/neutron/api/rpc/handlers/l3_rpc.py", line 104, in get
_router_ids
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server self.l3plugin.auto_schedule_routers(context, host)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/neutron/db/l3_agentschedulers_db.py", line 472, in auto_schedule_routers
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server self.router_scheduler.auto_schedule_routers(self, context, host)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/neutron/scheduler/l3_agent_scheduler.py", line 97, in auto_schedule_routers
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server plugin, context)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/neutron/scheduler/l3_agent_scheduler.py", line 108, in _get_underscheduled_routers
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server for router, count in plugin.get_routers_l3_agents_count(context):
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/sitepackages/neutron/db/l3_agentschedulers_db.py", line 392, in get_routers_l3_agents_count
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server context)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/neutron/objects/router.py", line 126, in get_router_agents_count
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server return [(router, agent_count) for router, agent_count in query]
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/neutron/objects/router.py", line 126, in <listcomp>
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server return [(router, agent_count) for router, agent_count in query]
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 98, in instances
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server util.raise_from_cause(err)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 265, in raise_from_c
ause
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server reraise(type(exception), exception, tb=exc_tb, cause=cause)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 249, in reraise
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server raise value
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 82, in instances
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server for row in fetch]
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 82, in <listcomp>
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server for row in fetch]
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 81, in <listcomp>
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server rows = [keyed_tuple([proc(row) for proc in process])
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 511, in _instance
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server loaded_instance, populate_existing, populators)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 622, in _populate_fu
ll
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server populator(state, dict_, row)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/strategies.py", line 1237, in load_col
lection_from_subq
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server ()
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/strategies.py", line 1174, in get
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server self._load()
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/strategies.py", line 1182, in _load
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server lambda x: x[1:]
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/strategies.py", line 1179, in <genexpr>
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server (k, [vv[0] for vv in v])
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 98, in instances
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server util.raise_from_cause(err)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 265, in raise_from_cause
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server reraise(type(exception), exception, tb=exc_tb, cause=cause)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 249, in reraise
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server raise value
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 82, in instances
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server for row in fetch]
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 82, in <listcomp>
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server for row in fetch]
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 81, in <listcomp>
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server rows = [keyed_tuple([proc(row) for proc in process])
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 511, in _instance
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server loaded_instance, populate_existing, populators)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 622, in _populate_full
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server populator(state, dict_, row)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/strategies.py", line 1806, in load_scalar_from_joined_new_row
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server dict_[key] = _instance(row)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 511, in _instance
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server loaded_instance, populate_existing, populators)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/loading.py", line 622, in _populate_full
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server populator(state, dict_, row)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/strategies.py", line 1237, in load_collection_from_subq
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server ()
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/strategies.py", line 1174, in get
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server self._load()
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/strategies.py", line 1182, in _load
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server lambda x: x[1:]
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/query.py", line 2988, in __iter__
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server return self._execute_and_instances(context)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/orm/query.py", line 3011, in _execute_and_instances
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server result = conn.execute(querycontext.statement, self._params)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 948, in execute
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server return meth(self, multiparams, params)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/sql/elements.py", line 269, in _execute_on_connection
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server return connection._execute_clauseelement(self, multiparams, params)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1060, in _execute_clauseelement
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server compiled_sql, distilled_params
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1200, in _execute_context
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server context)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1409, in _handle_dbapi_exception
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server util.raise_from_cause(newraise, exc_info)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 265, in raise_from_cause
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server reraise(type(exception), exception, tb=exc_tb, cause=cause)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 248, in reraise
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server raise value.with_traceback(tb)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1193, in _execute_context
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server context)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/sqlalchemy/engine/default.py", line 509, in do_execute
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server cursor.execute(statement, parameters)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/pymysql/cursors.py", line 170, in execute
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server result = self._query(query)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/pymysql/cursors.py", line 328, in _query
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server conn.query(q)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/pymysql/connections.py", line 516, in query
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/pymysql/connections.py", line 727, in _read_query_result
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server result.read()
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/pymysql/connections.py", line 1073, in read
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server self._read_result_packet(first_packet)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/pymysql/connections.py", line 1143, in _read_result_packet
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server self._read_rowdata_packet()
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/pymysql/connections.py", line 1177, in _read_rowdata_packet
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server packet = self.connection._read_packet()
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/pymysql/connections.py", line 673, in _read_packet
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server recv_data = self._read_bytes(bytes_to_read)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/pymysql/connections.py", line 702, in _read_bytes
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server CR.CR_SERVER_LOST, "Lost connection to MySQL server during query")
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server oslo_db.exception.DBConnectionError: (pymysql.err.OperationalError) (2013, 'Lost connection to MySQL server during query') [SQL: 'SELECT ml2_distributed_port_bindings.port_id AS ml2_distributed_port_bindings_port_id, ml2_distributed_port_bindings.host AS ml2_distributed_port_bindings_host, ml2_distributed_port_bindings.router_id AS ml2_distributed_port_bindings_router_id, ml2_distributed_port_bindings.vif_type AS ml2_distributed_port_bindings_vif_type, ml2_distributed_port_bindings.vif_details AS ml2_distributed_port_bindings_vif_details, ml2_distributed_port_bindings.vnic_type AS ml2_distributed_port_bindings_vnic_type, ml2_distributed_port_bindings.profile AS ml2_distributed_port_bindings_profile, ml2_distributed_port_bindings.status AS ml2_distributed_port_bindings_status, ports_1.id AS ports_1_id \nFROM (SELECT routers.id AS routers_id \nFROM routers LEFT OUTER JOIN (SELECT routerl3agentbindings.router_id AS router_id, count(routerl3agentbindings.router_id) AS count \nFROM routerl3agentbindings INNER JOIN router_extra_attributes ON routerl3agentbindings.router_id = router_extra_attributes.router_id INNER JOIN routers ON routers.id = router_extra_attributes.router_id GROUP BY routerl3agentbindings.router_id) AS anon_2 ON routers.id = anon_2.router_id) AS anon_1 INNER JOIN routerports AS routerports_1 ON anon_1.routers_id = routerports_1.router_id INNER JOIN ports AS ports_1 ON ports_1.id = routerports_1.port_id INNER JOIN ml2_distributed_port_bindings ON ports_1.id = ml2_distributed_port_bindings.port_id ORDER BY ports_1.id'] (Background on this error at: http://sqlalche.me/e/e3q8)
2022-05-12 05:59:06.406 50 ERROR oslo_messaging.rpc.server
```

as well as

```console
SELECT ml2_distributed_port_bindings.port_id AS ml2_distributed_port_bindings_port_id, ml2_distributed_port_bindings.host AS ml2_distributed_port_bindings_host, ml2_distributed_port_bindings.router_id AS ml2_distributed_port_bindings_router_id, ml2_distributed_port_bindings.vif_type AS ml2_distributed_port_bindings_vif_type, ml2_distributed_port_bindings.vif_details AS ml2_distributed_port_bindings_vif_details, ml2_distributed_port_bindings.vnic_type AS ml2_distributed_port_bindings_vnic_type, ml2_distributed_port_bindings.profile AS ml2_distributed_port_bindings_profile, ml2_distributed_port_bindings.status AS ml2_distributed_port_bindings_status, anon_1.ports_id AS anon_1_ports_id
FROM (SELECT ports.id AS ports_id
FROM ports
WHERE ports.device_owner IN ('network:router_interface_distributed') AND (EXISTS (SELECT 1
FROM ipallocations
WHERE ports.id = ipallocations.port_id AND ipallocations.subnet_id IN ('55f86bd8-4edc-4496-9b7a-28f460feb82a')))) AS anon_1 INNER JOIN ml2_distributed_port_bindings ON anon_1.ports_id = ml2_distributed_port_bindings.port_id ORDER BY anon_1.ports_id
```

from show processlist. and we saw excessive amounts of slow queries for ml2_distributed_port_binding which is weird because it looks like not necessary.

See original description

Tags:

OpenStack Infra (hudson-openstack) on 2022-05-16

Changed in neutron:
status:	New → In Progress

norman shen (jshen28) on 2022-05-16

description:

updated

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2022-05-16: Fix merged to neutron (master)

Reviewed: https://review.opendev.org/c/openstack/neutron/+/841823
Committed: https://opendev.org/openstack/neutron/commit/182044d628314290a38440bab203d27fb9db755d
Submitter: "Zuul (22348)"
Branch: master

commit 182044d628314290a38440bab203d27fb9db755d
Author: shenjiatong <email address hidden>
Date: Sun May 15 10:12:47 2022 +0800

Do not auto subquery load DistributedPortBindings

    We observe excessive DB calls to load DistributedPortBindings,
    We have enabled DVR and have some huge virtual routers with around
    60 router interfaces scheduled on around 200 compute nodes. Under such
    situation, subquery load DistributedPortBinding looks like not a very wise
    idea, because it is not explicitly used.

    I glance through the code and have a feeling that ml2_distributed_port_bindings
    is not used except explicitly called. So IMO it is safe to change it to
    default lazy load without causing serious regression.

Closes-bug: #1973576
Change-Id: Ib2c48bd5ad55e9c754a8e4938e6c5eafacc75dcc

Changed in neutron:
status:	In Progress → Fix Released

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2022-05-17: Fix proposed to neutron (stable/yoga)

Fix proposed to branch: stable/yoga
Review: https://review.opendev.org/c/openstack/neutron/+/841932

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2022-05-24: Fix merged to neutron (stable/yoga)

Reviewed: https://review.opendev.org/c/openstack/neutron/+/841932
Committed: https://opendev.org/openstack/neutron/commit/eb63fa883c7f05f806c213b40de158efaa5aed07
Submitter: "Zuul (22348)"
Branch: stable/yoga

commit eb63fa883c7f05f806c213b40de158efaa5aed07
Author: shenjiatong <email address hidden>
Date: Sun May 15 10:12:47 2022 +0800

Do not auto subquery load DistributedPortBindings

    Closes-bug: #1973576
    Change-Id: Ib2c48bd5ad55e9c754a8e4938e6c5eafacc75dcc
    (cherry picked from commit 182044d628314290a38440bab203d27fb9db755d)