settingsLogin | Registersettings

[openstack-dev] [neutron] Some findings while profiling instances boot

0 votes

Hi there,

We're trying to figure out why, sometimes, rpc_loop takes over 10 seconds
to process an iteration when booting instances. So we deployed devstack on
a 8GB, 4vCPU VM and did some profiling on the following command:

nova boot --flavor m1.nano --image cirros-0.3.4-x86_64-uec --nic
net-name=private --min-count 8 instance

(network private has portsecurityenabled set to False to avoid the
overhead of setting up sgs)

Logs showed that sometimes, the network-vif-plugged event was sent by the
server ~12 seconds after the vif was detected by ovsdb monitor. Usually,
first and second events come faster while the rest take longer. Further
analysis showed that rpc_loop iterations take several seconds to complete
so, if the vif is detected while iteration X is running, it won't be
processed until iteration X+1.

As an example, I've attached a simplified sequence diagram [0] to show what
happened in a particular iteration of my debug (I have full logs and pstat
files for this session for those interested). In this example, iteration 76
is going to process two ports while some of the previous spawned machines
are being managed by libvirt and so on... At the beginning of iteration 76,
a new vif is detected by ovsdb monitor but it won't be processed until 12
seconds later in iteration 77.

Profiling files show that aggregated CPU time for neutron workers is 97
seconds, while CPU time for ovs agent is 2.1 seconds. Most of its time is
spent waiting for RPC so it looks like there's apparently some room for
optimization and multiprocessing here.

According to dstat.log, CPU is at ~90% and there's ~1GB of free RAM. I
can't tell whether the hypervisor was swapping or not since I didn't have
access to it.

----system---- ----total-cpu-usage---- ------memory-usage----- -net/total->
time |usr sys idl wai hiq siq| used buff cach free| recv send>
05-02 14:22:50| 89 11 0 0 0 0|5553M 0 1151M 1119M|1808B 1462B>
05-02 14:22:51| 90 10 0 0 0 0|5567M 0 1151M 1106M|1588B 836B>
05-02 14:22:52| 89 11 1 0 0 0|5581M 0 1151M 1092M|3233B 2346B>
05-02 14:22:53| 89 10 0 0 0 0|5598M 0 1151M 1075M|2676B 2038B>
05-02 14:22:54| 90 10 0 0 0 0|5600M 0 1151M 1073M| 20k 14k>
05-02 14:22:55| 90 9 0 0 0 0|5601M 0 1151M 1072M| 22k 16k>

Also, while having a look at server profiling, around the 33% of the time
was spent building SQL queries [1]. Mike Bayer went through this and
suggested having a look at baked queries and also submitted a sketch of his
proposal [2].

I wanted to share these findings with you (probably most of you knew but
I'm quite new to OpenStack so It's been a really nice exercise for me to
better understand how things work) and gather your feedback about how
things can be improved. Also, I'll be happy to share the results and
discuss further if you think it's worth during the PTG next week.

Thanks a lot for reading and apologies for such a long email!

Cheers,
Daniel
IRC: dalvarez

[0] http://imgur.com/WQqaiYQ
[1] http://imgur.com/6KrfJUC
[2] https://review.openstack.org/430973


OpenStack Development Mailing List (not for usage questions)
Unsubscribe: OpenStack-dev-request@lists.openstack.org?subject:unsubscribe
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev
asked Feb 23, 2017 in openstack-dev by Daniel_Alvarez_Sanch (380 points)   1 1

8 Responses

0 votes

On 02/15/2017 12:46 PM, Daniel Alvarez Sanchez wrote:
Hi there,

We're trying to figure out why, sometimes, rpc_loop takes over 10
seconds to process an iteration when booting instances. So we deployed
devstack on a 8GB, 4vCPU VM and did some profiling on the following command:

nova boot --flavor m1.nano --image cirros-0.3.4-x86_64-uec --nic
net-name=private --min-count 8 instance

