Freezing after comet rerender

Oleksandr Bezhan

unread,

Aug 22, 2013, 4:55:21 AM8/22/13

to lif...@googlegroups.com

Hi. I have comet actor named ProcessingMonitor on a page. Sometimes I observe freezing between rerender completion and changes being applied on the client.

Here is how looks my render method:

def render = {

val cssSel = "#id" #> ... & "#id2" #> ... & ...

(in: NodeSeq) => {

val start = System.currentTimeMillis()

val nodeSeq = cssSel(in)

val time = System.currentTimeMillis() - start

logger.debug(s"Rendering took ${time}ms")

nodeSeq

}

And when I click on a button reRender is invoked and I see that rendering took only 218ms. But the changes are applied after 50 seconds(!). This is what I see in logs:

CASE 1(several ajax requests:

2013-08-22 10:00:12,804 [pool-11-thread-4] DEBUG com.*.ProcessingMonitor - reRender()

2013-08-22 10:00:12,805 [qtp1877710376-54 - /ajax_request/F1229511276243HNMVEM-10/] INFO net.liftweb.util.TimeHelpers - Service request (POST) /ajax_request/F1229511276243HNMVEM-10/ returned 200, took 8 Milliseconds

2013-08-22 10:00:13,027 [pool-11-thread-4] DEBUG com.db.itrac.dashboard.comet.ProcessingMonitor - Rendering took 218ms

> //------ here is freezing from 10:00:13 to 10:01:03 ------///

2013-08-22 10:01:03,756 [qtp1877710376-61 - /ajax_request/F1229511237802JK1MRN/] INFO net.liftweb.util.TimeHelpers - Service request (POST) /ajax_request/F1229511237802JK1MRN/ returned 200, took 6 Milliseconds

2013-08-22 10:01:17,763 [qtp1877710376-58 - /comet_request/64713511592/1n8lavbmy16o9crytazmxwnd/F1229511237802JK1MRN?F1229511237803J1DGLL=1229511246201&_=1377154877745] INFO net.liftweb.util.TimeHelpers - Service request (GET) /comet

_request/64713511592/1n8lavbmy16o9crytazmxwnd/F1229511237802JK1MRN returned 0, took 4 Milliseconds

2013-08-22 10:01:24,774 [qtp1877710376-59 - /ajax_request/F1229511276243HNMVEM/] INFO net.liftweb.util.TimeHelpers - Service request (POST) /ajax_request/F1229511276243HNMVEM/ returned 200, took 4 Milliseconds

2013-08-22 10:02:01,770 [qtp1877710376-60 - /ajax_request/F1229511237697IFYQ1U/] INFO net.liftweb.util.TimeHelpers - Service request (POST) /ajax_request/F1229511237697IFYQ1U/ returned 200, took 5 Milliseconds

2013-08-22 10:02:19,766 [qtp1877710376-60 - /ajax_request/F1229511237802JK1MRN/] INFO net.liftweb.util.TimeHelpers - Service request (POST) /ajax_request/F1229511237802JK1MRN/ returned 200, took 7 Milliseconds

2013-08-22 10:02:40,764 [qtp1877710376-61 - /ajax_request/F1229511276243HNMVEM/] INFO net.liftweb.util.TimeHelpers - Service request (POST) /ajax_request/F1229511276243HNMVEM/ returned 200, took 4 Milliseconds

// here we have several ajax requests

CASE 2:

2013-08-22 11:03:39,001 [pool-11-thread-12] DEBUG com.*.ProcessingMonitor - reRender()

2013-08-22 11:03:39,003 [qtp569197316-57 - /ajax_request/F615114249711I2PLNY-k0/] INFO net.liftweb.util.TimeHelpers - Service request (POST) /ajax_request/F615114249711I2PLNY-k0/ returned 200, took 9 Milliseconds

2013-08-22 11:03:39,169 [pool-11-thread-12] DEBUG com.db.itrac.dashboard.comet.ProcessingMonitor - Rendering took 165ms

> //------ here is freezing from 11:03:39 to 11:03:49 ------///

> 2013-08-22 11:03:49,252 [qtp569197316-59 - /comet_request/10142751131/1rpulsafzvopczc22jzxyl932/F615114249711I2PLNY?F615114247718YC5EGR=615114250545&_=1377158629195] INFO net.liftweb.util.TimeHelpers - Service request (GET) /comet_request/10142751131/1rpulsafzvopczc22jzxyl932/F615114249711I2PLNY returned 0, took 2 Milliseconds

2013-08-22 11:03:49,414 [qtp569197316-57 - /comet_request/38890918809/1rpulsafzvopczc22jzxyl932/F615114249711I2PLNY?F615114247718YC5EGR=615114250571&_=1377158629401] INFO net.liftweb.util.TimeHelpers - Service request (GET) /comet_request/38890918809/1rpulsafzvopczc22jzxyl932/F615114249711I2PLNY returned 0, took 2 Milliseconds

2013-08-22 11:03:49,542 [qtp569197316-61 - /comet_request/60421149292/1rpulsafzvopczc22jzxyl932/F615114249711I2PLNY?F615114247718YC5EGR=615114250624&_=1377158629526] INFO net.liftweb.util.TimeHelpers - Service request (GET) /comet_request/60421149292/1rpulsafzvopczc22jzxyl932/F615114249711I2PLNY returned 0, took 2 Milliseconds

2013-08-22 11:03:52,093 [qtp569197316-61 - /comet_request/36007535946/1rpulsafzvopczc22jzxyl932/F615114249711I2PLNY?F615114247718YC5EGR=615114250631&_=1377158632076] INFO net.liftweb.util.TimeHelpers - Service request (GET) /comet_request/36007535946/1rpulsafzvopczc22jzxyl932/F615114249711I2PLNY returned 0, took 4 Milliseconds

// here we have several comet requests

You can see that there is freeze from 10:00:13 to 10:01:03

after these ajax requests being processed I eventually see changes applied on the client

I would also emphasize that this issue happens in 20% cases.

Am I doing something wrong way ? Did anybody get the same issue ?

Sometimes I also see in logs weird exception, probably it can help somehow(but maybe it's not related to the issue):

2013-08-22 11:00:42,854 [pool-11-thread-8] ERROR net.liftweb.http.provider.servlet.containers.Servlet30AsyncProvider - Servlet 3.0 Async: Couldn't resume thread

java.lang.NullPointerException

at org.eclipse.jetty.http.HttpGenerator.prepareBuffers(HttpGenerator.java:974)

at org.eclipse.jetty.http.HttpGenerator.flushBuffer(HttpGenerator.java:934)

at org.eclipse.jetty.http.AbstractGenerator.blockForOutput(AbstractGenerator.java:518)

at org.eclipse.jetty.http.AbstractGenerator.flush(AbstractGenerator.java:442)

at org.eclipse.jetty.server.HttpOutput.flush(HttpOutput.java:94)

at org.eclipse.jetty.server.AbstractHttpConnection$Output.flush(AbstractHttpConnection.java:1022)

at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:173)

at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:111)

at net.liftweb.http.LiftServlet.sendResponse(LiftServlet.scala:890)

at net.liftweb.http.provider.servlet.containers.Servlet30AsyncProvider.resume(Servlet30AsyncProvider.scala:114)

at net.liftweb.http.provider.servlet.HTTPRequestServlet.resume(HTTPRequestServlet.scala:163)

at net.liftweb.http.LiftServlet$$anonfun$17.apply(LiftServlet.scala:707)

at net.liftweb.http.LiftServlet$$anonfun$17.apply(LiftServlet.scala:706)

at net.liftweb.http.LiftServlet$ContinuationActor$$anonfun$messageHandler$1.applyOrElse(LiftServlet.scala:692)

at scala.runtime.AbstractPartialFunction$mcVL$sp.apply$mcVL$sp(AbstractPartialFunction.scala:33)

at scala.runtime.AbstractPartialFunction$mcVL$sp.apply(AbstractPartialFunction.scala:33)

at scala.runtime.AbstractPartialFunction$mcVL$sp.apply(AbstractPartialFunction.scala:25)

at net.liftweb.actor.LiftActor$class.execTranslate(LiftActor.scala:440)

at net.liftweb.http.LiftServlet$ContinuationActor.execTranslate(LiftServlet.scala:667)

at net.liftweb.actor.SpecializedLiftActor$class.liftedTree2$1(LiftActor.scala:288)

at net.liftweb.actor.SpecializedLiftActor$class.net$liftweb$actor$SpecializedLiftActor$$proc2(LiftActor.scala:287)

at net.liftweb.actor.SpecializedLiftActor$$anonfun$net$liftweb$actor$SpecializedLiftActor$$processMailbox$1.apply$mcV$sp(LiftActor.scala:210)

at net.liftweb.actor.SpecializedLiftActor$$anonfun$net$liftweb$actor$SpecializedLiftActor$$processMailbox$1.apply(LiftActor.scala:210)

at net.liftweb.actor.SpecializedLiftActor$class.around(LiftActor.scala:224)

at net.liftweb.http.LiftServlet$ContinuationActor.around(LiftServlet.scala:667)

at net.liftweb.actor.SpecializedLiftActor$class.net$liftweb$actor$SpecializedLiftActor$$processMailbox(LiftActor.scala:209)

at net.liftweb.actor.SpecializedLiftActor$$anonfun$2$$anonfun$apply$mcV$sp$1.apply$mcV$sp(LiftActor.scala:173)

at net.liftweb.actor.LAScheduler$$anonfun$9$$anon$2$$anon$3.run(LiftActor.scala:64)

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

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

Antonio Salazar Cardozo

unread,

Aug 22, 2013, 1:56:04 PM8/22/13

to lif...@googlegroups.com

Actors are scheduled in a thread pool as needed, and as resources are available.

At a glance, it seems like you may be using a container without continuation support, or perhaps that you're putting too much load on the container. Regardless, the issue is likely to be external to Lift.

Thanks,

Antonio

Diego Medina

unread,

Aug 22, 2013, 2:17:05 PM8/22/13

to Lift

also, what version of the container are you using? We used to see things like that on earlier jetty versions, 8.x and 9.x should be ok with lift 2.5.1 or later.

Also, it helps if you don't use reRender as much, and instead use partialUpdate. reREnder sends a lot more js code to the client, while partialUpdate can be more targeted.

Thanks

Diego

--
--
Lift, the simply functional web framework: http://liftweb.net
Code: http://github.com/lift
Discussion: http://groups.google.com/group/liftweb
Stuck? Help us help you: https://www.assembla.com/wiki/show/liftweb/Posting_example_code

---
You received this message because you are subscribed to the Google Groups "Lift" group.
To unsubscribe from this group and stop receiving emails from it, send an email to liftweb+u...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.

--
Diego Medina
Lift/Scala Developer
di...@fmpwizard.com
http://fmpwizard.telegr.am

Oleksandr Bezhan

unread,

Sep 23, 2013, 9:31:22 AM9/23/13

to lif...@googlegroups.com

1). I use Jetty 8

