Re: No statistics/results for test
Darren Ball <[email protected]> Mon, 14 Sep 2015 20:02:36 -0400
| Newsgroups | gmane.comp.java.grinder.user |
|---|---|
| Message-ID | <CA+YPNhevhxh6F8msLe8VkpXBdj3kWJgeLPLHfZYhvhQh_7aC5Q@mail.gmail.com> |
Well, that definitely sounds interesting. I have two tests, both having the same classpath. The first does not load schema/dataset(s), and it works. The second, is similar, with the exception that it loads a schema/dataset(s). The memory is not the issue, as it is only consuming 2.3% of total memory on the system as far as I can tell. -Darren On Mon, Sep 14, 2015 at 6:15 PM, Ouray Viney <[email protected]> wrote: > I have seen the exact same issue. In our case, it was identified to be > related to class loading times or init (a tone of jars needed to be > loaded). Similar to what you have diagnosed. The result was the same as > yours, the stats com to the Console was broken, the agent log file didn't > have the table of stats. Annoying, not fixed and not easy to diagnose. We > even tried throwing more H/W at it but that didn't fix the issue - upwards > of 8 GB of heap and 8-16 CPU's. I highly doubt you are dealing with an > OOM. The java stack would normally report that - so either in the output > from your agent or in the console if you aren't piping the stderr and > stdout to a file. > > Good luck, it would be fun to see this problem to the end. We worked > around it by using non-grinder agent log report, used the raw data files > instead. > > On Mon, Sep 14, 2015 at 1:59 PM, Darren Ball <[email protected]> > wrote: > >> Hi Marc, >> >> I am working on providing information. In the meantime, I am increasing >> my env to have more memory etc. >> >> I will provide info shortly. >> >> Thanks for replying! >> >> -Darren >> >> On Mon, Sep 14, 2015 at 1:23 PM, Marc Holden <[email protected]> >> wrote: >> >>> Hi Darren, >>> >>> Can you provide any additional details about your configuration? The >>> exception is due to a broken pipe which can be the result a worker process >>> either running out of memory or a premature termination of a network >>> connection. If it is an OME, you will need to capture stderr and stdout of >>> the agent proces, IIRC these exceptions are not logged by the worker. >>> >>> Hope this helps. >>> >>> -Marc >>> >>> >>> >>> On Mon, Sep 14, 2015 at 12:25 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 >>> >>> >> >> >> ------------------------------------------------------------------------------ >> >> _______________________________________________ >> grinder-use mailing list >> [email protected] >> https://lists.sourceforge.net/lists/listinfo/grinder-use >> >> > > > -- > Ouray Viney > http://www.viney.ca > > > > ------------------------------------------------------------------------------ > > _______________________________________________ > 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