Re: No statistics/results for test
Darren Ball <[email protected]> Mon, 14 Sep 2015 13:36:19 -0400
| Newsgroups | gmane.comp.java.grinder.user |
|---|---|
| Message-ID | <CA+YPNheJxpptu4gwgv0r5UAQ1OMt4kkqXLtv3OuoVkjPUBOUPA@mail.gmail.com> |
I can also see this behaviour on the agent side : [grinder@ip-10-82-151-65 150914]$ netstat -an | grep 6372 tcp 0 0 10.82.151.65:55588 10.82.151.16:6372 ESTABLISHED [grinder@ip-10-82-151-65 150914]$ netstat -an | grep 6372 tcp 0 0 10.82.151.65:55588 10.82.151.16:6372 ESTABLISHED [grinder@ip-10-82-151-65 150914]$ netstat -an | grep 637 tcp 0 0 10.82.151.65:55588 10.82.151.16:6372 ESTABLISHED [grinder@ip-10-82-151-65 150914]$ netstat -an | grep 637 tcp 0 0 10.82.151.65:55588 10.82.151.16:6372 ESTABLISHED tcp 0 0 10.82.151.65:55592 10.82.151.16:6372 ESTABLISHED [grinder@ip-10-82-151-65 150914]$ netstat -an | grep 637 tcp 0 0 10.82.151.65:55588 10.82.151.16:6372 ESTABLISHED tcp 0 0 10.82.151.65:55592 10.82.151.16:6372 ESTABLISHED [grinder@ip-10-82-151-65 150914]$ netstat -an | grep 637 tcp 0 0 10.82.151.65:55588 10.82.151.16:6372 ESTABLISHED tcp 0 0 10.82.151.65:55592 10.82.151.16:6372 ESTABLISHED [grinder@ip-10-82-151-65 150914]$ netstat -an | grep 637 tcp 0 0 10.82.151.65:55588 10.82.151.16:6372 ESTABLISHED tcp 0 0 10.82.151.65:55592 10.82.151.16:6372 ESTABLISHED [grinder@ip-10-82-151-65 150914]$ netstat -an | grep 637 tcp 0 0 10.82.151.65:55588 10.82.151.16:6372 ESTABLISHED tcp 0 0 10.82.151.65:55592 10.82.151.16:6372 ESTABLISHED [grinder@ip-10-82-151-65 150914]$ netstat -an | grep 637 tcp 0 0 10.82.151.65:55588 10.82.151.16:6372 ESTABLISHED tcp 0 0 10.82.151.65:55592 10.82.151.16:6372 ESTABLISHED [grinder@ip-10-82-151-65 150914]$ netstat -an | grep 637 tcp 0 0 10.82.151.65:55588 10.82.151.16:6372 ESTABLISHED tcp 0 0 10.82.151.65:55592 10.82.151.16:6372 ESTABLISHED [grinder@ip-10-82-151-65 150914]$ netstat -an | grep 637 tcp 0 0 10.82.151.65:55588 10.82.151.16:6372 ESTABLISHED tcp 73 0 10.82.151.65:55592 10.82.151.16:6372 CLOSE_WAIT [grinder@ip-10-82-151-65 150914]$ netstat -an | grep 637 tcp 0 0 10.82.151.65:55588 10.82.151.16:6372 ESTABLISHED tcp 73 0 10.82.151.65:55592 10.82.151.16:6372 CLOSE_WAIT [grinder@ip-10-82-151-65 150914]$ netstat -an | grep 637 tcp 0 0 10.82.151.65:55588 10.82.151.16:6372 ESTABLISHED tcp 73 0 10.82.151.65:55592 10.82.151.16:6372 CLOSE_WAIT [grinder@ip-10-82-151-65 150914]$ netstat -an | grep 637 tcp 0 0 10.82.151.65:55588 10.82.151.16:6372 ESTABLISHED tcp 73 0 10.82.151.65:55592 10.82.151.16:6372 CLOSE_WAIT [grinder@ip-10-82-151-65 150914]$ netstat -an | grep 637 tcp 0 0 10.82.151.65:55588 10.82.151.16:6372 ESTABLISHED tcp 73 0 10.82.151.65:55592 10.82.151.16:6372 CLOSE_WAIT [grinder@ip-10-82-151-65 150914]$ netstat -an | grep 637 tcp 0 0 10.82.151.65:55588 10.82.151.16:6372 ESTABLISHED tcp 73 0 10.82.151.65:55592 10.82.151.16:6372 CLOSE_WAIT [grinder@ip-10-82-151-65 150914]$ netstat -an | grep 637 tcp 0 0 10.82.151.65:55588 10.82.151.16:6372 ESTABLISHED tcp 73 0 10.82.151.65:55592 10.82.151.16:6372 CLOSE_WAIT [grinder@ip-10-82-151-65 150914]$ netstat -an | grep 637 tcp 0 0 10.82.151.65:55588 10.82.151.16:6372 ESTABLISHED tcp 73 0 10.82.151.65:55592 10.82.151.16:6372 CLOSE_WAIT On Mon, Sep 14, 2015 at 12:15 PM, Darren Ball <[email protected]> wrote: > Ok - so this is a little concerning. > > I get this error for a specific test. Short running tests that have > little initialization work fine. > It typically happens as soon as the starting threads message occurs. > > My test has a long period of initialization (above the TestRunner class > declaration). > > Here is what the code looks like: > > from net.grinder.script import Test > from net.grinder.script.Grinder import grinder > from com.myapp.api.controllers.perf.app import CreateAppPerf > import java.lang.System, java.util.Random > > # App under test can be processed via JVM arguments or simply via the properites file. To inflate an app, realmid and appid are required > realmId = grinder.getProperties().getProperty("grinder.realmid") > appId = grinder.getProperties().getProperty("grinder.appid") > > g_Weights = { > 'CREATE': grinder.getProperties().getProperty("grinder.createweight"), # 2 > 'READ' : grinder.getProperties().getProperty("grinder.readweight"), # 4 > 'UPDATE': grinder.getProperties().getProperty("grinder.updateweight"), # 3 > 'PATCH': grinder.getProperties().getProperty("grinder.patchweight"), # 3 > 'REPLACE': grinder.getProperties().getProperty("grinder.replaceweight"), # 3 > 'DELETE': grinder.getProperties().getProperty("grinder.deleteweight"), # 1 > 'BULKADD': grinder.getProperties().getProperty("grinder.bulkaddweight"), # 1 > } > > bulkrecordcnt = grinder.getProperties().getProperty("grinder.bulkrecordcnt") > > cscAppPerf = CreateAppPerf() > cscAppPerf.initialize(realmId, appId) > > g_rng = java.util.Random(java.lang.System.currentTimeMillis()) > > > # Random number generator based on distribution numbers > def randNum(i_min, i_max): > assert i_min <= i_max > range = i_max - i_min + 1 # re-purposing "range" is legal in Python > assert range <= 0x7fffffff # because we're using java.util.Random > randnum = i_min + g_rng.nextInt(range) > assert i_min <= randnum <= i_max > return randnum > > def weightAccumulator(i_dict): > keyList = i_dict.keys() > keyList.sort() > listAcc = [] > weightAcc = 0 > for key in keyList: > weightAcc += int(i_dict[key]) > listAcc.append((key, weightAcc)) > return (listAcc, weightAcc) > > tests = { > "addRecordTest" : Test(1, "Add record test"), > "retrieveAllRecordsTableTest" : Test(2, "Retrieve all records (table) test"), > "retrieveTableReportTest" : Test(3, "Retrieve table report test"), > "listTablesTest" : Test(4, "List all tables test"), > "deleteRecordTest" : Test(5, "Delete Record Test"), > "getRecordTest" : Test(6, "Get single record test"), > "replaceRecordTest" : Test(7, "Replace single record test"), > "updateRecordTest" : Test(8, "Update single record test"), > "bulkAddRecordTest" : Test(9, "Bulk add records test"), > > } > > # Calculate weights and maximums > g_WeightsAcc, g_WeightsAccMax = weightAccumulator(g_Weights) > g_WeightsAccLen, g_WeightsAccMax_1 = len(g_WeightsAcc), g_WeightsAccMax-1 > > # Instrumentation for recording metrices - each call is recorded > tests["addRecordTest"].record(cscAppPerf.perfAddTableRecord) > tests["retrieveAllRecordsTableTest"].record(cscAppPerf.perfRetrieveTable) > tests["retrieveTableReportTest"].record(cscAppPerf.perfRetrieveReport) > tests["listTablesTest"].record(cscAppPerf.perfListTables) > tests["deleteRecordTest"].record(cscAppPerf.perfDeleteTableRecord) > tests["getRecordTest"].record(cscAppPerf.perfGetTableRecord) > tests["replaceRecordTest"].record(cscAppPerf.perfReplaceTableRecord) > tests["updateRecordTest"].record(cscAppPerf.perfUpdateTableRecord) > tests["bulkAddRecordTest"].record(cscAppPerf.perfAddBulkTableRecord) > > > log = grinder.logger.info > log("REALMID: %s" % realmId) > log("APPID: %s" % appId) > > class TestRunner: > def __init__(self): > log("Worker process initializing") > > def initialSleep( self): > sleepTime = grinder.threadNumber * 3000 # 3 seconds per thread > grinder.sleep(sleepTime, 0) > log("initial sleep complete, slept for around %d ms" % sleepTime) > > def __call__(self): > if grinder.runNumber == 0: self.initialSleep() > opNum = randNum(0, g_WeightsAccMax_1) > opType = None # flag for assertion below > for i in range(g_WeightsAccLen): > if opNum < g_WeightsAcc[i][1]: > opType = g_WeightsAcc[i][0] > break > assert opType in g_Weights.keys() > > if opType=='CREATE': self.addRecordTest() > elif opType=='BULKADD' : self.addBulkRecordTest() > elif opType=='READ' : self.retrieveAllRecordsTableTest() > elif opType=='UPDATE': self.listTablesTest() > elif opType=='PATCH': self.updateRecordTest() > elif opType=='REPLACE': self.replaceRecordTest() > elif opType=='DELETE': self.listTablesTest() > else : assert False > > def addRecordTest(self): > log('Doing add record test ...') > tableid = cscAppPerf.getRandomAppTableID(); > recordId = cscAppPerf.perfAddTableRecord(tableid) > cscAppPerf.perfGetTableRecord(tableid,recordId) > cscAppPerf.perfDeleteTableRecord(tableid,recordId) > > def addBulkRecordTest(self): > tableid = cscAppPerf.getRandomAppTableID(); > cscAppPerf.perfAddBulkTableRecord(tableid, bulkrecordcnt) > > def replaceRecordTest(self): > tableid = cscAppPerf.getRandomAppTableID(); > cscAppPerf.perfReplaceTableRecord(tableid) > > def updateRecordTest(self): > tableid = cscAppPerf.getRandomAppTableID(); > cscAppPerf.perfUpdateTableRecord(tableid) > > def retrieveAllRecordsTableTest(self): > tableid = cscAppPerf.getRandomAppTableID(); > cscAppPerf.perfRetrieveTable(tableid) > cscAppPerf.perfRetrieveReport(tableid); > > def listTablesTest(self): > cscAppPerf.perfListTables() > > > Excuse the mess of the code - but it is in progress. I've remove the > logging statements for clarity. > > The total time to call cscAppPerf.initialize(realmId, appId) takes > anywhere from 1.5 minutes to up to 30 minutes potentially. > It is only tests in which I have this weight period does the following > Report to console error occur: > > Logging: > > {"timestamp":"2015-09-14T16:04:51.806+00:00","logger":"i-20ff63e6-0","thread":"main","level":"INFO","HOSTNAME":"ip-10-82-151-65.localdomain","WORKER_NAME":"i-20ff63e6-0","LOG_DIRECTORY":"/var/log/qbase/150914","message":"starting > threads"} > > {"timestamp":"2015-09-14T16:04:51.860+00:00","logger":"i-20ff63e6-0","thread":"main","level":"INFO","HOSTNAME":"ip-10-82-151-65.localdomain","WORKER_NAME":"i-20ff63e6-0","LOG_DIRECTORY":"/var/log/qbase/150914","message":"Report > to console > failed","stack_trace":"net.grinder.communication.CommunicationException: > Exception whilst sending message\n\tat > net.grinder.communication.AbstractSender.send(AbstractSender.java:57) > ~[grinder-core-3.11.jar:na]\n\tat > net.grinder.communication.QueuedSenderDecorator.flush(QueuedSenderDecorator.java:60) > ~[grinder-core-3.11.jar:na]\n\tat > net.grinder.engine.process.GrinderProcess.sendStatusMessage(GrinderProcess.java:638) > [grinder-core-3.11.jar:na]\n\tat > net.grinder.engine.process.GrinderProcess.access$1100(GrinderProcess.java:110) > [grinder-core-3.11.jar:na]\n\tat > net.grinder.engine.process.GrinderProcess$ReportToConsoleTimerTask.run(GrinderProcess.java:615) > ~[grinder-core-3.11.jar:na]\n\tat > net.grinder.engine.process.GrinderProcess.run(GrinderProcess.java:465) > [grinder-core-3.11.jar:na]\n\tat > net.grinder.engine.process.WorkerProcessEntryPoint.run(WorkerProcessEntryPoint.java:86) > [grinder-core-3.11.jar:na]\n\tat > net.grinder.engine.process.WorkerProcessEntryPoint.main(WorkerProcessEntryPoint.java:59) > [grinder-core-3.11.jar:na]\nCaused by: java.net.SocketException: Broken > pipe\n\tat java.net.SocketOutputStream.socketWrite0(Native Method) > ~[na:1.8.0_40]\n\tat > java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109) > ~[na:1.8.0_40]\n\tat > java.net.SocketOutputStream.write(SocketOutputStream.java:153) > ~[na:1.8.0_40]\n\tat > java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82) > ~[na:1.8.0_40]\n\tat > java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140) > ~[na:1.8.0_40]\n\tat > java.io.ObjectOutputStream$BlockDataOutputStream.flush(ObjectOutputStream.java:1823) > ~[na:1.8.0_40]\n\tat > java.io.ObjectOutputStream.flush(ObjectOutputStream.java:719) > ~[na:1.8.0_40]\n\tat > net.grinder.communication.AbstractSender.writeMessageToStream(AbstractSender.java:90) > ~[grinder-core-3.11.jar:na]\n\tat > net.grinder.communication.StreamSender.writeMessage(StreamSender.java:70) > ~[grinder-core-3.11.jar:na]\n\tat > net.grinder.communication.AbstractSender.send(AbstractSender.java:53) > ~[grinder-core-3.11.jar:na]\n\t... 7 common frames omitted\n"} > > .... > > > {"timestamp":"2015-09-14T16:05:08.629+00:00","logger":"i-20ff63e6-0","thread":"main","level":"INFO","HOSTNAME":"ip-10-82-151-65.localdomain","WORKER_NAME":"i-20ff63e6-0","LOG_DIRECTORY":"/var/log/qbase/150914","message":"finished"} > > On Mon, Sep 14, 2015 at 10:30 AM, Darren Ball <[email protected]> > wrote: > >> Looks like I am having issues reporting to console: >> >> {"timestamp":"2015-09-14T14:27:07.369+00:00","logger":"i-20ff63e6-0","thread":"main","level":"INFO","HOSTNAME":"ip-10-82-151-65.localdomain","WORKER_NAME":"i-20ff63e6-0","LOG_DIRECTORY":"/var/log/qbase/150914","message":"Report >> to console >> failed","stack_trace":"net.grinder.communication.CommunicationException: >> Exception whilst sending message\n\tat >> net.grinder.communication.AbstractSender.send(AbstractSender.java:57) >> ~[grinder-core-3.11.jar:na]\n\tat >> net.grinder.communication.QueuedSenderDecorator.flush(QueuedSenderDecorator.java:60) >> ~[grinder-core-3.11.jar:na]\n\tat >> net.grinder.engine.process.GrinderProcess.sendStatusMessage(GrinderProcess.java:638) >> [grinder-core-3.11.jar:na]\n\tat >> net.grinder.engine.process.GrinderProcess.access$1100(GrinderProcess.java:110) >> [grinder-core-3.11.jar:na]\n\tat >> net.grinder.engine.process.GrinderProcess$ReportToConsoleTimerTask.run(GrinderProcess.java:615) >> ~[grinder-core-3.11.jar:na]\n\tat >> net.grinder.engine.process.GrinderProcess.run(GrinderProcess.java:465) >> [grinder-core-3.11.jar:na]\n\tat >> net.grinder.engine.process.WorkerProcessEntryPoint.run(WorkerProcessEntryPoint.java:86) >> [grinder-core-3.11.jar:na]\n\tat >> net.grinder.engine.process.WorkerProcessEntryPoint.main(WorkerProcessEntryPoint.java:59) >> [grinder-core-3.11.jar:na]\nCaused by: java.net.SocketException: Broken >> pipe\n\tat java.net.SocketOutputStream.socketWrite0(Native Method) >> ~[na:1.8.0_40]\n\tat >> java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109) >> ~[na:1.8.0_40]\n\tat >> java.net.SocketOutputStream.write(SocketOutputStream.java:153) >> ~[na:1.8.0_40]\n\tat >> java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82) >> ~[na:1.8.0_40]\n\tat >> java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140) >> ~[na:1.8.0_40]\n\tat >> java.io.ObjectOutputStream$BlockDataOutputStream.flush(ObjectOutputStream.java:1823) >> ~[na:1.8.0_40]\n\tat >> java.io.ObjectOutputStream.flush(ObjectOutputStream.java:719) >> ~[na:1.8.0_40]\n\tat >> net.grinder.communication.AbstractSender.writeMessageToStream(AbstractSender.java:90) >> ~[grinder-core-3.11.jar:na]\n\tat >> net.grinder.communication.StreamSender.writeMessage(StreamSender.java:70) >> ~[grinder-core-3.11.jar:na]\n\tat >> net.grinder.communication.AbstractSender.send(AbstractSender.java:53) >> ~[grinder-core-3.11.jar:na]\n\t... 7 common frames omitted\n"} >> >> >> Looks like the ports are up on the console side : >> >> [grinder@ip-10-82-151-16 ~]$ netstat -an | grep 637 >> >> tcp 0 0 0.0.0.0:6372 0.0.0.0:* >> LISTEN >> tcp 0 0 127.0.0.1:6373 0.0.0.0:* >> LISTEN >> tcp 0 0 127.0.0.1:58492 127.0.0.1:6373 >> TIME_WAIT >> tcp 0 0 127.0.0.1:58488 127.0.0.1:6373 >> TIME_WAIT >> tcp 0 0 127.0.0.1:58489 127.0.0.1:6373 >> TIME_WAIT >> tcp 0 0 10.82.151.16:6372 10.82.151.65:51017 >> ESTABLISHED >> tcp 0 0 127.0.0.1:58487 127.0.0.1:6373 >> TIME_WAIT >> tcp 0 0 127.0.0.1:58490 127.0.0.1:6373 >> TIME_WAIT >> tcp 0 0 127.0.0.1:58491 127.0.0.1:6373 >> TIME_WAIT >> >> Any clues - anyone? >> >> On Fri, Sep 11, 2015 at 3:20 PM, Darren Ball <[email protected]> >> wrote: >> >>> >>> I recently am seeing the following happening: >>> I run a series of test runs (100). >>> >>> My data log contains results for all 100 runs (0-99) >>> >>> [grinder@ip-10-82-151-65 150911]$ more i-20ff63e6-1-data.log >>> >>> Thread, Run, Test, Start time (ms since Epoch), Test time, Errors >>> 0, 0, 8, 1441998741194, 166, 0 >>> 0, 1, 7, 1441998741363, 151, 0 >>> 0, 2, 4, 1441998741515, 56, 0 >>> 0, 3, 2, 1441998741573, 219, 0 >>> 0, 3, 3, 1441998741792, 68, 0 >>> ... >>> >>> 0, 96, 4, 1441998815931, 43, 0 >>> 0, 97, 7, 1441998815975, 156, 0 >>> 0, 98, 2, 1441998816131, 3928, 0 >>> 0, 98, 3, 1441998820059, 41, 0 >>> 0, 99, 4, 1441998820100, 52, 0 >>> >>> >>> But the summary at the end of the worker log contains nothing: >>> >>> 2015-09-11 19:13:40,152 INFO i-20ff63e6-1 thread-0: finished 100 runs >>> 2015-09-11 19:13:40,155 INFO i-20ff63e6-1 : elapsed time is 78966 ms >>> 2015-09-11 19:13:40,155 INFO i-20ff63e6-1 : Final statistics for this >>> process: >>> 2015-09-11 19:13:40,162 INFO i-20ff63e6-1 : >>> >>> Tests Errors Mean Test Test Time TPS >>> >>> Time (ms) Standard >>> >>> Deviation >>> >>> (ms) >>> >>> >>> Totals 0 0 - 0.00 0.00 >>> >>> >>> >>> Tests resulting in error only contribute to the Errors column. >>> >>> Statistics for individual tests can be found in the data file, >>> including >>> (possibly incomplete) statistics for erroneous tests. Composite tests >>> >>> are marked with () and not included in the totals. >>> >>> >>> >>> >>> Why would that be? My test logic has not changed and my instrumentation >>> of record is identical in which I was previously getting results summary at >>> the end of the worker log. >>> >>> Any insight would be great. >>> >> >> > ------------------------------------------------------------------------------ _______________________________________________ grinder-use mailing list [email protected] https://lists.sourceforge.net/lists/listinfo/grinder-use