Hi Daniel, thanks for posting the information here. Quick request of
you, though... can you try re-running the test but doing 8 separate
calls to nova boot instead of using the --min-count 8 parameter? I'm
curious to see if you notice any difference in contention/performance.

Best,
-jay


OpenStack Development Mailing List (not for usage questions)
Unsubscribe: OpenStack-dev-request@lists.openstack.org?subject:unsubscribe
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev
responded Feb 15, 2017 by Jay_Pipes (59,760 points)   3 10 13
0 votes

Thanks for the stats and the nice diagram. I did some profiling and I'm
sure it's the RPC handler on the Neutron server-side behaving like garbage.

There are several causes that I have a string of patches up to address that
mainly stem from the fact that l2pop requires multiple port status updates
to function correctly:

The top two accounted for more than 60% of the overhead in my profiling and
they are pretty simple, so we may be able to get them into Ocata for RC
depending on how other cores feel. If not, they should be good candidates
for back-porting later. Some of the others start to get more invasive so we
may be stuck.

Cheers,
Kevin Benton

On Wed, Feb 15, 2017 at 12:25 PM, Jay Pipes jaypipes@gmail.com wrote:

On 02/15/2017 12:46 PM, Daniel Alvarez Sanchez wrote:

Hi there,

We're trying to figure out why, sometimes, rpc_loop takes over 10
seconds to process an iteration when booting instances. So we deployed
devstack on a 8GB, 4vCPU VM and did some profiling on the following
command:

nova boot --flavor m1.nano --image cirros-0.3.4-x86_64-uec --nic
net-name=private --min-count 8 instance

Hi Daniel, thanks for posting the information here. Quick request of you,
though... can you try re-running the test but doing 8 separate calls to
nova boot instead of using the --min-count 8 parameter? I'm curious to see
if you notice any difference in contention/performance.

Best,
-jay


OpenStack Development Mailing List (not for usage questions)
Unsubscribe: OpenStack-dev-request@lists.openstack.org?subject:unsubscribe
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev


OpenStack Development Mailing List (not for usage questions)
Unsubscribe: OpenStack-dev-request@lists.openstack.org?subject:unsubscribe
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev
responded Feb 16, 2017 by kevin_at_benton.pub (15,600 points)   2 3 4
0 votes

Awesome work, Kevin!

For the DHCP notification, in my profiling I got only 10% of the CPU time
[0] without taking the waiting times into account which it's probably what
you also measured.
Your patch seems like a neat and great optimization :)

Also, since "getdevicesdetailslistandfaileddevices()" takes quite a
long time, does it make sense to trigger this request asynchronously (same
approach you took for OVO notifier) and continue executing the iteration?
This would not result in a huge improvement but, in the case I showed in
the diagram, both 'getdevicedetails' can be issued at the same time
instead of one after another and, probably, freeing the iteration for
further processing on the agent side. Thoughts on this?

Regarding, the time of SQL queries, it looks like the server spends a
significant amount of time building those and reducing that time will
result in a nice improvement. Mike's outstanding analysis looks promising
and maybe it's worth to discuss it.

[0] http://imgur.com/lDikZ0I

On Thu, Feb 16, 2017 at 8:23 AM, Kevin Benton kevin@benton.pub wrote:

Thanks for the stats and the nice diagram. I did some profiling and I'm
sure it's the RPC handler on the Neutron server-side behaving like garbage.

There are several causes that I have a string of patches up to address
that mainly stem from the fact that l2pop requires multiple port status
updates to function correctly:

  • The DHCP notifier will trigger a notification to the DHCP agents on the
    network on a port status update. This wouldn't be too problematic on it's
    own, but it does several queries for networks and segments to determine
    which agents it should talk to. Patch to address it here:
    https://review.openstack.org/#/c/434677/

  • The OVO notifier will also generate a notification on any port data
    model change, including the status. This is ultimately the desired
    behavior, but until we eliminate the frivolous status flipping, it's going
    to incur a performance hit. Patch here to put it asynced into the
    background so it doesn't block the port update process:
    https://review.openstack.org/#/c/434678/

  • A wasteful DB query in the ML2 PortContext: https://review.op
    enstack.org/#/c/434679/

  • More unnecessary queries for the status update case in the ML2
    PortContext: https://review.openstack.org/#/c/434680/

  • Bulking up the DB queries rather than retrieving port details one by
    one.
    https://review.openstack.org/#/c/434681/ https://review.open
    stack.org/#/c/434682/

