<div dir="ltr">Thanks for doing this. I dug into the <span style="font-size:12.8px">test_</span><span style="font-size:12.8px">volume_boot_pattern test to see what was going on. </span><div><span style="font-size:12.8px"><br></span></div><div><span style="font-size:12.8px">On the first boot, Nova called Neutron to create a port at 23:29:44 and it took 441ms to return the port to Nova.[1]</span></div><div><span style="font-size:12.8px">Nova then plugged the interface for that port into OVS a little over 6 seconds later at 23:29:50.[2]</span></div><div><span style="font-size:12.8px">The Neutron agent attempted to process this on the iteration at 23:29:52 [3]; however, it didn't get the ofport populated from the OVSDB monitor... a bug![4] </span><span style="font-size:12.8px">The Neutron agent did catch it on the next iteration two seconds later on a retry and notified the Neutron server at 23:29:54.[5]</span></div><div><span style="font-size:12.8px">The Neutron server processed the port ACTIVE change in just under 80ms[6], but it did not dispatch the notification to Nova until 2 seconds later at 23:29:56 [7] due to the Nova notification batching mechanism[8].</span></div><div><span style="font-size:12.8px"><br></span></div><div><span style="font-size:12.8px">Total time between port create and boot is about 12 seconds. 6 in Nova and 6 in Neutron.</span></div><div><span style="font-size:12.8px"><br></span></div><div><span style="font-size:12.8px">For the Neutron side, the bug fix should eliminate 2 seconds. We could probably make the Nova notifier batching mechanism a little more aggressive so it only batches up calls in a very short interval rather than making 2 second buckets at all times. The remaining 2 seconds is just the agent processing loop interval, which can be tuned with a config but it should be okay if that's the only bottleneck.</span></div><div><span style="font-size:12.8px"><br></span></div><div><span style="font-size:12.8px">For Nova, we need to improve that 6 seconds after it has created the Neutron port before it has plugged it into the vswitch. I can see it makes some other calls to Neutron in this time to list security groups and floating IPs. Maybe this can be done asynchronously because I don't think they should block the initial VM boot to pause that plugs in the VIF.</span></div><div><span style="font-size:12.8px"><br></span></div><div><span style="font-size:12.8px">Completely unrelated to the boot process, the entire tempest run spent ~412 seconds building and destroying Neutron resources </span><span style="font-size:12.8px">in setup and teardown</span><span style="font-size:12.8px">.[9] However, considering the number of tests executed, this seems reasonable so I'm not sure we need to work on optimizing that yet.</span><br></div><div><span style="font-size:12.8px"><br></span></div><div><span style="font-size:12.8px"><br></span></div><div><span style="font-size:12.8px">Cheers,</span></div><div><span style="font-size:12.8px">Kevin Benton</span></div><div><span style="font-size:12.8px"><br></span></div><div><br></div><div><span style="font-size:12.8px">1. <a href="http://logs.openstack.org/87/295487/1/check/gate-tempest-dsvm-neutron-full/5022853/logs/screen-q-svc.txt.gz#_2016-03-21_23_29_45_341">http://logs.openstack.org/87/295487/1/check/gate-tempest-dsvm-neutron-full/5022853/logs/screen-q-svc.txt.gz#_2016-03-21_23_29_45_341</a></span></div><div><span style="font-size:12.8px">2. <a href="http://logs.openstack.org/87/295487/1/check/gate-tempest-dsvm-neutron-full/5022853/logs/screen-n-cpu.txt.gz#_2016-03-21_23_29_50_629">http://logs.openstack.org/87/295487/1/check/gate-tempest-dsvm-neutron-full/5022853/logs/screen-n-cpu.txt.gz#_2016-03-21_23_29_50_629</a></span></div><div><span style="font-size:12.8px">3. <a href="http://logs.openstack.org/87/295487/1/check/gate-tempest-dsvm-neutron-full/5022853/logs/screen-q-agt.txt.gz#_2016-03-21_23_29_52_216">http://logs.openstack.org/87/295487/1/check/gate-tempest-dsvm-neutron-full/5022853/logs/screen-q-agt.txt.gz#_2016-03-21_23_29_52_216</a></span></div><div><span style="font-size:12.8px">4. <a href="https://bugs.launchpad.net/neutron/+bug/1560464">https://bugs.launchpad.net/neutron/+bug/1560464</a></span></div><div><span style="font-size:12.8px">5. <a href="http://logs.openstack.org/87/295487/1/check/gate-tempest-dsvm-neutron-full/5022853/logs/screen-q-agt.txt.gz#_2016-03-21_23_29_54_738">http://logs.openstack.org/87/295487/1/check/gate-tempest-dsvm-neutron-full/5022853/logs/screen-q-agt.txt.gz#_2016-03-21_23_29_54_738</a></span></div><div><span style="font-size:12.8px">6. <a href="http://logs.openstack.org/87/295487/1/check/gate-tempest-dsvm-neutron-full/5022853/logs/screen-q-svc.txt.gz#_2016-03-21_23_29_54_813">http://logs.openstack.org/87/295487/1/check/gate-tempest-dsvm-neutron-full/5022853/logs/screen-q-svc.txt.gz#_2016-03-21_23_29_54_813</a></span></div><div><span style="font-size:12.8px">7. <a href="http://logs.openstack.org/87/295487/1/check/gate-tempest-dsvm-neutron-full/5022853/logs/screen-q-svc.txt.gz#_2016-03-21_23_29_56_782">http://logs.openstack.org/87/295487/1/check/gate-tempest-dsvm-neutron-full/5022853/logs/screen-q-svc.txt.gz#_2016-03-21_23_29_56_782</a></span></div><div><span style="font-size:12.8px">8. <a href="http://git.openstack.org/cgit/openstack/neutron/tree/neutron/notifiers/nova.py">http://git.openstack.org/cgit/openstack/neutron/tree/neutron/notifiers/nova.py</a></span></div><div><span style="font-size:12.8px">9. egrep -R 'tearDown|setUp' tempest.txt.gz | grep 9696 | awk '{print $(NF)}' | ./fsum</span></div></div><div class="gmail_extra"><br><div class="gmail_quote">On Mon, Mar 21, 2016 at 5:09 PM, Clark Boylan <span dir="ltr"><<a href="mailto:cboylan@sapwetik.org" target="_blank">cboylan@sapwetik.org</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div class="HOEnZb"><div class="h5">On Mon, Mar 21, 2016, at 01:23 PM, Sean Dague wrote:<br>
> On 03/21/2016 04:09 PM, Clark Boylan wrote:<br>
> > On Mon, Mar 21, 2016, at 11:49 AM, Clark Boylan wrote:<br>
> >> On Mon, Mar 21, 2016, at 11:08 AM, Clark Boylan wrote:<br>
> >>> On Mon, Mar 21, 2016, at 09:32 AM, Armando M. wrote:<br>
> >>>> Do you have an a better insight of job runtimes vs jobs in other<br>
> >>>> projects?<br>
> >>>> Most of the time in the job runtime is actually spent setting the<br>
> >>>> infrastructure up, and I am not sure we can do anything about it, unless<br>
> >>>> we<br>
> >>>> take this with Infra.<br>
> >>><br>
> >>> I haven't done a comparison yet buts lets break down the runtime of a<br>
> >>> recent successful neutron full run against neutron master [0].<br>
> >><br>
> >> And now for some comparative data from the gate-tempest-dsvm-full job<br>
> >> [0]. This job also ran against a master change that merged and ran in<br>
> >> the same cloud and region as the neutron job.<br>
> >><br>
> > snip<br>
> >> Generally each step of this job was quicker. There were big differences<br>
> >> in devstack and tempest run time though. Is devstack much slower to<br>
> >> setup neutron when compared to nova net? For tempest it looks like we<br>
> >> run ~1510 tests against neutron and only ~1269 against nova net. This<br>
> >> may account for the large difference there. I also recall that we run<br>
> >> ipv6 tempest tests against neutron deployments that were inefficient and<br>
> >> booted 2 qemu VMs per test (not sure if that is still the case but<br>
> >> illustrates that the tests themselves may not be very quick in the<br>
> >> neutron case).<br>
> ><br>
> > Looking at the tempest slowest tests output for each of these jobs<br>
> > (neutron and nova net) some tests line up really well across jobs and<br>
> > others do not. In order to get a better handle on the runtime for<br>
> > individual tests I have pushed <a href="https://review.openstack.org/295487" rel="noreferrer" target="_blank">https://review.openstack.org/295487</a> which<br>
> > will run tempest serially reducing the competition for resources between<br>
> > tests.<br>
> ><br>
> > Hopefully the subunit logs generated by this change can provide more<br>
> > insight into where we are losing time during the tempest test runs.<br>
<br>
</div></div>The results are in, we have gate-tempest-dsvm-full [0] and<br>
gate-tempest-dsvm-neutron-full [1] job results where tempest ran<br>
serially to reduce resource contention and provide accurateish per test<br>
timing data. Both of these jobs ran on the same cloud so should have<br>
comparable performance from the underlying VMs.<br>
<br>
gate-tempest-dsvm-full<br>
Time spent in job before tempest: 700 seconds<br>
Time spent running tempest: 2428<br>
Tempest tests run: 1269 (113 skipped)<br>
<br>
gate-tempest-dsvm-neutron-full<br>
Time spent in job before tempest: 789 seconds<br>
Time spent running tempest: 4407 seconds<br>
Tempest tests run: 1510 (76 skipped)<br>
<br>
All times above are wall time as recorded by Jenkins.<br>
<br>
We can also compare the 10 slowest tests in the non neutron job against<br>
their runtimes in the neutron job. (note this isn't a list of the top 10<br>
slowest tests in the neutron job because that job runs extra tests).<br>
<br>
nova net job<br>
tempest.scenario.test_volume_boot_pattern.TestVolumeBootPatternV2.test_volume_boot_pattern<br>
85.232<br>
tempest.scenario.test_volume_boot_pattern.TestVolumeBootPattern.test_volume_boot_pattern<br>
83.319<br>
tempest.scenario.test_shelve_instance.TestShelveInstance.test_shelve_volume_backed_instance<br>
50.338<br>
tempest.scenario.test_snapshot_pattern.TestSnapshotPattern.test_snapshot_pattern<br>
43.494<br>
tempest.scenario.test_minimum_basic.TestMinimumBasicScenario.test_minimum_basic_scenario<br>
40.225<br>
tempest.scenario.test_shelve_instance.TestShelveInstance.test_shelve_instance<br>
39.653<br>
tempest.api.volume.admin.test_volumes_backup.VolumesBackupsV1Test.test_volume_backup_create_get_detailed_list_restore_delete<br>
37.720<br>
tempest.api.volume.admin.test_volumes_backup.VolumesBackupsV2Test.test_volume_backup_create_get_detailed_list_restore_delete<br>
36.355<br>
tempest.api.compute.servers.test_server_actions.ServerActionsTestJSON.test_resize_server_confirm_from_stopped<br>
27.375<br>
tempest.scenario.test_encrypted_cinder_volumes.TestEncryptedCinderVolumes.test_encrypted_cinder_volumes_luks<br>
27.025<br>
<br>
neutron job<br>
tempest.scenario.test_volume_boot_pattern.TestVolumeBootPatternV2.test_volume_boot_pattern<br>
110.345<br>
tempest.scenario.test_volume_boot_pattern.TestVolumeBootPattern.test_volume_boot_pattern<br>
108.170<br>
tempest.scenario.test_shelve_instance.TestShelveInstance.test_shelve_volume_backed_instance<br>
63.852<br>
tempest.scenario.test_shelve_instance.TestShelveInstance.test_shelve_instance<br>
59.931<br>
tempest.scenario.test_snapshot_pattern.TestSnapshotPattern.test_snapshot_pattern<br>
57.835<br>
tempest.scenario.test_minimum_basic.TestMinimumBasicScenario.test_minimum_basic_scenario<br>
49.552<br>
tempest.api.volume.admin.test_volumes_backup.VolumesBackupsV1Test.test_volume_backup_create_get_detailed_list_restore_delete<br>
40.378<br>
tempest.api.volume.admin.test_volumes_backup.VolumesBackupsV2Test.test_volume_backup_create_get_detailed_list_restore_delete<br>
39.088<br>
tempest.scenario.test_encrypted_cinder_volumes.TestEncryptedCinderVolumes.test_encrypted_cinder_volumes_luks<br>
35.645<br>
tempest.api.compute.servers.test_server_actions.ServerActionsTestJSON.test_resize_server_confirm_from_stopped<br>
30.551<br>
<span class=""><br>
> Subunit logs aren't the full story here. Activity in addCleanup doesn't<br>
> get added to the subunit time accounting for the test, which causes some<br>
> interesting issues when waiting for resources to delete. I would be<br>
> especially cautious of that on some of these.<br>
<br>
</span>Based on this those numbers above may not tell the whole story but they<br>
do seem to tell us that in comparable circumstances neutron is slower<br>
than nova net. Now the sample size is tiny, but again it gives us<br>
somewhere to start. What is boot from volume doing in the neutron case<br>
that makes it so much slower? Why is shelving so much slower with<br>
neutron? and so on.<br>
<br>
A few seconds here and a few seconds there adds up when these operations<br>
are repeated a few hundred times. We can probably start to whittle the<br>
job runtime down by shaving that extra time off. In any case I think<br>
this is about as far as I can pull this thread, and will let the neutron<br>
team take it from here.<br>
<br>
[0]<br>
<a href="http://logs.openstack.org/87/295487/1/check/gate-tempest-dsvm-full/8e64615/console.html" rel="noreferrer" target="_blank">http://logs.openstack.org/87/295487/1/check/gate-tempest-dsvm-full/8e64615/console.html</a><br>
[1]<br>
<a href="http://logs.openstack.org/87/295487/1/check/gate-tempest-dsvm-neutron-full/5022853/console.html" rel="noreferrer" target="_blank">http://logs.openstack.org/87/295487/1/check/gate-tempest-dsvm-neutron-full/5022853/console.html</a><br>
<div class="HOEnZb"><div class="h5"><br>
__________________________________________________________________________<br>
OpenStack Development Mailing List (not for usage questions)<br>
Unsubscribe: <a href="http://OpenStack-dev-request@lists.openstack.org?subject:unsubscribe" rel="noreferrer" target="_blank">OpenStack-dev-request@lists.openstack.org?subject:unsubscribe</a><br>
<a href="http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev" rel="noreferrer" target="_blank">http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev</a><br>
</div></div></blockquote></div><br></div>