silva 2.3 - pylibmc issues
Andrew Altepeter <[email protected]> Fri, 29 Jul 2011 12:20:47 -0500
| Newsgroups | gmane.comp.web.zope.silva.devel |
|---|---|
| Message-ID | <CAEssFdB7z=z2umqo=CWA7nDKEEpV1LcXZb+-SNaJ90whbkkt7A@mail.gmail.com> |
--===============2053989763588298894==
Content-Type: multipart/alternative; boundary=000e0cd34ff499c00604a938805d
--000e0cd34ff499c00604a938805d
Content-Type: text/plain; charset=ISO-8859-1
Greetings!
I attempted to upgrade our Silva 2.1 instance to Silva 2.3 on Wednesday.
Before the upgrade was scheduled, everything was tested and functioning
properly.
The upgrade went smoothly, but the resultant system was immediately
unstable. We're using apache/mod_wsgi in production. After starting up,
the server would lock up when serving the assets for the first web page.
This lock-up would happen whether running under mod_wsgi, or using paster
serve and either debug or deploy scripts. As a result, we aborted the
upgrade. I don't know why we did not see this issue earlier.
What follows in this email is my troubleshooting steps and results, and what
we're thinking of doing to address this issue.
I've been troubleshooting the past two days, and I think I've found the
problem. First, I needed to inspect a thread dump. Zope 2, pre-wsgi had
DeadlockDebugger. For wsgi, I found a nice thread dumper for 'paster
deploy', and adjusted the 'debug.ini' script as follows:
[app:watch_threads]
use = egg:Paste#watch_threads
allow_kill = true
[composite:main]
use = egg:Paste#urlmap
/ = silva
/.tracker = watch_threads
#[pipeline:main]
#pipeline = silva
[server:main]
use = egg:Paste#http
host = 0.0.0.0
port = 8080
threadpool_workers = 7
I can now go to localhost:8080/.tracker and get a nice thread dumper, with
env vars, and can even kill off the threads! (although killing doesn't
nicely close the tcp session with the client, it just terminates the thread)
Using the thread dumper, I was able to see where the threads were locking
up. Since we are using ZEO, we are also using memcached for caching
storage. Every thread was locking up in a specific section of code, having
to deal with Beaker either retrieving values from memcached, or see if they
exist.
In my development environment (opensuse 11.3, system python 2.6.5, pylibmc
1.1.1 and 1.1.2, libmemcached-0.47), I actually get tracebacks instead of
hung threads. Here is the tail end of one:
File
"/home/aaltepet/.buildout/eggs/Products.PluggableAuthService-1.7.2-py2.6.egg/Products/PluggableAuthService/PluggableAuthService.py",
line 226, in validate
user_ids = self._extractUserIds(request, plugins)
File
"/home/aaltepet/.buildout/eggs/Products.PluggableAuthService-1.7.2-py2.6.egg/Products/PluggableAuthService/PluggableAuthService.py",
line 599, in _extractUserIds
credentials )
File
"/home/aaltepet/silva/local-Silva-2.3/src/silva.pas.base/src/silva/pas/base/plugins/cookie.py",
line 178, in authenticateCredentials
if session.get('secret', None) == client_secret:
File
"/home/aaltepet/silva/local-Silva-2.3/src/silva.core.cache/src/silva/core/cache/store.py",
line 31, in get
return self.__backend.get(self._real_key(key))
File
"/home/aaltepet/.buildout/eggs/Beaker-1.5.4-py2.6.egg/beaker/cache.py", line
214, in get
return self._get_value(key, **kw).get_value()
File
"/home/aaltepet/.buildout/eggs/Beaker-1.5.4-py2.6.egg/beaker/container.py",
line 252, in get_value
has_value = self.has_value()
File
"/home/aaltepet/.buildout/eggs/Beaker-1.5.4-py2.6.egg/beaker/container.py",
line 214, in has_value
return self.namespace.has_key(self.key)
File
"/home/aaltepet/.buildout/eggs/Beaker-1.5.4-py2.6.egg/beaker/ext/memcached.py",
line 61, in has_key
return key in self
File
"/home/aaltepet/.buildout/eggs/Beaker-1.5.4-py2.6.egg/beaker/ext/memcached.py",
line 57, in __contains__
value = self.mc.get(self._format_key(key))
MemcachedError: error 15 from memcached_get: STORED
In production, there were no errors, rather hung threads. Production is
RHEL5, manually compile python 2.6.7. The thread dump would show the tread
hung at the same line, memcached.py:57. Similarly I've seen hung threads at
memcached.py:54 (same call, but in __getitem__).
Silva 2.3 is using pylibmc, which are python bindings for libmemcached, a
memcached client library in C. As such, it is impossible to get inside the
self.mc.get call to see what is actually happening.
The memcached server doesn't appear to be the problem, as the same server is
working for our legacy zopes which have custom memcached caching.
I tried upgrading pylibmc to 1.1.2, same problem. libmemcached to 0.51 does
not compile. libmemcached 0.50 does compile, but crashes zope with some c
error:
python: libmemcached/get.cc:86: char* memcached_get_by_key(memcached_st*,
const char*, size_t, const char*, size_t, size_t*, uint32_t*,
memcached_return_t*): Assertion `ptr->query_id == query_id +1' failed.
Aborted
I ran a memcached server in the foreground with very verbose debugging
(memcached -p 11211 -vv). I then started up zope (./bin/paster serve
debug.ini) and in my browser went to /silva/edit. I was prompted to login
(this is Silva's cookie-based login, not HTTP-Basic). The Silva edit screen
would then partially load, and a few requests would hang. In memcached, I
saw the following lines repeated a huge number of times:
<43 get session:32de58cc0b8b4b5e32cf7ba6a13a49066f91c9e1_login
>43 sending key session:32de58cc0b8b4b5e32cf7ba6a13a49066f91c9e1_login
>43 END
(this is for Silva's cookie-based auth checking my browser's session
cookie).
If I disable Silva's cookie auth and use HTTP-Basic, requests do not hang
(there are no session:XXXX GETs in memcached). If I keep cookie auth and
reconfigure silva.core.cache/beaker to instead use file storage for sessions
(the default in the base.cfg buildout profile), there are no hung threads
and things work swimmingly.
I don't know what to make of this. Is there some concurrency issue with
these large numbers of session:XXXX GETs, and libmemcached deadlocks? With
file storage for sessions enabled but memcached is still the default cache
type, I see that there are still stores and gets with memcached, but no lock
ups. Perhaps this is due to the lower frequency of stores / gets.
I mentioned that our older Silva cms has some custom memcached caching.
We're using python-memcached for this, which is a pure python memcached
client. I adjusted the Silva 2.3 buildout to install python-memcached and
NOT install pylibmc, since pylibmc is preferred if found. I turned
memcached storage for auth sessions back on, and Silva 2.3 is now stable.
I can only think that libmemcached is preferred for performance reasons, and
nothing else. Bethel's current ZEO setup is quite responsive using
python-memcached, and since it appears stable I think we'll be launching
with that memcached client instead.
Has anyone who has already deployed / upgraded to Silva 2.3 + memcached
experienced any similar issues? I'd appreciate some feedback if you have.
peace,
Andy
--000e0cd34ff499c00604a938805d
Content-Type: text/html; charset=ISO-8859-1
Content-Transfer-Encoding: quoted-printable
Greetings!<div><br></div><div>I attempted to upgrade our Silva 2.1 instance=
to Silva 2.3 on Wednesday. =A0Before the upgrade was scheduled, everything=
was tested and functioning properly.</div><div><br></div><div>The upgrade =
went smoothly, but the resultant system was immediately unstable. =A0We'=
;re using apache/mod_wsgi in production. =A0After starting up, the server w=
ould lock up when serving the assets for the first web page. =A0This lock-u=
p would happen whether running under mod_wsgi, or using paster serve and ei=
ther debug or deploy scripts. =A0As a result, we aborted the upgrade. =A0I =
don't know why we did not see this issue earlier.</div>
<div><br></div><div>What follows in this email is my troubleshooting steps =
and results, and what we're thinking of doing to address this issue.</d=
iv><div><br></div><div>I've been troubleshooting the past two days, and=
I think I've found the problem. =A0First, I needed to inspect a thread=
dump. =A0Zope 2, pre-wsgi had DeadlockDebugger. =A0For wsgi, I found a nic=
e thread dumper for 'paster deploy', and adjusted the 'debug.in=
i' script as follows:</div>
<div><br></div><div><div>[app:watch_threads]</div><div>use =3D egg:Paste#wa=
tch_threads</div><div>allow_kill =3D true</div><div><br></div><div>[composi=
te:main]</div><div>use =3D egg:Paste#urlmap</div><div>/ =3D silva</div><div=
>/.tracker =3D watch_threads</div>
<div><br></div><div>#[pipeline:main]</div><div>#pipeline =3D silva</div><di=
v><br></div><div>[server:main]</div><div>use =3D egg:Paste#http</div><div>h=
ost =3D 0.0.0.0</div><div>port =3D 8080</div><div>threadpool_workers =3D 7<=
/div></div>
<div><br></div><div>I can now go to localhost:8080/.tracker and get a nice =
thread dumper, with env vars, and can even kill off the threads! =A0(althou=
gh killing doesn't nicely close the tcp session with the client, it jus=
t terminates the thread)</div>
<div><br></div><div>Using the thread dumper, I was able to see where the th=
reads were locking up. =A0Since we are using ZEO, we are also using memcach=
ed for caching storage. =A0Every thread was locking up in a specific sectio=
n of code, having to deal with Beaker either=A0retrieving=A0values from mem=
cached, or see if they exist.</div>
<div><br></div><div>In my development environment (opensuse 11.3, system py=
thon 2.6.5, pylibmc 1.1.1 and 1.1.2, libmemcached-0.47), I actually get tra=
cebacks instead of hung threads. Here is the tail end of one:</div><div>
<br></div><div><div>=A0=A0File "/home/aaltepet/.buildout/eggs/Products=
.PluggableAuthService-1.7.2-py2.6.egg/Products/PluggableAuthService/Pluggab=
leAuthService.py", line 226, in validate</div><div>=A0=A0 =A0user_ids =
=3D self._extractUserIds(request, plugins)</div>
<div>=A0=A0File "/home/aaltepet/.buildout/eggs/Products.PluggableAuthS=
ervice-1.7.2-py2.6.egg/Products/PluggableAuthService/PluggableAuthService.p=
y", line 599, in _extractUserIds</div><div>=A0=A0 =A0credentials )</di=
v><div>
=A0=A0File "/home/aaltepet/silva/local-Silva-2.3/src/silva.pas.base/sr=
c/silva/pas/base/plugins/cookie.py", line 178, in authenticateCredenti=
als</div><div>=A0=A0 =A0if session.get('secret', None) =3D=3D clien=
t_secret:</div>
<div>=A0=A0File "/home/aaltepet/silva/local-Silva-2.3/src/silva.core.c=
ache/src/silva/core/cache/store.py", line 31, in get</div><div>=A0=A0 =
=A0return self.__backend.get(self._real_key(key))</div><div>=A0=A0File &quo=
t;/home/aaltepet/.buildout/eggs/Beaker-1.5.4-py2.6.egg/beaker/cache.py"=
;, line 214, in get</div>
<div>=A0=A0 =A0return self._get_value(key, **kw).get_value()</div><div>=A0=
=A0File "/home/aaltepet/.buildout/eggs/Beaker-1.5.4-py2.6.egg/beaker/c=
ontainer.py", line 252, in get_value</div><div>=A0=A0 =A0has_value =3D=
self.has_value()</div>
<div>=A0=A0File "/home/aaltepet/.buildout/eggs/Beaker-1.5.4-py2.6.egg/=
beaker/container.py", line 214, in has_value</div><div>=A0=A0 =A0retur=
n self.namespace.has_key(self.key)</div><div>=A0=A0File "/home/aaltepe=
t/.buildout/eggs/Beaker-1.5.4-py2.6.egg/beaker/ext/memcached.py", line=
61, in has_key</div>
<div>=A0=A0 =A0return key in self</div><div>=A0=A0File "/home/aaltepet=
/.buildout/eggs/Beaker-1.5.4-py2.6.egg/beaker/ext/memcached.py", line =
57, in __contains__</div><div>=A0=A0 =A0value =3D self.mc.get(self._format_=
key(key))</div>
<div>MemcachedError: error 15 from memcached_get: STORED</div></div><div><b=
r></div><div>In production, there were no errors, rather hung threads. =A0P=
roduction is RHEL5, manually compile python 2.6.7. =A0The thread dump would=
show the tread hung at the same line, memcached.py:57. =A0Similarly I'=
ve seen hung threads at memcached.py:54 (same call, but in __getitem__).</d=
iv>
<div><br></div><div>Silva 2.3 is using pylibmc, which are python bindings f=
or libmemcached, a memcached client library in C. =A0As such, it is impossi=
ble to get inside the self.mc.get call to see what is actually happening.=
=A0</div>
<div><br></div><div>The memcached server doesn't appear to be the probl=
em, as the same server is working for our legacy zopes which have custom me=
mcached caching.</div><div><br></div><div>I tried upgrading pylibmc to 1.1.=
2, same problem. =A0libmemcached to 0.51 does not compile. =A0libmemcached =
0.50 does compile, but crashes zope with some c error:</div>
<div><div>python: libmemcached/get.cc:86: char* memcached_get_by_key(memcac=
hed_st*, const char*, size_t, const char*, size_t, size_t*, uint32_t*, memc=
ached_return_t*): Assertion `ptr->query_id =3D=3D query_id +1' faile=
d.</div>
<div>Aborted</div></div><div><br></div><div>I ran a memcached server in the=
foreground with very verbose debugging (memcached -p 11211 -vv). =A0I then=
started up zope (./bin/paster serve debug.ini) and in my browser went to /=
silva/edit. =A0I was prompted to login (this is Silva's cookie-based lo=
gin, not HTTP-Basic). =A0The Silva edit screen would then partially load, a=
nd a few requests would hang. =A0In memcached, I saw the following lines re=
peated a huge number of times:</div>
<div><br></div><div><div><43 get session:32de58cc0b8b4b5e32cf7ba6a13a490=
66f91c9e1_login=A0</div><div>>43 sending key session:32de58cc0b8b4b5e32c=
f7ba6a13a49066f91c9e1_login</div><div>>43 END</div></div><div><br></div>
<div>(this is for Silva's cookie-based auth checking my browser's s=
ession cookie).</div><div><br></div><div>If I disable Silva's cookie au=
th and use HTTP-Basic, requests do not hang (there are no session:XXXX GETs=
in memcached). =A0If I keep cookie auth and reconfigure silva.core.cache/b=
eaker to instead use file storage for sessions (the default in the base.cfg=
buildout profile), there are no hung threads and things work swimmingly.</=
div>
<div><br></div><div>I don't know what to make of this. =A0Is there some=
concurrency issue with these large numbers of session:XXXX GETs, and libme=
mcached deadlocks? =A0With file storage for sessions enabled but memcached =
is still the default cache type, I see that there are still stores and gets=
with memcached, but no lock ups. =A0Perhaps this is due to the lower frequ=
ency of stores / gets.</div>
<div><br></div><div>I mentioned that our older Silva cms has some custom me=
mcached caching. =A0We're using python-memcached for this, which is a p=
ure python memcached client. =A0I adjusted the Silva 2.3 buildout to instal=
l python-memcached and NOT install pylibmc, since pylibmc is preferred if f=
ound. =A0I turned memcached storage for auth sessions back on, and Silva 2.=
3 is now stable.</div>
<div><br></div><div>I can only think that libmemcached is preferred for per=
formance reasons, and nothing else. =A0Bethel's current ZEO setup is qu=
ite responsive using python-memcached, and since it appears stable I think =
we'll be launching with that memcached client instead.</div>
<div><br></div><div>Has anyone who has already deployed / upgraded to Silva=
2.3 + memcached experienced any similar issues? =A0I'd appreciate some=
feedback if you have.</div><div><br></div><div>peace,</div><div>Andy</div>
<div><br></div><div><br></div><div><br></div>
--000e0cd34ff499c00604a938805d--
--===============2053989763588298894==
Content-Type: text/plain; charset="us-ascii"
MIME-Version: 1.0
Content-Transfer-Encoding: 7bit
Content-Disposition: inline
_______________________________________________
silva-dev mailing list
silva-dev-IAPFreCvJWM6s/[email protected]
https://lists.infrae.com/mailman/listinfo/silva-dev
--===============2053989763588298894==--