Hi All,<div><br></div><div>tl;dr Nova REST calls take more then 1 second about 5% of the time, with some calls taking upwards of 2 seconds on average in small scale testing (and much worse in production). Lets fix this.</div>
<div><br></div><div><br></div><div><br></div><div>After noticing slow nova REST API performance in devstack, I dug a bit further.</div>
<div><br>Log sources</div><div><div>=========</div><div><a href="http://jenkins.openstack.org" target="_blank">jenkins.openstack.org</a> runs several periodic tempest tests with logs saved to <a href="http://logs.openstack.org" target="_blank">logs.openstack.org</a></div>
<div><br></div><a href="http://logs.openstack.org/periodic/periodic-tempest-devstack-vm-check-hourly/" target="_blank">http://logs.openstack.org/periodic/periodic-tempest-devstack-vm-check-hourly/</a><br>
<a href="http://logs.openstack.org/periodic/periodic-tempest-devstack-vm-full/" target="_blank">http://logs.openstack.org/periodic/periodic-tempest-devstack-vm-full/</a><div><br></div><div><br></div><div>Percent REST calls slower than 1 second</div>
<div>
<div>===============================</div></div><div>periodic-tempest-devstack-vm-check-hourly: 5.9%</div><div>periodic-tempest-devstack-vm-full: 4.4%</div><div><br></div><div><br></div><div>Average REST call time</div><div>
==================</div>
<div>periodic-tempest-devstack-vm-check-hourl:y 0.420115 seconds<br></div><div>periodic-tempest-devstack-vm-full: 0.339301 seconds</div><div><br></div><div><br></div><div>Fastest call (min, average)</div><div>====================</div>
<div>
/2009-04-04/meta-data/*: 0.0005190 0.099357 seconds</div><div><br></div><div>Excluding meta-data calls the fastest seen calls take about 0.05 seconds. So we see the problem isn't WSGI.</div><div><br></div><div><br>
</div><div>Slow REST Calls by average (from 37 recent runs of periodic-tempest-devstack-vm-check-hourly)</div>
<div>=======================================================================</div>
<div><br></div><div> format: [Average-time username REST CALL]</div><div> the username is included to provide more context about what the rest call is actually doing by making it easy find in the log files.</div>
<div><br><div>0.765313 demo GET /v2/UUID/images/UUID2</div><div>0.892474 ImagesMetadataTest-user GET /v2/UUID/images/UUID2</div><div>0.939789 ListImageFiltersTest-user GET /v2/UUID/images/UUID2</div>
<div>0.946835 AuthorizationTest-user GET /v2/UUID/images/UUID2</div><div>1.32859 ListImageFiltersTest-user DELETE /v2/UUID/images/UUID2</div><div>1.39626 ListImageFiltersTest-user POST /v2/UUID/servers/UUID2/action</div>
<div>
1.5389 ImagesMetadataTest-user PUT /v2/UUID/images/UUID2/metadata</div><div>1.79531 ServerActionsTestXML-user POST /v2/UUID/servers/UUID2/action</div><div>1.80866 ServerActionsTestJSON-user POST /v2/UUID/servers/UUID2/action</div>
<div>2.05908 FloatingIPsTestXML-user POST /v2/UUID/servers/UUID2/action</div><div>2.11384 FloatingIPsTestJSON-user POST /v2/UUID/servers/UUID2/action</div><div>2.20237 demo POST /v2/UUID/servers</div><div>2.23645 ServersTestJSON-user POST /v2/UUID/servers</div>
<div>2.23917 ServersTestXML-user POST /v2/UUID/servers</div><div>2.26852 ListServersNegativeTest-user POST /v2/UUID/servers</div><div>2.35584 VolumesActionsTest-user POST /v2/UUID/servers</div><div>2.37725 ServerActionsTestJSON-user POST /v2/UUID/servers</div>
<div>2.39885 ServerActionsTestXML-user POST /v2/UUID/servers</div><div>2.9973 TestServerDiskConfig-user POST /v2/UUID/servers/UUID2/action</div></div></div><div><br></div><div>Further analysis</div><div>=============</div>
<div>source: <a href="http://logs.openstack.org/periodic/periodic-tempest-devstack-vm-check-hourly/1222/logs/screen-n-api.txt.gz" target="_blank">http://logs.openstack.org/periodic/periodic-tempest-devstack-vm-check-hourly/1222/logs/screen-n-api.txt.gz</a> </div>
<div>Test: TestServerDiskConfig-user POST /v2/UUID/servers/UUID2/action</div><div>action: Rebuilding instance</div><div><br></div><div>request IDs: </div><div>req-d9c61f7e-78ac-4412-8956-a35189a49fa6 <br></div><div>req-6ec84648-5a9e-4a4f-b4e8-b4ebff73f8f7<br>
</div><div><div>req-19bac8ca-3cae-4b8f-be68-6d045fdb8aa7</div></div><div>req-f4e2be63-03b0-47e3-8e41-04828227547f<br></div><div> nova-api 00:53:52 receive REST call</div><div> nova-api 00:53:55 cast to compute </div>
<div> nova-cpu 00:53:55 receive call</div>
<div> nova-cpu 00:53:55 respond</div><div><br></div><div>Most of the time appears to be spent in nova.compute.api:rebuild (line 1528)</div><div><br></div><div><br></div><div>Local test: FloatingIPsTestXML-user POST /v2/UUID/servers/UUID2/action </div>
<div>=======================================================</div><div><br></div><div>With logging of nova.db.api call times added</div><div><br></div><div>Total time: 3.117 seconds</div><div><br></div><div>Logs:</div><div>
nova-api 00:31:01 REST call received <br></div><div>nova-api 00:31:01 nova.db.api.instance_get_by_uuid 0.12 sec<br></div><div>nova-api 00:31:01 nova.db.api.instance_info_cache_update 0.01 sec</div><div><br></div><div>nova-net 00:31:02 nova.db.api.floating_ip_get_by_address 0.00 sec</div>
<div>nova-net 00:31:02 nova.db.api.fixed_ip_get_by_address 0.08 sec</div><div>nova-net 00:31:02 nova.db.api.network_get 0.01 sec<br></div><div>nova-net 00:31:02 nova.db.api.floating_ip_fixed_ip_associate 0.08 sec </div><div>
nova-net 00:31:04 nova.db.api.instance_get_by_uuid' 0.23 sec </div><div>nova-net 00:31:04 nova.db.api.virtual_interface_get_by_instance' 0.23 sec</div><div><div>nova-net 00:31:04 nova.db.api.network_get' 0.01 sec</div>
<div>nova-net 00:31:04 nova.db.api.network_get_by_uuid' 0.02 sec</div><div>nova-net 00:31:04 nova.db.api.virtual_interface_get_by_uuid' 0.00 sec</div><div>nova-net 00:31:04 nova.db.api.fixed_ips_by_virtual_interface' 0.00 sec</div>
<div>nova-net 00:31:04 nova.db.api.network_get_by_uuid' 0.01 sec</div><div>nova-net 00:31:04 nova.db.api.virtual_interface_get_by_uuid' 0.02 sec</div><div>nova-net 00:31:04 nova.db.api.floating_ip_get_by_fixed_address' 0.02 sec</div>
</div><div><br></div><div>total nova.db.api time: 0.84 seconds over 15 calls </div><div>nova.db.api takes up 26.9 % of call time</div><div><br></div><div>Other time appears to be in rootwrap for iptables.</div><div><br>
</div><div>Conclusion</div><div>=========</div><div><br></div><div>Nova REST calls take way long, even in small scale devstack/tempest testing. We should spend resources on fixing this for Grizzly. I would like to start a dialog on how we can fix this and see if anyone wants to volunteer help. Below are a few possible ideas of things that will help us make the REST calls faster.</div>
<div><br></div><div>* Continuously track REST API times of devstack/tempest jobs, to identify slow API calls and watch for trends. (logstash + statsd?)<br></div><div>* Identify the underlying cause of the slow performance. It looks like nova.db.api may be partially responsible, but not the only issue? What else is a bottleneck?</div>
<div>* Enable millisecond level time logging <a href="https://review.openstack.org/#/c/18933/" target="_blank">https://review.openstack.org/#/c/18933/</a></div><div>* Add an option in devstack to enable python profiling? Whats best way to do this?</div>
<div>* Make more REST API related code asynchronous (via RPC)</div><div><br></div><div><br></div><div>best,</div><div>Joe Gordon</div>