Received: by 10.66.77.39 with SMTP id p7mr2495560paw.0.1349480700784;
Fri, 05 Oct 2012 16:45:00 -0700 (PDT)
X-BeenThere: python-tornado@googlegroups.com
Received: by 10.68.194.202 with SMTP id hy10ls16660049pbc.0.gmail; Fri, 05 Oct
2012 16:44:57 -0700 (PDT)
Received: by 10.68.211.6 with SMTP id my6mr3625220pbc.15.1349480697246;
Fri, 05 Oct 2012 16:44:57 -0700 (PDT)
Date: Fri, 5 Oct 2012 16:44:56 -0700 (PDT)
From: Daniel Kador <d...@keen.io>
To: python-tornado@googlegroups.com
Cc: b...@bendarnell.com
Message-Id: <18c6f171-5e1e-40c6-9b2f-4ae478a92fb5@googlegroups.com>
In-Reply-To: <5e0e2fa0-f6ba-466c-8dd7-2c58997f97eb@googlegroups.com>
References: <3086a6a3-fdc1-4b6d-9ae4-774e3755579c@googlegroups.com>
<CAFkYKJ7__VNz1tzXEBRPTp9ugW3YYe=umCYGWZEj-O4hOojDFg@mail.gmail.com>
<3b912ec9-50ff-456c-a31b-082d6279ce25@googlegroups.com>
<c5e856fe-ecf0-49c0-ad81-26b276bec821@googlegroups.com>
<95a7e31c-b396-448e-ab1b-c730de2cde02@googlegroups.com>
<a1f6e311-89b1-4d44-a91c-419baae01717@googlegroups.com>
<4920cd4a-8a33-450a-9568-63e07582b704@googlegroups.com>
<5e0e2fa0-f6ba-466c-8dd7-2c58997f97eb@googlegroups.com>
Subject: Re: [tornado] Timeouts in tests using Tornado + Motor
MIME-Version: 1.0
Content-Type: multipart/mixed;
boundary="----=_Part_220_27785369.1349480696769"
------=_Part_220_27785369.1349480696769
Content-Type: multipart/alternative;
boundary="----=_Part_221_11670270.1349480696769"
------=_Part_221_11670270.1349480696769
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 7bit
I appear to have found a fix. I was previously returning an Application
instance in self.get_app() with the debug kwarg set to True (tests were
inheriting the default value for running in dev mode) and now everything is
quite speedy. More importantly, the tests actually all run! I'm
satisfied, but if Ben or Jesse wants me to dig in more to figure out what,
exactly, debug mode is doing, I'm happy to help out.
One thing I noticed: I was able to reproduce the problem in a small test
class with ~100 tests. The ONLY way I could repro, though, was if I had
debug mode on AND I returned the singleton IOLoop from IOLoop.instance() in
self.get_new_ioloop() AND each test made a simple HTTP request AND my
application used my request handlers (if I tried with a barebones app it
was all fine).
So it *appears* as if there's some strange interaction between my handlers
and debug mode?
On Friday, October 5, 2012 3:21:19 PM UTC-7, Daniel Kador wrote:
>
> The doc additions looks great, thanks for handling it so quickly.
>
> db.serverStatus().cursors reports nothing interesting at all. The cursors
> are definitely being closed (which is good).
>
> The CPU is being used by Python. Mongo hardly has a blip.
>
> I ran lsof -p PID | wc -l, where PID was the PID of my Python process.
> The count stays steady around 55. Most of the results are related to the
> .so files loaded by Python. There are about 10 related to sockets, which
> seems pretty reasonable to me.
>
> Mongo stays pretty consistent around 113. Again, that doesn't sound crazy.
>
> It definitely *feels* like the Python layer is leaking something,
> somewhere. Is there an easy way to see what's registered on the ioloop?
> Or just simply log what the ioloop is currently working on? I wonder if my
> code is somehow not terminating in some cases? Or taking much longer than
> I think?
>
> On Friday, October 5, 2012 3:09:38 PM UTC-7, A. Jesse Jiryu Davis wrote:
>>
>> I've updated the docs about MotorCursor:
>>
>> http://emptysquare.net/motor/pymongo/api/motor/motor_cursor.html
>>
>> Let me know what you find out regarding your tests, Dan, or any other way
>> I can help. I want anyone who uses Motor to succeed. =)
>>
>> On Friday, October 5, 2012 2:53:00 PM UTC-7, A. Jesse Jiryu Davis wrote:
>>>
>>> No, I'll add this to the docs -- a MotorCursor's __del__ calls the
>>> PyMongo Cursor's close(), which checks if the cursor needs to be closed on
>>> the server and if so sends the closeCursors command. So if you've fully
>>> iterated a cursor (with to_list, or next_object until it returns None) then
>>> the server has already closed the cursor, otherwise the client cursor
>>> closes itself on the server when it's dereferenced.
>>>
>>> Motor's own test suite checks for leaked cursors after every test:
>>>
>>>
>>> https://github.com/ajdavis/mongo-python-driver/blob/motor/test/motor/__init__.py#L278
>>>
>>> So you could do something similar in your tests, or manually run
>>> db.serverStatus().cursors in the Mongo shell while the tests are going. If
>>> it rises a lot, then we have a problem.
>>>
>>> Is it Python or MongoDB that mostly uses CPU? I'm not surprised your CPU
>>> is pegged, nothing *else* would be the bottleneck in your unittests.
>>>
>>> Can you run lsof|grep PID|wc -l, where PID is the PID of your Python
>>> process, and make sure that process itself isn't opening more than a dozen
>>> or so connections? What about with mongod's PID?
>>>
>>> On Friday, October 5, 2012 2:11:19 PM UTC-7, Daniel Kador wrote:
>>>>
>>>> Quick update - I believe I've ruled out file descriptors as the source
>>>> of my problem. I wrote a small script that just repeatedly runs "lsof | wc
>>>> -l" (which, as I understand it, should give me the number of open file
>>>> descriptors on my system) and stores the results in a texfile. Before I
>>>> launched any tests, my open file descriptor count hovered around 7,300. As
>>>> I ran tests, the number fluctuated a bit, but never went above 7,405 and
>>>> never went below 7,221. So it feels like I'm not blowing out the
>>>> descriptor count anywhere.
>>>>
>>>> I also verified that the tearDown methods in AsyncTestCase and
>>>> AsyncHTTPTestCase are being called on every test.
>>>>
>>>> Some more details (not sure if they're useful or relevant, but I'm
>>>> hoping they are): when I run tests my CPU gets pegged. One of my cores
>>>> goes to about 90% and hovers there for the whole run. Also, I'm overriding
>>>> get_new_ioloop() to return the singleton instance.
>>>>
>>>> Jesse, question for you: do I need to explicitly close cursors opened
>>>> by Motor? I'm pretty sure I don't need to do anything with the Connection
>>>> object, but I couldn't find anything that told me my responsibility re: the
>>>> cursor lifecycle.
>>>>
>>>> Will keep digging in.
>>>>
>>>> Thanks again!
>>>>
>>>> -Dan
>>>>
>>>> On Friday, October 5, 2012 11:38:59 AM UTC-7, Daniel Kador wrote:
>>>>>
>>>>> Awesome, I was thinking along the same lines. I've seen this problem
>>>>> on both my local development platform (Mac) and my CI box (Ubuntu). I've
>>>>> looked into the file descriptor problem before and didn't come up with
>>>>> anything definitive, but I'll dig in more. Both Jesse's and Ben's
>>>>> suggestions sound like good places to start.
>>>>>
>>>>> I'm using MotorReplicaSetConnection. I don't create a new one per
>>>>> test, I have a single module-level connection reference. I've tried
>>>>> explicitly setting up the connection and then tearing it down on every
>>>>> test, which didn't make a noticeable difference (except to significantly
>>>>> slow down my tests :P).
>>>>>
>>>>> I'll dig in more and report back. I don't /believe/ I'm forgetting to
>>>>> call super.tearDown(), but I'll double-check. If it's that simple I'll be
>>>>> relieved (and slightly embarrassed).
>>>>>
>>>>> Thanks so much!
>>>>>
>>>>> -Dan
>>>>>
>>>>> On Thursday, October 4, 2012 11:23:11 PM UTC-7, A. Jesse Jiryu Davis
>>>>> wrote:
>>>>>>
>>>>>> Agreed. Are you using MotorConnection or MotorReplicaSetConnection?
>>>>>> Do you create a new connection per test? Does it help to call close() on
>>>>>> that connection in tearDown() rather than simply relying on it to be
>>>>>> garbage-collected when it's dereferenced?
>>>>>>
>>>>>> On Thursday, October 4, 2012 8:53:31 PM UTC-7, Ben Darnell wrote:
>>>>>>>
>>>>>>> This sounds like it might be a file descriptor leak. Your tests
>>>>>>> might
>>>>>>> be opening sockets and not closing them, which would cause problems
>>>>>>> once you hit the file descriptor limit, which is relatively low by
>>>>>>> default on many platforms. Try increasing the limit by running
>>>>>>> "uname
>>>>>>> -n 10000" before running your tests (if you're on linux and the OS
>>>>>>> won't let you, try increasing the settings in
>>>>>>> /etc/security/limits.conf). If that works, then you're running out
>>>>>>> of
>>>>>>> file descriptors. Once you've confirmed the problem, a better
>>>>>>> long-term solution is to ensure that you're closing all the file
>>>>>>> descriptors you're opening. This includes sockets and regular
>>>>>>> files,
>>>>>>> as well as other file descriptors created by IOLoop and
>>>>>>> AsyncHTTPClient (could you be forgetting to call super.tearDown() in
>>>>>>> your tests?).
>>>>>>>
>>>>>>> -Ben
>>>>>>>
>>>>>>> On Thu, Oct 4, 2012 at 5:50 PM, Daniel Kador <d...@keen.io> wrote:
>>>>>>> > Hi!
>>>>>>> >
>>>>>>> > I'm running into (what I perceive to be) a strange problem with my
>>>>>>> tests.
>>>>>>> > I've got an application written on top of Tornado that
>>>>>>> communicates with
>>>>>>> > Mongo through the Motor library. It's humming away nicely in
>>>>>>> production
>>>>>>> > (daemonized using supervisord). The only problems (that I can
>>>>>>> detect) are
>>>>>>> > with my tests. I'm very happy to acknowledge that this could be a
>>>>>>> problem
>>>>>>> > in my application layer, or in the Motor layer, or maybe even in
>>>>>>> MongoDB
>>>>>>> > itself - mostly I'm looking for some guidance as I'm not really
>>>>>>> sure where
>>>>>>> > to start digging in.
>>>>>>> >
>>>>>>> > But let me step back and describe what I've noticed in more
>>>>>>> detail.
>>>>>>> >
>>>>>>> > I have approximately ~150 tests that extend the
>>>>>>> > tornado.testing.AsyncHTTPTestCase class, spread across a number of
>>>>>>> my own
>>>>>>> > classes. I have ~50 that are simple unit tests. They both
>>>>>>> communicate to
>>>>>>> > Mongo through Motor. The unit tests are fast and never fail (I
>>>>>>> mention this
>>>>>>> > only as a data point that may show Motor by itself may not be the
>>>>>>> culprit).
>>>>>>> > The AsyncHTTPTestCase tests all pass when their various test
>>>>>>> classes are run
>>>>>>> > individually.
>>>>>>> >
>>>>>>> > But when I run them all together, after about ~65 tests running
>>>>>>> and passing,
>>>>>>> > I start getting timeouts in various spots. Sometimes it's when
>>>>>>> interacting
>>>>>>> > directly with Motor. Sometimes it's when making an async HTTP
>>>>>>> request to
>>>>>>> > one of the APIs I've created (which, under the covers, is talking
>>>>>>> to Mongo
>>>>>>> > through Motor). But it's always when calling (from a test)
>>>>>>> self.wait().
>>>>>>> >
>>>>>>> > It's getting to be a serious problem, as now I can't actually run
>>>>>>> all my
>>>>>>> > tests locally (at one time). Obviously not a recipe for
>>>>>>> test-driven
>>>>>>> > development success.
>>>>>>> >
>>>>>>> > I'm relatively sure I've done something stupid, but I haven't
>>>>>>> figured out
>>>>>>> > where yet. Would really appreciate some help here.
>>>>>>> >
>>>>>>> > Thanks!
>>>>>>> >
>>>>>>> > -Dan
>>>>>>>
>>>>>>
------=_Part_221_11670270.1349480696769
Content-Type: text/html; charset=utf-8
Content-Transfer-Encoding: quoted-printable
I appear to have found a fix. I was previously returning an Applicati=
on instance in self.get_app() with the debug kwarg set to True (tests were =
inheriting the default value for running in dev mode) and now everything is=
quite speedy. More importantly, the tests actually all run! I'=
m satisfied, but if Ben or Jesse wants me to dig in more to figure out what=
, exactly, debug mode is doing, I'm happy to help out.<div><br></div><div>O=
ne thing I noticed: I was able to reproduce the problem in a small test cla=
ss with ~100 tests. The ONLY way I could repro, though, was if I had =
debug mode on AND I returned the singleton IOLoop from IOLoop.instance() in=
self.get_new_ioloop() AND each test made a simple HTTP request AND my appl=
ication used my request handlers (if I tried with a barebones app it was al=
l fine).</div><div><br></div><div>So it <b>appears</b> as if there's s=
ome strange interaction between my handlers and debug mode?<br><div><br>On =
Friday, October 5, 2012 3:21:19 PM UTC-7, Daniel Kador wrote:<blockquote cl=
ass=3D"gmail_quote" style=3D"margin: 0;margin-left: 0.8ex;border-left: 1px =
#ccc solid;padding-left: 1ex;">The doc additions looks great, thanks for ha=
ndling it so quickly.<div><br></div><div>db.serverStatus().cursors reports =
nothing interesting at all. The cursors are definitely being closed (=
which is good).</div><div><br></div><div>The CPU is being used by Python. &=
nbsp;Mongo hardly has a blip.</div><div><br></div><div>I ran lsof -p PID | =
wc -l, where PID was the PID of my Python process. The count stays st=
eady around 55. Most of the results are related to the .so files load=
ed by Python. There are about 10 related to sockets, which seems pret=
ty reasonable to me.</div><div><br></div><div>Mongo stays pretty consistent=
around 113. Again, that doesn't sound crazy.</div><div><br></div><di=
v>It definitely *feels* like the Python layer is leaking something, somewhe=
re. Is there an easy way to see what's registered on the ioloop? &nbs=
p;Or just simply log what the ioloop is currently working on? I wonder if m=
y code is somehow not terminating in some cases? Or taking much longe=
r than I think?</div><div><div><div><div><br>On Friday, October 5, 2012 3:0=
9:38 PM UTC-7, A. Jesse Jiryu Davis wrote:<blockquote class=3D"gmail_quote"=
style=3D"margin:0;margin-left:0.8ex;border-left:1px #ccc solid;padding-lef=
t:1ex">I've updated the docs about MotorCursor:<br><br><a href=3D"http://em=
ptysquare.net/motor/pymongo/api/motor/motor_cursor.html" target=3D"_blank">=
http://emptysquare.net/motor/<wbr>pymongo/api/motor/motor_<wbr>cursor.html<=
/a><br><br>Let me know what you find out regarding your tests, Dan, or any =
other way I can help. I want anyone who uses Motor to succeed. =3D)<br><br>=
On Friday, October 5, 2012 2:53:00 PM UTC-7, A. Jesse Jiryu Davis wrote:<bl=
ockquote class=3D"gmail_quote" style=3D"margin:0;margin-left:0.8ex;border-l=
eft:1px #ccc solid;padding-left:1ex">No, I'll add this to the docs -- a Mot=
orCursor's __del__ calls the PyMongo Cursor's close(), which checks if the =
cursor needs to be closed on the server and if so sends the closeCursors co=
mmand. So if you've fully iterated a cursor (with to_list, or next_object u=
ntil it returns None) then the server has already closed the cursor, otherw=
ise the client cursor closes itself on the server when it's dereferenced.<b=
r><br>Motor's own test suite checks for leaked cursors after every test:<br=
><br><a href=3D"https://github.com/ajdavis/mongo-python-driver/blob/motor/t=
est/motor/__init__.py#L278" target=3D"_blank">https://github.com/ajdavis/<w=
br>mongo-python-driver/blob/<wbr>motor/test/motor/__init__.py#<wbr>L278</a>=
<br><br>So you could do something similar in your tests, or manually run db=
.serverStatus().cursors in the Mongo shell while the tests are going. If it=
rises a lot, then we have a problem.<br><br>Is it Python or MongoDB that m=
ostly uses CPU? I'm not surprised your CPU is pegged, nothing *else* would =
be the bottleneck in your unittests.<br><br>Can you run lsof|grep PID|wc -l=
, where PID is the PID of your Python process, and make sure that process i=
tself isn't opening more than a dozen or so connections? What about with mo=
ngod's PID?<br><br>On Friday, October 5, 2012 2:11:19 PM UTC-7, Daniel Kado=
r wrote:<blockquote class=3D"gmail_quote" style=3D"margin:0;margin-left:0.8=
ex;border-left:1px #ccc solid;padding-left:1ex">Quick update - I believe I'=
ve ruled out file descriptors as the source of my problem. I wrote a =
small script that just repeatedly runs "lsof | wc -l" (which, as I understa=
nd it, should give me the number of open file descriptors on my system) and=
stores the results in a texfile. Before I launched any tests, my ope=
n file descriptor count hovered around 7,300. As I ran tests, the num=
ber fluctuated a bit, but never went above 7,405 and never went below 7,221=
. So it feels like I'm not blowing out the descriptor count anywhere.=
<div><br></div><div>I also verified that the tearDown methods in AsyncTestC=
ase and AsyncHTTPTestCase are being called on every test.</div><div><br></d=
iv><div>Some more details (not sure if they're useful or relevant, but I'm =
hoping they are): when I run tests my CPU gets pegged. One of my core=
s goes to about 90% and hovers there for the whole run. Also, I'm ove=
rriding get_new_ioloop() to return the singleton instance.</div><div><br></=
div><div>Jesse, question for you: do I need to explicitly close cursors ope=
ned by Motor? I'm pretty sure I don't need to do anything with the Co=
nnection object, but I couldn't find anything that told me my responsibilit=
y re: the cursor lifecycle.</div><div><br></div><div>Will keep digging in.<=
/div><div><br></div><div>Thanks again!</div><div><br></div><div>-Dan<br><br=
>On Friday, October 5, 2012 11:38:59 AM UTC-7, Daniel Kador wrote:<blockquo=
te class=3D"gmail_quote" style=3D"margin:0;margin-left:0.8ex;border-left:1p=
x #ccc solid;padding-left:1ex">Awesome, I was thinking along the same lines=
. I've seen this problem on both my local development platform (Mac) =
and my CI box (Ubuntu). I've looked into the file descriptor problem =
before and didn't come up with anything definitive, but I'll dig in more. &=
nbsp;Both Jesse's and Ben's suggestions sound like good places to start.<di=
v><br></div><div>I'm using MotorReplicaSetConnection. I don't create =
a new one per test, I have a single module-level connection reference. &nbs=
p;I've tried explicitly setting up the connection and then tearing it down =
on every test, which didn't make a noticeable difference (except to signifi=
cantly slow down my tests :P).</div><div><br></div><div>I'll dig in more an=
d report back. I don't /believe/ I'm forgetting to call super.tearDown(), b=
ut I'll double-check. If it's that simple I'll be relieved (and sligh=
tly embarrassed).</div><div><br></div><div>Thanks so much!</div><div><br></=
div><div>-Dan</div><div><br>On Thursday, October 4, 2012 11:23:11 PM UTC-7,=
A. Jesse Jiryu Davis wrote:<blockquote class=3D"gmail_quote" style=3D"marg=
in:0;margin-left:0.8ex;border-left:1px #ccc solid;padding-left:1ex">Agreed.=
Are you using MotorConnection or MotorReplicaSetConnection? Do you create =
a new connection per test? Does it help to call close() on that connection =
in tearDown() rather than simply relying on it to be garbage-collected when=
it's dereferenced?<br><br>On Thursday, October 4, 2012 8:53:31 PM UTC-7, B=
en Darnell wrote:<blockquote class=3D"gmail_quote" style=3D"margin:0;margin=
-left:0.8ex;border-left:1px #ccc solid;padding-left:1ex">This sounds like i=
t might be a file descriptor leak. Your tests might
<br>be opening sockets and not closing them, which would cause problems
<br>once you hit the file descriptor limit, which is relatively low by
<br>default on many platforms. Try increasing the limit by running "u=
name
<br>-n 10000" before running your tests (if you're on linux and the OS
<br>won't let you, try increasing the settings in
<br>/etc/security/limits.conf). If that works, then you're running ou=
t of
<br>file descriptors. Once you've confirmed the problem, a better
<br>long-term solution is to ensure that you're closing all the file
<br>descriptors you're opening. This includes sockets and regular fil=
es,
<br>as well as other file descriptors created by IOLoop and
<br>AsyncHTTPClient (could you be forgetting to call super.tearDown() in
<br>your tests?).
<br>
<br>-Ben
<br>
<br>On Thu, Oct 4, 2012 at 5:50 PM, Daniel Kador <<a>d...@keen.io</a>>=
; wrote:
<br>> Hi!
<br>>
<br>> I'm running into (what I perceive to be) a strange problem with my=
tests.
<br>> I've got an application written on top of Tornado that communicate=
s with
<br>> Mongo through the Motor library. It's humming away nicely in=
production
<br>> (daemonized using supervisord). The only problems (that I ca=
n detect) are
<br>> with my tests. I'm very happy to acknowledge that this could=
be a problem
<br>> in my application layer, or in the Motor layer, or maybe even in M=
ongoDB
<br>> itself - mostly I'm looking for some guidance as I'm not really su=
re where
<br>> to start digging in.
<br>>
<br>> But let me step back and describe what I've noticed in more detail=
.
<br>>
<br>> I have approximately ~150 tests that extend the
<br>> tornado.testing.<wbr>AsyncHTTPTestCase class, spread across a numb=
er of my own
<br>> classes. I have ~50 that are simple unit tests. They b=
oth communicate to
<br>> Mongo through Motor. The unit tests are fast and never fail =
(I mention this
<br>> only as a data point that may show Motor by itself may not be the =
culprit).
<br>> The AsyncHTTPTestCase tests all pass when their various test class=
es are run
<br>> individually.
<br>>
<br>> But when I run them all together, after about ~65 tests running an=
d passing,
<br>> I start getting timeouts in various spots. Sometimes it's wh=
en interacting
<br>> directly with Motor. Sometimes it's when making an async HTT=
P request to
<br>> one of the APIs I've created (which, under the covers, is talking =
to Mongo
<br>> through Motor). But it's always when calling (from a test) s=
elf.wait().
<br>>
<br>> It's getting to be a serious problem, as now I can't actually run =
all my
<br>> tests locally (at one time). Obviously not a recipe for test=
-driven
<br>> development success.
<br>>
<br>> I'm relatively sure I've done something stupid, but I haven't figu=
red out
<br>> where yet. Would really appreciate some help here.
<br>>
<br>> Thanks!
<br>>
<br>> -Dan
<br></blockquote></blockquote></div></blockquote></div></blockquote></block=
quote></blockquote></div></div></div></div></blockquote></div></div>
------=_Part_221_11670270.1349480696769--
------=_Part_220_27785369.1349480696769--
Message from discussion Timeouts in tests using Tornado + Motor
| Create a group - Google Groups - Google Home - Terms of Service - Privacy Policy |
| ©2013 Google |