yahoo-eng-team team mailing list archive
-
yahoo-eng-team team
-
Mailing list archive
-
Message #83400
[Bug 1788149] Re: nova list too slow
[Expired for OpenStack Compute (nova) because there has been no activity
for 60 days.]
** Changed in: nova
Status: Incomplete => Expired
--
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/1788149
Title:
nova list too slow
Status in OpenStack Compute (nova):
Expired
Bug description:
Description
===========
The version of Openstack is pike, the nova list command would take about 60 seconds, it is wired.
I checked the nova-api log, and found it would get stuck about 30
seconds after release lock by
"nova.context.get_or_set_cached_cell_and_set_connections" for one
cell.
Steps to reproduce
==================
[root@controller ~]# nova --timings list
+--------------------------------------+--------------+--------+------------+-------------+-----------------------------------------+
| ID | Name | Status | Task State | Power State | Networks |
+--------------------------------------+--------------+--------+------------+-------------+-----------------------------------------+
| cffc9bbb-02bb-4835-b367-9c46f6cd3d69 | influxdb | ACTIVE | - | Running | internal_192=192.168.51.16, 10.19.7.120 |
| 9f2c72fc-1eb7-44a8-841f-8d39575fd851 | k8s-master | ACTIVE | - | Running | internal_192=192.168.51.8, 10.19.7.116 |
| d75269ae-4e7f-4bd1-851c-20b8c5a25563 | k8s-node-1 | ACTIVE | - | Running | internal_192=192.168.51.5, 10.19.7.169 |
| 49f7b4c4-265d-4015-a447-620a777fe67c | k8s-node-2 | ACTIVE | - | Running | internal_192=192.168.51.12, 10.19.7.162 |
| c17ab2a3-f456-41fa-9c96-efd85dd80503 | k8s-node-3 | ACTIVE | - | Running | internal_192=192.168.51.15, 10.19.7.163 |
| bfea3c06-db83-4c06-9f2d-66a4c56bcdc3 | k8s-register | ACTIVE | - | Running | internal_192=192.168.51.18, 10.19.7.160 |
| a09e8187-f021-46b0-bf82-007aa673b36e | redis-mqtt | ACTIVE | - | Running | internal_192=192.168.51.17, 10.19.7.117 |
| 87004468-e14f-41fb-af6e-46e04f276026 | test-iot | ACTIVE | - | Running | internal_192=192.168.51.13, 10.19.7.170 |
| 8dec73ca-2ff9-4513-afce-da4075cca414 | test-iot2 | ACTIVE | - | Running | internal_192=192.168.51.7, 10.19.7.175 |
| 99786459-220d-4ba6-b939-3b7bcc5ec52e | test2 | ACTIVE | - | Running | internal_192=192.168.51.6 |
| 92d376ee-293c-46b8-a1f4-c2f77686d5ca | testai | ACTIVE | - | Running | internal_192=192.168.51.3, 10.19.7.165 |
| e49a17f8-d224-4639-90f2-fb6c17a8043e | zk-kafka | ACTIVE | - | Running | internal_192=192.168.51.4, 10.19.7.119 |
+--------------------------------------+--------------+--------+------------+-------------+-----------------------------------------+
+--------------------------------------+-------------------+
| url | seconds |
+--------------------------------------+-------------------+
| auth_url http://10.19.7.111:35357/v3 | 0.000923871994019 |
| GET /servers/detail | 61.2467708588 |
| Total | 61.2476947308 |
+--------------------------------------+-------------------+
Expected result
===============
the expected result is nova should return the result in 1-2 seconds
Actual result
=============
the actual result is the
Environment
===========
1. Exact version of OpenStack you are running. See the following
list for all releases: http://docs.openstack.org/releases/
[root@controller ~]# rpm -qa | grep nova
openstack-nova-console-16.1.4-1.el7.noarch
openstack-nova-common-16.1.4-1.el7.noarch
python-nova-16.1.4-1.el7.noarch
openstack-nova-conductor-16.1.4-1.el7.noarch
openstack-nova-api-16.1.4-1.el7.noarch
openstack-nova-placement-api-16.1.4-1.el7.noarch
openstack-nova-novncproxy-16.1.4-1.el7.noarch
python2-novaclient-9.1.2-1.el7.noarch
openstack-nova-scheduler-16.1.4-1.el7.noarch
2. Which hypervisor did you use?
Libvirt + KVM
What's the version of that?
[root@controller ~]# rpm -qa | grep qemu
centos-release-qemu-ev-1.0-3.el7.centos.noarch
2. Which storage type did you use?
Did not use install storage service.
3. Which networking type did you use?
Neutron with LinuxBridge.
Logs & Configs
==============
the log of nova-api:
2018-08-21 03:15:36.775 150170 DEBUG nova.osapi_compute.wsgi.server [req-affc6fdb-ff53-433f-8769-3bf02e9c26a1 - - - - -] (150170) accepted ('10.19.7.111', 42430) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:883
2018-08-21 03:15:37.618 150170 INFO nova.osapi_compute.wsgi.server [req-d73e45c5-ca4e-4b19-b079-953d476d682c 5e742936c606450a9d241503df027cba 819544d7df22453abce480d85f7f8429 - default default] 10.19.7.111 "GET /v2.1 HTTP/1.1" status: 302 len: 313 time: 0.8419631
2018-08-21 03:15:37.624 150170 DEBUG nova.api.openstack.wsgi [req-fea2da59-3777-493a-9fba-dd8b3dd3db3b 5e742936c606450a9d241503df027cba 819544d7df22453abce480d85f7f8429 - default default] Calling method '<bound method VersionsController.show of <nova.api.openstack.compute.versionsV21.VersionsController object at 0x7c07810>>' _process_stack /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:612
2018-08-21 03:15:37.625 150170 INFO nova.osapi_compute.wsgi.server [req-fea2da59-3777-493a-9fba-dd8b3dd3db3b 5e742936c606450a9d241503df027cba 819544d7df22453abce480d85f7f8429 - default default] 10.19.7.111 "GET /v2.1/ HTTP/1.1" status: 200 len: 784 time: 0.0055721
2018-08-21 03:15:37.720 150170 DEBUG nova.api.openstack.wsgi [req-4cb31238-8962-4e50-8688-23c40ee3a762 5e742936c606450a9d241503df027cba 819544d7df22453abce480d85f7f8429 - default default] Calling method '<bound method ServersController.detail of <nova.api.openstack.compute.servers.ServersController object at 0x81fb650>>' _process_stack /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:612
2018-08-21 03:15:37.724 150170 DEBUG nova.compute.api [req-4cb31238-8962-4e50-8688-23c40ee3a762 5e742936c606450a9d241503df027cba 819544d7df22453abce480d85f7f8429 - default default] Searching by: {'deleted': False, 'project_id': u'819544d7df22453abce480d85f7f8429'} get_all /usr/lib/python2.7/site-packages/nova/compute/api.py:2356
2018-08-21 03:15:37.735 150170 DEBUG oslo_db.sqlalchemy.engines [req-4cb31238-8962-4e50-8688-23c40ee3a762 5e742936c606450a9d241503df027cba 819544d7df22453abce480d85f7f8429 - default default] MySQL server mode set to STRICT_TRANS_TABLES,STRICT_ALL_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,TRADITIONAL,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION _check_effective_sql_mode /usr/lib/python2.7/site-packages/oslo_db/sqlalchemy/engines.py:285
2018-08-21 03:15:37.747 150170 DEBUG oslo_concurrency.lockutils [req-4cb31238-8962-4e50-8688-23c40ee3a762 5e742936c606450a9d241503df027cba 819544d7df22453abce480d85f7f8429 - default default] Lock "00000000-0000-0000-0000-000000000000" acquired by "nova.context.get_or_set_cached_cell_and_set_connections" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:270
2018-08-21 03:15:37.748 150170 DEBUG oslo_concurrency.lockutils [req-4cb31238-8962-4e50-8688-23c40ee3a762 5e742936c606450a9d241503df027cba 819544d7df22453abce480d85f7f8429 - default default] Lock "00000000-0000-0000-0000-000000000000" released by "nova.context.get_or_set_cached_cell_and_set_connections" :: held 0.001s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:282
2018-08-21 03:16:07.762 150170 DEBUG oslo_db.sqlalchemy.engines [req-4cb31238-8962-4e50-8688-23c40ee3a762 5e742936c606450a9d241503df027cba 819544d7df22453abce480d85f7f8429 - default default] MySQL server mode set to STRICT_TRANS_TABLES,STRICT_ALL_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,TRADITIONAL,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION _check_effective_sql_mode /usr/lib/python2.7/site-packages/oslo_db/sqlalchemy/engines.py:285
2018-08-21 03:16:07.839 150170 DEBUG nova.compute.api [req-4cb31238-8962-4e50-8688-23c40ee3a762 5e742936c606450a9d241503df027cba 819544d7df22453abce480d85f7f8429 - default default] Found 2 cells: 00000000-0000-0000-0000-000000000000(cell0),49ff5a02-af70-40b3-9202-8ae83f3bd17f(cell1) load_cells /usr/lib/python2.7/site-packages/nova/compute/api.py:236
2018-08-21 03:16:07.839 150170 DEBUG nova.compute.api [req-4cb31238-8962-4e50-8688-23c40ee3a762 5e742936c606450a9d241503df027cba 819544d7df22453abce480d85f7f8429 - default default] Skipping already-collected cell0 list _get_instances_by_filters_all_cells /usr/lib/python2.7/site-packages/nova/compute/api.py:2556
2018-08-21 03:16:07.840 150170 DEBUG nova.compute.api [req-4cb31238-8962-4e50-8688-23c40ee3a762 5e742936c606450a9d241503df027cba 819544d7df22453abce480d85f7f8429 - default default] Listing 1000 instances in cell 49ff5a02-af70-40b3-9202-8ae83f3bd17f(cell1) _get_instances_by_filters_all_cells /usr/lib/python2.7/site-packages/nova/compute/api.py:2559
2018-08-21 03:16:07.841 150170 DEBUG oslo_concurrency.lockutils [req-4cb31238-8962-4e50-8688-23c40ee3a762 5e742936c606450a9d241503df027cba 819544d7df22453abce480d85f7f8429 - default default] Lock "49ff5a02-af70-40b3-9202-8ae83f3bd17f" acquired by "nova.context.get_or_set_cached_cell_and_set_connections" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:270
2018-08-21 03:16:07.843 150170 DEBUG oslo_concurrency.lockutils [req-4cb31238-8962-4e50-8688-23c40ee3a762 5e742936c606450a9d241503df027cba 819544d7df22453abce480d85f7f8429 - default default] Lock "49ff5a02-af70-40b3-9202-8ae83f3bd17f" released by "nova.context.get_or_set_cached_cell_and_set_connections" :: held 0.002s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:282
2018-08-21 03:16:37.857 150170 DEBUG oslo_db.sqlalchemy.engines [req-4cb31238-8962-4e50-8688-23c40ee3a762 5e742936c606450a9d241503df027cba 819544d7df22453abce480d85f7f8429 - default default] MySQL server mode set to STRICT_TRANS_TABLES,STRICT_ALL_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,TRADITIONAL,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION _check_effective_sql_mode /usr/lib/python2.7/site-packages/oslo_db/sqlalchemy/engines.py:285
2018-08-21 03:16:38.178 150170 DEBUG oslo_concurrency.lockutils [req-4cb31238-8962-4e50-8688-23c40ee3a762 5e742936c606450a9d241503df027cba 819544d7df22453abce480d85f7f8429 - default default] Lock "49ff5a02-af70-40b3-9202-8ae83f3bd17f" acquired by "nova.context.get_or_set_cached_cell_and_set_connections" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:270
2018-08-21 03:16:38.179 150170 DEBUG oslo_concurrency.lockutils [req-4cb31238-8962-4e50-8688-23c40ee3a762 5e742936c606450a9d241503df027cba 819544d7df22453abce480d85f7f8429 - default default] Lock "49ff5a02-af70-40b3-9202-8ae83f3bd17f" released by "nova.context.get_or_set_cached_cell_and_set_connections" :: held 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:282
2018-08-21 03:16:38.192 150170 DEBUG nova.policy [req-4cb31238-8962-4e50-8688-23c40ee3a762 5e742936c606450a9d241503df027cba 819544d7df22453abce480d85f7f8429 - default default] Policy check for os_compute_api:os-hide-server-addresses failed with credentials {'service_roles': [], 'user_id': u'5e742936c606450a9d241503df027cba', 'roles': [u'admin'], 'user_domain_id': u'default', 'service_project_id': None, 'service_user_id': None, 'service_user_domain_id': None, 'service_project_domain_id': None, 'is_admin_project': True, 'is_admin': True, 'project_id': u'819544d7df22453abce480d85f7f8429', 'project_domain_id': u'default'} authorize /usr/lib/python2.7/site-packages/nova/policy.py:168
2018-08-21 03:16:38.958 150170 INFO nova.osapi_compute.wsgi.server [req-4cb31238-8962-4e50-8688-23c40ee3a762 5e742936c606450a9d241503df027cba 819544d7df22453abce480d85f7f8429 - default default] 10.19.7.111 "GET /v2.1/servers/detail HTTP/1.1" status: 200 len: 24851 time: 61.2431269
To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1788149/+subscriptions
References
