Open Stack

Hi Morgan,

You may have just given me my weekend back, though don't want to be
too optimistic just yet.

I set the expiration to 3600, restarted keystone (eventlet) and sent
memcached a flush_all.  Very briefly everything worked well and at low
load, saw accesses whizzing by in the keystone log and my Dash board
was snappy even in admin mode (which usually bogs things down).  About
10min in eventlet is pushing 100% but still responsive, so I'm hopeful
that moving back behind
apache will get me where i need to be, unless the new neutron is too
token happy (32k/hr over a 60 node cluster seems more than generous).


Thanks,
-Jon

On Sat, Jan 11, 2014 at 2:07 PM, Morgan Fainberg <m at metacloud.com> wrote:
> Hi Johnathan,
>
> This might be related to your issue.
>
> I think there are two problems here.  The first problem has to do with
> limited page sizes in memcache.  If you have an insane number of tokens
> issued (and as you said neutron is making a ton of requests for new tokens),
> you can fill up the user’s token index (due to the way tokens are stored we
> need to keep track of which user the token belongs to, so we can
> invalidate/revoke them as appropriate).  By default, the memcache page size
> is 1MB.  Each token will take up approximately 32 bytes (plus some overhead
> for separators etc), meaning we can hold about 32k active tokens for a
> single user.  The second issue is that as this list increases in size, there
> is a higher penalty due to round-trips to memcache to validate the tokens
> are still valid (we try and keep this list at a “sane” size, but in some
> cases this performs poorly).  So, to prevent an issue with filling up the
> page and being completely unable to authenticate until the page falls out of
> memcache, we check each token for a given user for validity on issuance of a
> new token.
>
> As long as you are not relying on long-lived tokens, you can decrease the
> life of the tokens by setting “expiration” setting in the “[token]” section
> of the configuration to a much smaller number of seconds (e.g. 3600 or so)
> rather than relying on the default 1 day (86400) expiration.  This means
> that a given token will expire sooner, and help to keep that user-token
> index list smaller.  If reducing the token expiration time helps
> significantly, then we know this is related to this bug:
> https://bugs.launchpad.net/keystone/+bug/1251123
>
> I’ll see if I can get a test-patch that you can attempt to work with that
> should use some of the same mechanisms I’m working on for Icehouse
> (specifically to address this issue).  However, it is likely that you will
> need to reduce the token TTL in either case.
>
> An alternative is to use the dogpile settings for token and use the SQL
> token backend (and add a cron to flush expired tokens out on a regular
> basis).  If you use the alternative, I still recommend setting the token
> expiration down to something in the ~3 hour range (if possible) to help keep
> bloat down.
>
> --Morgan
>
> On January 11, 2014 at 10:43:12, Jonathan Proulx (jon at jonproulx.com) wrote:
>
> Hi All,
>
> recently upgraded my 1 controller 60 compute node Ubuntu 12.04(+cloud
> archive) system from Grizlzy to Havana. Now even before I let my
> users back to the API I'm barely able to do anything due to
> authentication time outs. I am using neutron which like to
> authenticate *a lot*, I'm not entierly convinced the real problem
> isn't neutron reauthenticating a bajillion services a second, but
> right now it looks like Keystone...
>
> I'm using UUID Tokens with memcached backend.
>
> Under Grizzly I had been using Peter Feiner's multi worker patches,
> though this was only needed for peak loads (when starting 100's of
> instances). With just background noise of the running compute-nodes
> (60) and instances (281) in default single worker (eventlet) mode
> keystone runs at 100% and many client requests (from dash board or
> CLI) time out. Nova-compute nodes also frequently log timeouts when
> trying to authenticate to the neutron service.
>
> Verbose keystone logs show very little activity even when running 100%
> load, just a few "INFO acceess" type entries every few *minutes*.
> Debug logging show many sqlalchemy actions per second for the neutron
> user id and admin tenant id.
>
> I took the next obvious step and put keystone behind apache, while
> that does get more servers running, performance if anything is even
> worse while using virtually all of the 12 core controller node's CPUs
> rather than just one of them.
>
> The logs quickly fill with data read timeouts:
>
> 2014-01-11 12:31:26.606 3054 INFO access [-] 192.168.128.43 - -
> [11/Jan/2014:17:31:26 +0000] "POST
> http://192.168.128.15:35357/v2.0/tokens HTTP/1.1" 500 167
> 2014-01-11 12:31:26.621 3054 ERROR keystone.common.wsgi [-] request
> data read error
> 2014-01-11 12:31:26.621 3054 TRACE keystone.common.wsgi Traceback
> (most recent call last):
> 2014-01-11 12:31:26.621 3054 TRACE keystone.common.wsgi File
> "/usr/lib/python2.7/dist-packages/keystone/common/wsgi.py", line 371,
> in __call__
> 2014-01-11 12:31:26.621 3054 TRACE keystone.common.wsgi response =
> self.process_request(request)
> 2014-01-11 12:31:26.621 3054 TRACE keystone.common.wsgi File
> "/usr/lib/python2.7/dist-packages/keystone/middleware/core.py", line
> 110, in process_request
> 2014-01-11 12:31:26.621 3054 TRACE keystone.common.wsgi
> params_json = request.body
> 2014-01-11 12:31:26.621 3054 TRACE keystone.common.wsgi File
> "/usr/lib/python2.7/dist-packages/webob/request.py", line 677, in
> _body__get
> 2014-01-11 12:31:26.621 3054 TRACE keystone.common.wsgi
> self.make_body_seekable() # we need this to have content_length
> 2014-01-11 12:31:26.621 3054 TRACE keystone.common.wsgi File
> "/usr/lib/python2.7/dist-packages/webob/request.py", line 922, in
> make_body_seekable
> 2014-01-11 12:31:26.621 3054 TRACE keystone.common.wsgi self.copy_body()
> 2014-01-11 12:31:26.621 3054 TRACE keystone.common.wsgi File
> "/usr/lib/python2.7/dist-packages/webob/request.py", line 945, in
> copy_body
> 2014-01-11 12:31:26.621 3054 TRACE keystone.common.wsgi self.body
> = self.body_file.read(self.content_length)
> 2014-01-11 12:31:26.621 3054 TRACE keystone.common.wsgi File
> "/usr/lib/python2.7/dist-packages/webob/request.py", line 1521, in
> readinto
> 2014-01-11 12:31:26.621 3054 TRACE keystone.common.wsgi data =
> self.file.read(sz0)
> 2014-01-11 12:31:26.621 3054 TRACE keystone.common.wsgi IOError:
> request data read error
> 2014-01-11 12:31:26.621 3054 TRACE keystone.common.wsgi
>
> I've played around with different process and tread count numbers in
> the WSGIDaemonProcess apache directive, but while some seem make it
> worse none have made it better.
>
> Clearly I must be doing something wrong since the single process
> eventlet mode has significantly better performance than the
> multiprocess wsgi mode.
>
> I've also fiddled a bit with the dogpile cache settings, when running
> a single stand alone process the 'memory' backend seemed to make
> things actually go, though after getting the pylibmc backend setup (or
> I think setup there could well be more I'm misisng), which didn't make
> a noticible difference, I wasn't able to revert to the 'success' or
> the memory backend though for obvious reasons I wouldn't have wanted
> to keep that one in production anyway.
>
> How can I either make Keystone go faster or Neutron authenticate less?
>
> -Jon
>
> _______________________________________________
> Mailing list: http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack
> Post to : openstack at lists.openstack.org
> Unsubscribe : http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack