Re: No statistics/results for test

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