The top two accounted for more than 60% of the overhead in my profiling
and they are pretty simple, so we may be able to get them into Ocata for RC
depending on how other cores feel. If not, they should be good candidates
for back-porting later. Some of the others start to get more invasive so we
may be stuck.

Cheers,
Kevin Benton

On Wed, Feb 15, 2017 at 12:25 PM, Jay Pipes jaypipes@gmail.com wrote:

On 02/15/2017 12:46 PM, Daniel Alvarez Sanchez wrote:

Hi there,

We're trying to figure out why, sometimes, rpc_loop takes over 10
seconds to process an iteration when booting instances. So we deployed
devstack on a 8GB, 4vCPU VM and did some profiling on the following
command:

nova boot --flavor m1.nano --image cirros-0.3.4-x86_64-uec --nic
net-name=private --min-count 8 instance

Hi Daniel, thanks for posting the information here. Quick request of you,
though... can you try re-running the test but doing 8 separate calls to
nova boot instead of using the --min-count 8 parameter? I'm curious to see
if you notice any difference in contention/performance.

Best,
-jay



OpenStack Development Mailing List (not for usage questions)
Unsubscribe: OpenStack-dev-request@lists.openstack.org?subject:unsubscrib
e
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev


OpenStack Development Mailing List (not for usage questions)
Unsubscribe: OpenStack-dev-request@lists.openstack.org?subject:unsubscribe
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev


OpenStack Development Mailing List (not for usage questions)
Unsubscribe: OpenStack-dev-request@lists.openstack.org?subject:unsubscribe
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev
responded Feb 16, 2017 by Daniel_Alvarez_Sanch (380 points)   1 1
0 votes

On 02/15/2017 12:46 PM, Daniel Alvarez Sanchez wrote:
Also, while having a look at server profiling, around the 33% of the
time was spent building SQL queries [1]. Mike Bayer went through this
and suggested having a look at baked queries and also submitted a sketch
of his proposal [2].

Neutron relies heavily on a big JOIN query that returns just one row.
In the profiling, it seemed like joined eager loading overhead is
significant. Someone independently opened an upstream issue at
https://bitbucket.org/zzzeek/sqlalchemy/issues/3915/performance-degradation-on-version-10xx#comment-34442856
with similar comments.

While the "baked" query thing is the ultimate hammer for "ORM SQL
building" overhead, it's a very heavy hammer to swing as folks will note
in the gerrit that shows roughly how it would look, it's involved and
not that easy to work with.

Fortunately, the joined eager load codepaths here have never been
optimized for the "many short queries" use case, and a large portion of
the overhead is all rolled up into some SQL alias objects that can be
memoized so that most of the work they do happens once, instead of
thousands of times.

In https://gerrit.sqlalchemy.org/311 (note this is SQLAlchemy's gerrit,
not openstack's) I have a patch that reduces the overhead associated
specifically with joined eager loaded entities by around 270% for a
worst-case scenario (which Neutron seems to be close to). If those
folks running the load tests can please try this revision out and see if
it makes a dent, that would be helpful.

Note that SQLAlchemy 1.1 has been out for about five months now, and
it's time that Openstack move up to 1.1 series - that's where the
performance enhancement will be.

I wanted to share these findings with you (probably most of you knew but
I'm quite new to OpenStack so It's been a really nice exercise for me to
better understand how things work) and gather your feedback about how
things can be improved. Also, I'll be happy to share the results and
discuss further if you think it's worth during the PTG next week.