2). Partial update in my case is the same render written in javascript instead of CssSel, which requires more effort to maintain.

Четвер, 22 серпня 2013 р. 11:55:21 UTC+3 користувач Oleksandr Bezhan написав:

Oleksandr Bezhan

unread,

Sep 23, 2013, 9:46:16 AM9/23/13

to lif...@googlegroups.com

I tried to profile this case with visualvm and during "freeze time" there are only few threads in RUNNABLE state.

Here is one thread with jetty stack trace:

"qtp429738776-43 Selector0" prio=6 tid=0x0000000010e0f800 nid=0xe64 runnable [0x0000000013c9f000]

java.lang.Thread.State: RUNNABLE

at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method)

at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:295)

at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:277)

at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:158)

at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:87)

- locked <0x00000000c25b9a18> (a sun.nio.ch.Util$2)

- locked <0x00000000c25b9a08> (a java.util.Collections$UnmodifiableSet)

- locked <0x00000000c25b3260> (a sun.nio.ch.WindowsSelectorImpl)

at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:98)

at org.eclipse.jetty.io.nio.SelectorManager$SelectSet.doSelect(SelectorManager.java:564)

at org.eclipse.jetty.io.nio.SelectorManager$1.run(SelectorManager.java:285)

at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:603)

at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:538)

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

