Re: No statistics/results for test
Marc Holden <[email protected]> Mon, 14 Sep 2015 18:07:39 +0000
| Newsgroups | gmane.comp.java.grinder.user |
|---|---|
| Message-ID | <CADV_OVWoL-=qbFRyOV=2+4Ty2BURPJ0hsJ87Vw2sczOv39D9Rw@mail.gmail.com> |
I just looked at those log messages again and it is very interesting... Can you redirect stderr and stdout to a log file for the agent process? It may be worth adding some logging before the assert statement to confirm you are indeed getting valid values back that you are asserting on. On Mon, Sep 14, 2015 at 1:39 PM Darren Ball <[email protected]> wrote: > 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 > ------------------------------------------------------------------------------ _______________________________________________ grinder-use mailing list [email protected] https://lists.sourceforge.net/lists/listinfo/grinder-use