Thanks a lot for reading and apologies for such a long email!

Cheers,
Daniel
IRC: dalvarez

[0] http://imgur.com/WQqaiYQ
[1] http://imgur.com/6KrfJUC
[2] https://review.openstack.org/430973


OpenStack Development Mailing List (not for usage questions)
Unsubscribe: OpenStack-dev-request@lists.openstack.org?subject:unsubscribe
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev


OpenStack Development Mailing List (not for usage questions)
Unsubscribe: OpenStack-dev-request@lists.openstack.org?subject:unsubscribe
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev
responded Feb 16, 2017 by Mike_Bayer (15,260 points)   1 5 6
0 votes

Mike, Team,

Rolling the dice here:
https://review.openstack.org/#/c/435009/

Thanks,
Dims

On Thu, Feb 16, 2017 at 11:35 AM, Mike Bayer mbayer@redhat.com wrote:

On 02/15/2017 12:46 PM, Daniel Alvarez Sanchez wrote:

Also, while having a look at server profiling, around the 33% of the
time was spent building SQL queries [1]. Mike Bayer went through this
and suggested having a look at baked queries and also submitted a sketch
of his proposal [2].

Neutron relies heavily on a big JOIN query that returns just one row. In the
profiling, it seemed like joined eager loading overhead is significant.
Someone independently opened an upstream issue at
https://bitbucket.org/zzzeek/sqlalchemy/issues/3915/performance-degradation-on-version-10xx#comment-34442856
with similar comments.

While the "baked" query thing is the ultimate hammer for "ORM SQL building"
overhead, it's a very heavy hammer to swing as folks will note in the gerrit
that shows roughly how it would look, it's involved and not that easy to
work with.

Fortunately, the joined eager load codepaths here have never been optimized
for the "many short queries" use case, and a large portion of the overhead
is all rolled up into some SQL alias objects that can be memoized so that
most of the work they do happens once, instead of thousands of times.

In https://gerrit.sqlalchemy.org/311 (note this is SQLAlchemy's gerrit, not
openstack's) I have a patch that reduces the overhead associated
specifically with joined eager loaded entities by around 270% for a
worst-case scenario (which Neutron seems to be close to). If those folks
running the load tests can please try this revision out and see if it makes
a dent, that would be helpful.

Note that SQLAlchemy 1.1 has been out for about five months now, and it's
time that Openstack move up to 1.1 series - that's where the performance
enhancement will be.

I wanted to share these findings with you (probably most of you knew but
I'm quite new to OpenStack so It's been a really nice exercise for me to
better understand how things work) and gather your feedback about how
things can be improved. Also, I'll be happy to share the results and
discuss further if you think it's worth during the PTG next week.

Thanks a lot for reading and apologies for such a long email!

Cheers,
Daniel
IRC: dalvarez

[0] http://imgur.com/WQqaiYQ
[1] http://imgur.com/6KrfJUC
[2] https://review.openstack.org/430973


OpenStack Development Mailing List (not for usage questions)
Unsubscribe: OpenStack-dev-request@lists.openstack.org?subject:unsubscribe
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev


OpenStack Development Mailing List (not for usage questions)
Unsubscribe: OpenStack-dev-request@lists.openstack.org?subject:unsubscribe
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev

--
Davanum Srinivas :: https://twitter.com/dims


OpenStack Development Mailing List (not for usage questions)
Unsubscribe: OpenStack-dev-request@lists.openstack.org?subject:unsubscribe
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev
responded Feb 16, 2017 by Davanum_Srinivas (35,920 points)   2 4 7
0 votes

We could potentially make that call async on the agent, but the agent has
very little to do without the information in the response that comes back.

As we switch over to push notifications, this method of data retrieval will
be completely gone so we probably don't want to spend much time redesigning
that workflow anyway.

The baked queries thing is interesting, I'll reply on Mike's email with
more details.

