jetty/actors performance question tangentially related to lift

[Lincoln]

Hi,

Currently I have a jetty webapp that uses continuations and actors to
scale to many connections. While this isn't a lift question per se I
was hoping the folks on this list could help since it's my
understanding that Lift does similar stuff under certain setups.

Basically, the functionality that I'm testing receives a request,
suspends it via jetty continuations, and fires it off to an actor for
processing. Once the work is done (some benchmark database requests,
usually on the order of 10 to 100ms) the continuation is resumed and
results are returned.

As I scale up to 1000+ concurrents in apache benchmark, I notice that
the vast majority of time from receipt of the request to response, is
between when the continuation is suspended and when my actor receives
the message. This strikes me as bizarre since I'm monitoring the
mailbox and it never grows to a size larger than 1 or 2. It gets to
the point where requests are taking 10 seconds to come back and 9.5 of
those seconds are my actor waiting to receive the work request.

Throughout the load test the database does not become stressed.

Any thoughts on this? I guess I'm hoping there is something basic
that I'm doing wrong. Just in case, I've tried creating an actor pool
to receive the work requests but that apparently has no effect on the
results.

My only speculation at this point is that perhaps the reason messages
are taking so long to get to my actor is because jetty itself is
overloaded trying to queue requests but that is just a guess.

Thanks,
Lincoln

[David Pollak]

If you have all your requests going to 1 actor, then you've reduced your application to a single threaded app.

If you're using Scala Actors, there are all kinds of wacky things that happen with the Fork-Join library that the Actors use for scheduling and a whole lot of knobs to turn to get the scheduling right depending on your number of CPUs, etc.

But, at the end of the day, if you're just pushing work from one thread (the thread that the HTTP request comes in on) to another thread (the thread that's waiting for the RDBMS request), you're not saving any time or threads, in fact you're only increasing the amount of thrash between scheduling the Actor, suspending the HTTP request thread, etc.

But, without seeing your code, it's hard to give you a better analysis.

--
Lift, the simply functional web framework http://liftweb.net
Beginning Scala http://www.apress.com/book/view/1430219890
Follow me: http://twitter.com/dpp
Surf the harmonics

[Lincoln]

Thanks for the feedback David... I have also created a pool of actors
and dispatch requests round-robin style to it. Oddly enough, I see
absolutely no difference in the performance characteristics - in both
cases 95% of the time is spent between the suspend and the actor
receiving the request, but the mailbox never grows past a size of 1 or
2. I will try and send along a simplified version of my code to
illustrate what I'm doing.

Thanks,
Lincoln

[Lincoln]

Hi, thank you very much for your help so far I really appreciate it.  Apologies in advance if this thread has become inappropriate since it's not directly related to Lift.  Just let me know if that's the case and I will attempt to solve this problem another way.  But, I'm hoping you can help me some more...

Warning: Long email ahead...

Here's the summary of my load testing results:

Each request in my load test consists of a single save() to mongodb, followed by a findOne() for the record just written and then an arbitrary find() for 1000 docs.

I've been experimenting with 3 scenarios:

1. A single actor processing all requests (this effectively makes things single-threaded)
2. A pool of 50 actors handling requests that are dispatched to via a round robin scheduler
3. Create a new actor on demand for every request.

The load I've been using for all tests is 2000 requests at a concurrency level of 75.  All the results I'm reporting are averages over 3 executions.

As a benchmark, I ran all these scenarios with the worker stubbed out to simply sleep for 100ms and then return.  Here are the results when I ran the benchmark:

• Single shared worker: 7534.439 ms
• Shared Pool of 50 workers: 156.190 ms
• On-demand actor for each request: 127.066 ms

These results are about what I expected.  In the single worker case the queue quickly backed up and stayed at 74 requests, thus the results were about the concurrency level (75) multiplied by the work length (100 ms).  The shared pool was obviously a huge improvement, but the actor on demand was even better because the concurrency level (75) was greater than the number of actors in the shared pool (50) and thus there was still some queueing in that case.

