I am able to replicate this bug with a development system setup with master branch. Executing the following python script, I created 6000+ security groups in my development system (showing only relevant part):
After creating the security groups (and leaving above script stopped at the pdb.set_trace() line), I execute the following bash script:
source ~/demo-openrc
start_time="$(date -u +%s)"
openstack security group list
end_time="$(date -u +%s)"
elapsed="$(($end_time-$start_time))"
echo "Total of $elapsed seconds elapsed for process"
One of the executions produces the following output (all runs showed about the same elapsed time):
+--------------------------------------+---------+------------------------+----------------------------------+------+
| ID | Name | Description | Project | Tags |
+--------------------------------------+---------+------------------------+----------------------------------+------+
| 58d172f3-b1ce-4592-a954-7151f9e7708e | default | Default security group | 29b2f9ab6dc04e0ab8ab7e48c8baaa8d | [] |
+--------------------------------------+---------+------------------------+----------------------------------+------+
Total of 525 seconds elapsed for process
However, executing the following python script:
import time
from sqlalchemy import create_engine
from sqlalchemy.orm import sessionmaker
from neutron.db.models import securitygroup
engine = create_engine(
'mysql+pymysql://root:devstack@127.0.0.1/neutron?charset=utf8',
echo=False)
session = sessionmaker()
session.configure(bind=engine)
s = session()
start = time.time()
query = s.query(securitygroup.SecurityGroup)
secgroups = query.all()
end = time.time()
print('Number of security groups retrieved %s' % len(secgroups))
print('Elapsed time in seconds: %s' % (end - start))
I get the following output:
Number of security groups retrieved 6005
Elapsed time in seconds: 0.654874801636
This tells us that the problem is not the definition of the SQLAlchemy DB model as suggested in one of the previous comments regarding the lazy attribute of the rbac_entries relationship (https://review.opendev.org/#/c/635311/22/neutron/db/models/securitygroup.py@33), because a query that retrieves 6005 sec groups takes less than a second.
+--------------------------------------+---------+------------------------+----------------------------------+------+
| ID | Name | Description | Project | Tags |
+--------------------------------------+---------+------------------------+----------------------------------+------+
| 58d172f3-b1ce-4592-a954-7151f9e7708e | default | Default security group | 29b2f9ab6dc04e0ab8ab7e48c8baaa8d | [] |
+--------------------------------------+---------+------------------------+----------------------------------+------+
Total of 504 seconds elapsed for process
While I can see the following lines in the neutron server log file:
Between these two lines there is an elapsed time of 454 seconds. In other words, Most of the 504 seconds shown above are spent trying to select, based on non-existent RBAC entries, the security groups retrieved from the DB
I am able to replicate this bug with a development system setup with master branch. Executing the following python script, I created 6000+ security groups in my development system (showing only relevant part):
secgroups_ids = [] in_project = 0 secgroups_ count = 0 secgroups_ count < 6000: in_project <= 0: projects. create(
name= 'test-project- %s' % created_projects,
domain= login_data[ 'user_domain_ id'])
secgroups_ in_project = random.randint(1, 7)
projects_ ids.append( project. id)
new_ project = True
created_ projects += 1
' name': 'test-secgroup-%s' % created_ secgroups_ count,
' description' : ('Test security group %s' %
created_ secgroups_ count),
' project_ id': project.id}} create_ security_ group(body= body)
secgroups_ in_project -= 1
secgroups_ ids.append( secgroup[ 'security_ group'] ['id'])
created_ secgroups_ count += 1
new_ project = False
default_ secgroup = neutron. list_security_ groups(
name= 'default' , project_ id=project. id)['security_ groups' ][0]
secgroups_ ids.append( default_ secgroup[ 'id'])
created_ secgroups_ count += 1
print( created_ secgroups_ count)
neutron. delete_ security_ group(secgroup_ id)
keystone. projects. delete( project_ id)
projects_ids = []
secgroups_
created_
created_projects = 0
try:
while created_
if secgroups_
project = keystone.
body = {'security_group': {
secgroup = neutron.
if new_project:
import pdb
pdb.set_trace()
finally:
for secgroup_id in secgroups_ids:
for project_id in projects_ids:
After creating the security groups (and leaving above script stopped at the pdb.set_trace() line), I execute the following bash script:
source ~/demo-openrc "$(($end_ time-$start_ time))"
start_time="$(date -u +%s)"
openstack security group list
end_time="$(date -u +%s)"
elapsed=
echo "Total of $elapsed seconds elapsed for process"
One of the executions produces the following output (all runs showed about the same elapsed time):
+------ ------- ------- ------- ------- ----+-- ------- +------ ------- ------- ----+-- ------- ------- ------- ------- ----+-- ----+ ------- ------- ------- ------- ----+-- ------- +------ ------- ------- ----+-- ------- ------- ------- ------- ----+-- ----+ b1ce-4592- a954-7151f9e770 8e | default | Default security group | 29b2f9ab6dc04e0 ab8ab7e48c8baaa 8d | [] | ------- ------- ------- ------- ----+-- ------- +------ ------- ------- ----+-- ------- ------- ------- ------- ----+-- ----+
| ID | Name | Description | Project | Tags |
+------
| 58d172f3-
+------
Total of 525 seconds elapsed for process
However, executing the following python script:
import time
from sqlalchemy import create_engine
from sqlalchemy.orm import sessionmaker
from neutron.db.models import securitygroup
engine = create_engine( pymysql: //root: devstack@ 127.0.0. 1/neutron? charset= utf8', configure( bind=engine) securitygroup. SecurityGroup)
'mysql+
echo=False)
session = sessionmaker()
session.
s = session()
start = time.time()
query = s.query(
secgroups = query.all()
end = time.time()
print('Number of security groups retrieved %s' % len(secgroups))
print('Elapsed time in seconds: %s' % (end - start))
I get the following output:
Number of security groups retrieved 6005
Elapsed time in seconds: 0.654874801636
This tells us that the problem is not the definition of the SQLAlchemy DB model as suggested in one of the previous comments regarding the lazy attribute of the rbac_entries relationship (https:/ /review. opendev. org/#/c/ 635311/ 22/neutron/ db/models/ securitygroup. py@33), because a query that retrieves 6005 sec groups takes less than a second.
Digging at the code, I added LOG statements right before this line https:/ /review. opendev. org/#/c/ 635311/ 22/neutron/ objects/ rbac_db. py@114 and right before this line https:/ /review. opendev. org/#/c/ 635311/ 22/neutron/ objects/ rbac_db. py@118. Executing the above bash script, I get the following output:
+------ ------- ------- ------- ------- ----+-- ------- +------ ------- ------- ----+-- ------- ------- ------- ------- ----+-- ----+ ------- ------- ------- ------- ----+-- ------- +------ ------- ------- ----+-- ------- ------- ------- ------- ----+-- ----+ b1ce-4592- a954-7151f9e770 8e | default | Default security group | 29b2f9ab6dc04e0 ab8ab7e48c8baaa 8d | [] | ------- ------- ------- ------- ----+-- ------- +------ ------- ------- ----+-- ------- ------- ------- ------- ----+-- ----+
| ID | Name | Description | Project | Tags |
+------
| 58d172f3-
+------
Total of 504 seconds elapsed for process
While I can see the following lines in the neutron server log file:
Jun 16 23:11:51 allinone neutron- server[ 14624]: DEBUG neutron. objects. rbac_db [None req-909eccd0- 1cdb-480c- a5be-170ef82abd eb demo demo] mlavalle {{(pid=14638) get_objects /opt/stack/ neutron/ neutron/ objects/ rbac_db. py:119} }
Jun 16 23:19:25 allinone neutron- server[ 14624]: DEBUG neutron. objects. rbac_db [None req-909eccd0- 1cdb-480c- a5be-170ef82abd eb demo demo] mlavalle {{(pid=14638) get_objects /opt/stack/ neutron/ neutron/ objects/ rbac_db. py:124} }
Between these two lines there is an elapsed time of 454 seconds. In other words, Most of the 504 seconds shown above are spent trying to select, based on non-existent RBAC entries, the security groups retrieved from the DB