Timeout from API with 50 Simultaneous Builds

I've managed to reproduce this locally by stubbing out quotas, ratelimiting, and the virt driver.

My current working hypothesis is that something in Nova is blocking. This causes the connect_timeout to trigger (because once eventlet context switches back into the main greenthread (or whatever it is that it does)), the timeout has expired without being cancelled. This would explain the log message in rabbit saying that the connection was abruptly terminated (meaning the connection was actually established, in spite of Nova saying it timed out).

If that's indeed the case, yes, we shouldn't be blocking, but eventlet also should check if the connection has been established before it kills the connection attempt.

Full logs from api and scheduler from 50 instance build:

http://paste.openstack.org/show/1271/ - nova-api
http://paste.openstack.org/show/1272/ - nova-scheduler

I'm still blaming eventlet for this. Looking at the logs, it looks like the sheer volume of requests simply makes it take more than 5 seconds before the event loop in eventlet gets back to the attempt to establish a connection. We can optimise the time-per-request, but that'll won't solve anything, it'll just hide the problem until we try 100 or 200 requests at a time. Same if we increase the timeout.

Wasn't there some idea that this was because nova-api doesn't monkeypatch all of the libraries?

Vish

On May 4, 2011, at 1:58 PM, Soren Hansen wrote:

> I'm still blaming eventlet for this. Looking at the logs, it looks like
> the sheer volume of requests simply makes it take more than 5 seconds
> before the event loop in eventlet gets back to the attempt to establish
> a connection. We can optimise the time-per-request, but that'll won't
> solve anything, it'll just hide the problem until we try 100 or 200
> requests at a time. Same if we increase the timeout.
>
> --
> You received this bug notification because you are a member of Nova Bug
> Team, which is subscribed to OpenStack Compute (nova).
> https://bugs.launchpad.net/bugs/771512
>
> Title:
> Timeout from API with 50 Simultaneous Builds
>
> Status in OpenStack Compute (Nova):
> Confirmed
>
> Bug description:
> Running cactus, I attempted a build of 50 VMs at once via the API and
> ran into a timeout where 12 of the 50 VMs timed out and are stuck in
> build. The remaining went active.
>
> for i in `seq 1 50`; do nova boot test --flavor 1 --image 10 & >
> /dev/null ; echo $i ; done
>
> API Limits were raised well past this in limits.py for stress testing.
>
> 2011-04-26 17:36:51,852 ERROR nova.api.openstack [-] Caught error: timed out
> (nova.api.openstack): TRACE: Traceback (most recent call last):
> (nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/nova/api/openstack/__init__.py", line 59, in __call__
> (nova.api.openstack): TRACE: return req.get_response(self.application)
> (nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/webob/request.py", line 919, in get_response
> (nova.api.openstack): TRACE: application, catch_exc_info=False)
> (nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/webob/request.py", line 887, in call_application
> (nova.api.openstack): TRACE: app_iter = application(self.environ, start_response)
> (nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/webob/dec.py", line 159, in __call__
> (nova.api.openstack): TRACE: return resp(environ, start_response)
> (nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/webob/dec.py", line 159, in __call__
> (nova.api.openstack): TRACE: return resp(environ, start_response)
> (nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/webob/dec.py", line 159, in __call__
> (nova.api.openstack): TRACE: return resp(environ, start_response)
> (nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/routes/middleware.py", line 131, in __call__
> (nova.api.openstack): TRACE: response = self.app(environ, start_response)
> (nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/webob/dec.py", line 159, in __call__
> (nova.api.openstack): TRACE: return resp(environ, start_response)
> (nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/webob/dec.py", line 147, in __call__
> (nova.api.openstack): TRACE: resp = self.call_func(req, *args, **self.kwargs)
> (nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/webob/dec.py", line 208, in call_func
...

2011/5/4 Vish Ishaya <email address hidden>:
> Wasn't there some idea that this was because nova-api doesn't
> monkeypatch all of the libraries?

There was. It wasn't.

Reproduced outside of Nova (in accordance with my previous analysis). Reported it upstream:

    https://bitbucket.org/which_linden/eventlet/issue/87/socket-connects-are-incorrectly-reported

I think we can say at this point that the problem is well understood and just needs someone to fix it. Marking Triaged accordingly.

In my opinion, this should be a Critical priority bug...

Additionally (another bug?), OS API really needs to take a num_instances parameter like EC2 so we can get the benefits of the load balancer/scheduler.

I added a comment to the above bitbucket thread with a potential patch. I'll attach it here as well. Comments are in the patch along with more on the bitbucket thread.

My above patch makes an improvement, but there's still timeouts. Unclear whether the timeouts are real or not yet. However, after talking with soren again, I've decided to try to fix eventlet more correctly by checking if a timeout exception was returned... and then re-trying a non-blocking event once more. If this 2nd non-blocking event fails, it returns original timeout exception. Attached is a start to the patch. My test case passes, but I need to fix the rest of the socket wrapper calls, yet. I've done connect(), recv(), recvfrom() so far. (See attached patch).

Sorry, the connect_ex() modification was wrong in the above. Here's an updated version of patch.

Maybe finished version, though it appears some tests need fixed. Either way, tests are failing in eventlet trunk without this patch.

I have tested the above patch with 50 simultaneous builds and the timeouts are gone.

(Additionally, after testing this and applying the merge prop diff for: https://bugs.launchpad.net/nova/+bug/766404
and a proposed fix for: https://bugs.launchpad.net/nova/+bug/781435

we can now get 50 instances all in the ACTIVE state when building them in parallel. Woo!)

There's another issue when we go to 100 instances, now. Getting lots of 'IOError: Socket closed' when carrot tries to connect to rabbit. Ultimately, I think we need to make some changes to nova-api to make it handle this level of concurrent sessions. I have some ideas, but I want to look at the api code, which I'm not that familiar with, before I make some statements that might be idiotic. :)

About Importance: I think "High" is about right, the impact is very serious but does not disable completely the use of the system, corrupts or exposes your data. See bottom of http://wiki.openstack.org/BugsLifecycle for guidelines.

That said, it's very much something we need to fix ASAP, so it should be targeted to a milestone :) Importance/Impact and urgency being two different (though very inter-related) things.

Linked lp:~cbehrens/nova/rpc-improvements here also. This implements a connection pool for connections to rabbit, as well as changes the 3 Service topic consumers to use a single connection that has a single wait() for events. That eliminates 3 threads that are reach repeatedly polling rabbit every 0.1 seconds.

All of that should:

1) Reduce bombing rabbit with new connections
2) Reduce overall number of connections to rabbit
3) Reduce a lot of context switches
4) Remove possible unnecessary 0.1 second delay in services processing requests.

etc.

Thanks, Chris!

I've applied your changes and it allowed me run 400 instances on 3 nodes without errors for the first time!

(RHEL6, KVM)

This bug was fixed in the package python-eventlet - 0.9.15-0ubuntu2

---------------
python-eventlet (0.9.15-0ubuntu2) oneiric; urgency=low

  * retry-on-timeout.patch: This addresses a problem where a timeout fires
    even though the connection was actually correctly established. (LP:
    #771512)
  * reuseaddr.patch: Make sure SO_REUSEADDR is set.
  * mysql-import-traceback.patch: Add missing import in the mysql tests.
  * Add python-greenlet dependency.
 -- Soren Hansen <email address hidden> Wed, 25 May 2011 22:02:42 +0200