I expected when I ran the tests with the mongodb work plugged in that I would see results that were roughly proportional to the benchmark.  However, here's what I got:

• Single shared worker: 1968.113 ms
• Shared Pool of 50 workers: 1955.218 ms
• On-demand actor for each request: 1951.352 ms

For the vast majority of these requests, most of the time for the request is spent waiting for the actor to receive the work job.  This is the case regardless of whether I'm using a single actor, a pool, or creating actors on demand.  In most cases, the mongo work takes 0 - 100 ms but with a meaningful minority in the 100 - 300ms range.  I think this means the JVM must be busy with something else while that waiting is happening.

I guess it makes sense that the single-threaded case goes faster since most of the time the mongodb operations take far less than 100 ms.  However, I don't understand why I'm not seeing proportional improvement in the pooled and on-demand scenarios.

Here is the method I'm using to create my actors, whether it be 1, the pool of 50, or a new one on demand every time:

def worker(n: Int) = actor {

loop {

react {

case msg @ LoadReq(timer, stats, cont) =>

timer.split("react")

stats("mailboxSize") = mailboxSize.toLong

val coll = staticColl

val dbo = (

_msg -> "blah blah blah" <<

_event -> "blah blah blah" <<

_user -> "blah blah blah" <<

_name -> "Lincoln"

)

coll.save(dbo)

timer.split("save")

coll.findOne(_name -> "Lincoln")

timer.split("findOne")

val res = coll.find().limit(1000).toArray

timer.split("findAll")

// timer.split("sleep")

cont.setAttribute(Base.CONTINUATION_RESP, LoadResp(timer, stats))

cont.resume

case other => trace("worker discarded: "+other)

}

}

}

I took a kill -3 while my load test was running and I saw a lot of these:

"qtp1491907201-104" prio=5 tid=0x0000000102278800 nid=0x153199000 runnable [0x0000000153198000]

   java.lang.Thread.State: TIMED_WAITING (parking)

at sun.misc.Unsafe.park(Native Method)

- parking to wait for  <0x0000000108bca370> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)

at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)

at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1963)

at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:319)

at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:450)

at java.lang.Thread.run(Thread.java:637)

I also used jstat throughout:

Timestamp         S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT   

          161.8 100.00   0.00   0.00  68.15  60.18    102    9.215     2    0.022    9.237

          166.8 100.00   0.00  10.04  28.97  60.32    134   12.083     4    0.049   12.132

          171.8 100.00   0.00  60.79  68.23  60.06    172   14.904     4    0.049   14.952

          176.8   0.00 100.00 100.00   4.04  59.87    191   17.437     7    1.362   18.799

          181.8 100.00   0.00   2.12   4.56  59.88    196   18.363     8    1.712   20.075

          186.8 100.00   0.00   4.62   4.56  59.88    196   18.363     8    1.712   20.075

          191.8 100.00   0.00   4.65   4.56  59.88    196   18.363     8    1.712   20.075

Am I reading this correctly that it's basically doing a ridiculous amount of garbage collection?  If so, I would imagine that's what all my threads might be waiting on.

Do you have any suggestions for what I should try next?

Thanks,

Lincoln

[David Pollak]

This is getting off-topic.... but...

I think the issue is that there's a single connection or a single thread accessing MongoDB.  I'd suggest trying a connection pool to MongoDB or to otherwise see why the MongoDB stuff is not getting parallelized.

Also, Scala Actors do a lot of fancy stuff in terms of scheduling... you might want to try the same benchmarks with Lift Actors and see if there's a difference.

[Lincoln]

Thanks David, I will give Lift Actors a try. Mongodb is supposedly
using a connection pool behind the scenes so it isn't supposed to
matter whether I create 1 or many connection objects, but I will check
the source as I'm not 100% sure.

Thanks,
Lincoln

On Thu, Nov 12, 2009 at 8:05 PM, David Pollak