On Feb 16, 2017 7:07 AM, "Daniel Alvarez Sanchez" dalvarez@redhat.com
wrote:

Awesome work, Kevin!

For the DHCP notification, in my profiling I got only 10% of the CPU time
[0] without taking the waiting times into account which it's probably what
you also measured.
Your patch seems like a neat and great optimization :)

Also, since "getdevicesdetailslistandfaileddevices()" takes quite a
long time, does it make sense to trigger this request asynchronously (same
approach you took for OVO notifier) and continue executing the iteration?
This would not result in a huge improvement but, in the case I showed in
the diagram, both 'getdevicedetails' can be issued at the same time
instead of one after another and, probably, freeing the iteration for
further processing on the agent side. Thoughts on this?

Regarding, the time of SQL queries, it looks like the server spends a
significant amount of time building those and reducing that time will
result in a nice improvement. Mike's outstanding analysis looks promising
and maybe it's worth to discuss it.

[0] http://imgur.com/lDikZ0I

On Thu, Feb 16, 2017 at 8:23 AM, Kevin Benton kevin@benton.pub wrote:

Thanks for the stats and the nice diagram. I did some profiling and I'm
sure it's the RPC handler on the Neutron server-side behaving like garbage.

There are several causes that I have a string of patches up to address
that mainly stem from the fact that l2pop requires multiple port status
updates to function correctly:

  • The DHCP notifier will trigger a notification to the DHCP agents on the
    network on a port status update. This wouldn't be too problematic on it's
    own, but it does several queries for networks and segments to determine
    which agents it should talk to. Patch to address it here:
    https://review.openstack.org/#/c/434677/

  • The OVO notifier will also generate a notification on any port data
    model change, including the status. This is ultimately the desired
    behavior, but until we eliminate the frivolous status flipping, it's going
    to incur a performance hit. Patch here to put it asynced into the
    background so it doesn't block the port update process:
    https://review.openstack.org/#/c/434678/

  • A wasteful DB query in the ML2 PortContext: https://review.op
    enstack.org/#/c/434679/

  • More unnecessary queries for the status update case in the ML2
    PortContext: https://review.openstack.org/#/c/434680/

  • Bulking up the DB queries rather than retrieving port details one by
    one.
    https://review.openstack.org/#/c/434681/ https://review.open
    stack.org/#/c/434682/

The top two accounted for more than 60% of the overhead in my profiling
and they are pretty simple, so we may be able to get them into Ocata for RC
depending on how other cores feel. If not, they should be good candidates
for back-porting later. Some of the others start to get more invasive so we
may be stuck.

Cheers,
Kevin Benton

On Wed, Feb 15, 2017 at 12:25 PM, Jay Pipes jaypipes@gmail.com wrote:

On 02/15/2017 12:46 PM, Daniel Alvarez Sanchez wrote:

Hi there,

We're trying to figure out why, sometimes, rpc_loop takes over 10
seconds to process an iteration when booting instances. So we deployed
devstack on a 8GB, 4vCPU VM and did some profiling on the following
command:

nova boot --flavor m1.nano --image cirros-0.3.4-x86_64-uec --nic
net-name=private --min-count 8 instance

Hi Daniel, thanks for posting the information here. Quick request of
you, though... can you try re-running the test but doing 8 separate calls
to nova boot instead of using the --min-count 8 parameter? I'm curious to
see if you notice any difference in contention/performance.

Best,
-jay



OpenStack Development Mailing List (not for usage questions)
Unsubscribe: OpenStack-dev-request@lists.op
enstack.org?subject:unsubscribe
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev



OpenStack Development Mailing List (not for usage questions)
Unsubscribe: OpenStack-dev-request@lists.openstack.org?subject:unsubscrib
e
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev


OpenStack Development Mailing List (not for usage questions)
Unsubscribe: OpenStack-dev-request@lists.openstack.org?subject:unsubscribe
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev


