I tried to see if a smaller heap has an impact on the slowdown problem: it seems to have but not in the expected direction, with -Xmx200m I succesfully perfomed already 8'3200'000 requests without degradation of the performance (time per requests at around 450ms).
puzzling.... reto On Fri, Oct 29, 2010 at 8:22 AM, Reto Bachmann-Gmuer < [email protected]> wrote: > after adding an ssp I observe a strange slowdow: after round 98 (i.e. > 980000 requests) it becomes 5 time slower > > for i in `seq 1000`; do echo round $i; ab -n 10000 -H "Accept: > application/xhtml+xml" -c 100 -A admin:admin > http://localhost:8080/greeting/list; done > > Round 1: Time per request: 520.207 [ms] (mean) > Round 2: Time per request: 395.147 [ms] (mean) > ... > Round 96: Time per request: 394.507 [ms] (mean) > Round 97: Time per request: 567.768 [ms] (mean) > Round 98: Time per request: 558.511 [ms] (mean) > Round 99: Time per request: 2662.950 [ms] (mean) > Round 100: Time per request: 2839.969 [ms] (mean) > Round 101: Time per request: 2928.085 [ms] (mean) > Round 102: Time per request: 2934.582 [ms] (mean) > Round 103: Time per request: 3008.430 [ms] (mean) > Round 104: Time per request: 2957.012 [ms] (mean) > Round 105: Time per request: 3012.764 [ms] (mean) > Round 106: Time per request: 3569.310 [ms] (mean) > Round 107: Time per request: 3915.529 [ms] (mean) > > > On the console I see aroung 1000 logs like this > > [qtp476205266-19 - Acceptor0 [email protected]:8080] WARN > org.eclipse.jetty.util.log - EXCEPTION > java.io.IOException: Too many open files > at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method) > at > sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:163) > at > org.eclipse.jetty.server.nio.SelectChannelConnector$1.acceptChannel(SelectChannelConnector.java:74) > at > org.eclipse.jetty.io.nio.SelectorManager$SelectSet.doSelect(SelectorManager.java:650) > at > org.eclipse.jetty.io.nio.SelectorManager.doSelect(SelectorManager.java:195) > at > org.eclipse.jetty.server.nio.SelectChannelConnector.accept(SelectChannelConnector.java:134) > at > org.eclipse.jetty.server.AbstractConnector$Acceptor.run(AbstractConnector.java:793) > at > org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:436) > at java.lang.Thread.run(Thread.java:636) > > There are two open sockets, and 256 open files in the tdb-data directory > > Repeating the experiment, the speed is quite constant till round 97 and > then starts to decrease massively. > > 95 Time per request: 533.913 [ms] (mean) > 96 Time per request: 377.717 [ms] (mean) > 97 Time per request: 541.047 [ms] (mean) > 98 Time per request: 1429.697 [ms] (mean) > 99 Time per request: 2693.674 [ms] (mean) > 100 Time per request: 2763.258 [ms] (mean) > 101 Time per request: 2857.210 [ms] (mean) > 102 Time per request: 2898.990 [ms] (mean) > 103 Time per request: 2932.736 [ms] (mean) > 104 Time per request: 3014.051 [ms] (mean) > 105 Time per request: 3325.968 [ms] (mean) > 106 Time per request: 4154.931 [ms] (mean) > 107 Time per request: 3938.169 [ms] (mean) > 108 Time per request: 4004.883 [ms] (mean) > 109 Time per request: 4181.464 [ms] (mean) > 110 Time per request: 4317.757 [ms] (mean) > 111 Time per request: 4535.995 [ms] (mean) > 112 Time per request: 4695.218 [ms] (mean) > 113 Time per request: 4900.455 [ms] (mean) > 114 Time per request: 5161.572 [ms] (mean) > 115 Time per request: 5372.835 [ms] (mean) > 116 Time per request: 5680.455 [ms] (mean) > 117 Time per request: 5965.081 [ms] (mean) > 118 Time per request: 6291.290 [ms] (mean) > 119 Time per request: 6668.914 [ms] (mean) > 120 Time per request: 7074.508 [ms] (mean) > 121 Time per request: 7546.811 [ms] (mean) > 122 Time per request: 8095.533 [ms] (mean) > 123 Time per request: 8619.783 [ms] (mean) > 124 Time per request: 9317.463 [ms] (mean) > 125 Time per request: 10131.045 [ms] (mean) > 126 Time per request: 11079.445 [ms] (mean) > 127 Time per request: 12146.688 [ms] (mean) > 128 Time per request: 13516.644 [ms] (mean) > 129 Time per request: 15219.902 [ms] (mean) > 130 Time per request: 17367.628 [ms] (mean) > 131 Time per request: 20243.487 [ms] (mean) > 132 Time per request: 24319.549 [ms] (mean) > 133 Time per request: 30387.020 [ms] (mean) > > No "Too many open files" logs this time, instead two logs about exceptions > caused by "java.io.IOException: Broken pipe". > > > Reto > > > > On Thu, Oct 28, 2010 at 7:58 PM, Reto Bachmann-Gmuer < > [email protected]> wrote: > >> Still investigating on the situation where Clerezza doesn'tswllo stress >> test. Today it passed the following 10 millions triples challenge: >> >> Setting: >> - 100 concurrent threads >> - 1000 * 10000 requests >> - requested media-type: application/rdf+xml >> >> generating resource method: >> @GET >> public GraphNode list() { >> TripleCollection resultGraph = new SimpleMGraph(); >> GraphNode result = new GraphNode(new BNode(), resultGraph); >> RdfList list = new RdfList(result); >> LockableMGraph contentGraph = cgProvider.getContentGraph(); >> Lock l = contentGraph.getLock().readLock(); >> l.lock(); >> try { >> Iterator<Triple> greetings = contentGraph.filter(null, >> RDF.type, GREETINGS.Greeting); >> while (greetings.hasNext()) { >> list.add(greetings.next().getSubject()); >> } >> } finally { >> l.unlock(); >> } >> return result; >> } >> >> Data: >> - 2 resources of type GREETINGS.Greeting >> >> Result: >> For every block of 10000 requests the following is true: >> - 90% of the requests where answered in less than 161 ms >> - 50% of all requests where answered in less than 58 ms >> - the longest request took between 15687 and 3105 ms >> - mean time between 109 and 221 ms >> - No requests failed >> >> No rocket science statistics, but it gives an idea. >> >> A next step is to add an ssp. >> >> Reto >> >> >
