Re: [jetty-users] Load testing slowness

[Jeff Segal <jeffrey.segal@xxxxxxxxx>]

Thanks Simone,

I enabled GC logging but this does not appear to be the cause. What I see in yourkit is that at a certain point into the test (after each of 5 nodes has spun up roughly 200 clients), the QTP threads start to block for a few seconds but clear later. This will continue for another minute or two, but eventually some conditions hits which causes all of the threads to stay blocked for 10-15 seconds at a time. Here are a few screenshots illustrating this:

Start of intermittent blocking: https://picasaweb.google.com/108087217805057830230/JettyProfile#5823701712648951026

Start of persistent blocking: https://picasaweb.google.com/108087217805057830230/JettyProfile#5823701715706059762

Sustained blocking: https://picasaweb.google.com/108087217805057830230/JettyProfile#5823701715591108450

As of this writing, I'm 20+ minutes past the end of the test and all the QTP threads remain in this state. Any other suggestions?

Here's the GC output covering the duration of the test (all between 0.1 and 0.2 seconds):

[GC 233496K->51548K(2070976K), 0.1909560 secs]

[GC 261340K->84619K(2070976K), 0.1467500 secs]

[GC 294411K->116745K(2070976K), 0.1408370 secs]

[GC 326537K->149294K(2070976K), 0.1053940 secs]

[GC 359086K->183532K(2070976K), 0.1406730 secs]

[GC 393324K->216449K(2070976K), 0.1027050 secs]

[GC 426241K->239929K(2070976K), 0.1023870 secs]

[GC 449721K->268750K(2070976K), 0.1210010 secs]

[GC 478542K->295231K(2070976K), 0.1122760 secs]

[GC 505023K->318765K(2070976K), 0.1059800 secs]

[GC 528557K->328292K(2070976K), 0.1304450 secs]

[GC 538084K->330614K(2070976K), 0.1110400 secs]

[GC 540406K->341456K(2070976K), 0.1234400 secs]

[GC 551248K->364941K(2070976K), 0.1552520 secs]

[GC 574733K->375288K(2070976K), 0.1211520 secs]

[GC 585080K->381414K(2070976K), 0.0869230 secs]

[GC 591206K->394076K(2070976K), 0.1192360 secs]

[GC 603868K->398872K(2070976K), 0.1259990 secs]

[GC 608664K->409684K(2070976K), 0.1199040 secs]

[GC 619476K->424394K(2070976K), 0.1241920 secs]

[GC 634186K->428971K(2070976K), 0.1151850 secs]

[GC 638763K->439776K(2070976K), 0.0845890 secs]

[GC 649568K->444960K(2070976K), 0.1323840 secs]

[GC 654752K->450064K(2070976K), 0.0983950 secs]

[GC 659856K->457175K(2070976K), 0.1289700 secs]

[GC 666967K->469089K(2070976K), 0.1485190 secs]

[GC 678881K->474470K(2070976K), 0.1070250 secs]

[GC 684262K->483294K(2070976K), 0.1161370 secs]

[GC 693086K->491008K(2070976K), 0.1207690 secs]

[GC 700800K->500115K(2070976K), 0.1093950 secs]

[GC 709907K->507427K(2070976K), 0.1323990 secs]

[GC 717219K->514780K(2070976K), 0.1030080 secs]

[GC 724572K->522918K(2070976K), 0.1398910 secs]

[GC 732710K->530294K(2070976K), 0.1499300 secs]

[GC 740086K->538759K(2070976K), 0.1240330 secs]

[GC 748550K->546814K(2070976K), 0.1199430 secs]

[GC 756606K->554707K(2070976K), 0.1238880 secs]

Jeff

On Wed, Dec 19, 2012 at 9:46 AM, Jeff Segal <jeffrey.segal@xxxxxxxxx> wrote:

I am load testing a Cometd app deployed to Jetty 8.1.3.v20120416. What I find occasionally, but not always, is that the handshake process is extremely slow (~15-20s per client instead of 100ms).

Looking at a thread dump, I see that the vast majority of QTP threads in the following state:

"qtp1870207216-70" prio=10 tid=0x00007fa35419b800 nid=0x7924 waiting for monitor entry [0x00007fa349fe2000]

   java.lang.Thread.State: BLOCKED (on object monitor)

        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:568)

        - waiting to lock <0x0000000780398e50> (a org.eclipse.jetty.servlet.ServletHolder)

        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1367)

        at org.eclipse.jetty.servlets.CrossOriginFilter.handle(CrossOriginFilter.java:212)

        at org.eclipse.jetty.servlets.CrossOriginFilter.doFilter(CrossOriginFilter.java:179)

        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1338)

Looking at the source at http://grepcode.com/file/repo1.maven.org/maven2/org.eclipse.jetty/jetty-servlet/8.1.3.v20120416/org/eclipse/jetty/servlet/ServletHolder.java?av=f#568, I see that all of these threads are waiting on the instance of ServletHolder, but I don't see why getServlet() would be running so slow or blocked by a lack of OS resources. But maybe I'm missing something?

Thanks,

Jeff