OpenStack Development Mailing List (not for usage questions)
Unsubscribe: OpenStack-dev-request@lists.openstack.org?subject:unsubscribe
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev
responded Feb 16, 2017 by kevin_at_benton.pub (15,600 points)   2 3 4
0 votes

Note that neutron no longer relies on giant join conditions so heavily due
to explosions in result sizes with the various many to one relationships as
of about a week ago[1].

We switched to subqueries for the one to many relationships to prevent the
result size explosions, so now we issue a lot more queries for an
individual retrieval. I'm not sure if that is better or worse WRT the
sqlalchemy performance but I thought it was important to bring up before we
spend time optimizing the old way of massive joins.

The subqueries make it that much more important that we bulk up requests to
retrieve ports, etc since we now pay a higher constant query cost.

  1. https://bugs.launchpad.net/neutron/+bug/1649317

On Feb 16, 2017 8:38 AM, "Mike Bayer" mbayer@redhat.com wrote:

On 02/15/2017 12:46 PM, Daniel Alvarez Sanchez wrote:

Also, while having a look at server profiling, around the 33% of the
time was spent building SQL queries [1]. Mike Bayer went through this
and suggested having a look at baked queries and also submitted a sketch
of his proposal [2].

Neutron relies heavily on a big JOIN query that returns just one row. In
the profiling, it seemed like joined eager loading overhead is
significant. Someone independently opened an upstream issue at
https://bitbucket.org/zzzeek/sqlalchemy/issues/3915/performa
nce-degradation-on-version-10xx#comment-34442856 with similar comments.

While the "baked" query thing is the ultimate hammer for "ORM SQL
building" overhead, it's a very heavy hammer to swing as folks will note in
the gerrit that shows roughly how it would look, it's involved and not that
easy to work with.

Fortunately, the joined eager load codepaths here have never been
optimized for the "many short queries" use case, and a large portion of the
overhead is all rolled up into some SQL alias objects that can be memoized
so that most of the work they do happens once, instead of thousands of
times.

In https://gerrit.sqlalchemy.org/311 (note this is SQLAlchemy's gerrit,
not openstack's) I have a patch that reduces the overhead associated
specifically with joined eager loaded entities by around 270% for a
worst-case scenario (which Neutron seems to be close to). If those folks
running the load tests can please try this revision out and see if it makes
a dent, that would be helpful.

Note that SQLAlchemy 1.1 has been out for about five months now, and it's
time that Openstack move up to 1.1 series - that's where the performance
enhancement will be.

I wanted to share these findings with you (probably most of you knew but
I'm quite new to OpenStack so It's been a really nice exercise for me to
better understand how things work) and gather your feedback about how
things can be improved. Also, I'll be happy to share the results and
discuss further if you think it's worth during the PTG next week.

Thanks a lot for reading and apologies for such a long email!

Cheers,
Daniel
IRC: dalvarez

[0] http://imgur.com/WQqaiYQ
[1] http://imgur.com/6KrfJUC
[2] https://review.openstack.org/430973



OpenStack Development Mailing List (not for usage questions)
Unsubscribe: OpenStack-dev-request@lists.openstack.org?subject:unsubscrib
e
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev


OpenStack Development Mailing List (not for usage questions)
Unsubscribe: OpenStack-dev-request@lists.openstack.org?subject:unsubscribe
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev


OpenStack Development Mailing List (not for usage questions)
Unsubscribe: OpenStack-dev-request@lists.openstack.org?subject:unsubscribe
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev
responded Feb 16, 2017 by kevin_at_benton.pub (15,600 points)   2 3 4
0 votes

We're planning to come up with some solution regarding neutron profiling.
For this purpose etherpad [1] got created.

If anyone wants to join efforts, feel free to contribute.

[1] https://etherpad.openstack.org/p/neutron-profiling


OpenStack Development Mailing List (not for usage questions)
Unsubscribe: OpenStack-dev-request@lists.openstack.org?subject:unsubscribe
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev
responded Feb 23, 2017 by Darek_Smigiel (1,960 points)   1
...