Locked ownable synchronizers:

- None

What is interesting is that there is another one thread(zookeeper) which stands in the same place:

"pool-6-thread-5-SendThread(127.0.0.1:2181)" daemon prio=6 tid=0x0000000010e0c800 nid=0xa3c runnable [0x000000001545e000]

java.lang.Thread.State: RUNNABLE

at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method)

at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:295)

at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:277)

at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:158)

at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:87)

- locked <0x00000000c226cba8> (a sun.nio.ch.Util$2)

- locked <0x00000000c226cb98> (a java.util.Collections$UnmodifiableSet)

- locked <0x00000000c226c6b0> (a sun.nio.ch.WindowsSelectorImpl)

at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:98)

at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:338)

at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1068)

Locked ownable synchronizers:

- None

As you can see both threads stay in the same native method. Probably this can cause the issue ?

And finally no lift code is running in any thread during the "freeze time", so I suppose it's not Lift's issue.

Четвер, 22 серпня 2013 р. 11:55:21 UTC+3 користувач Oleksandr Bezhan написав:

Hi. I have comet actor named ProcessingMonitor on a page. Sometimes I observe freezing between rerender completion and changes being applied on the client.

Antonio Salazar Cardozo

unread,

Sep 23, 2013, 1:28:16 PM9/23/13

to lif...@googlegroups.com

If things are freezing, you're more interested in the threads that aren't runnable than in the ones that are.