No statistics/results for test

classic Classic list List threaded Threaded
14 messages Options
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

No statistics/results for test

Darren Ball

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
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: No statistics/results for test

Darren Ball
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 <[hidden email]> 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
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: No statistics/results for test

Darren Ball
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 <[hidden email]> 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 <[hidden email]> 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
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: No statistics/results for test

Marc Holden
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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use

------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: No statistics/results for test

Darren Ball
In reply to this post by Darren Ball
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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: No statistics/results for test

Darren Ball
In reply to this post by Marc Holden
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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use

------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use



------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: No statistics/results for test

Marc Holden
In reply to this post by Darren Ball
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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use

------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: No statistics/results for test

Darren Ball
Next run I will ensure to redirect everything to a single log. 
It will take me a bit to get the formation up and running.

I'll post once I have the results.  

I will try to take a snapshot of the memory consumption as well.

-Darren

On Mon, Sep 14, 2015 at 2:07 PM, Marc Holden <[hidden email]> wrote:
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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use

------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use



------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: No statistics/results for test

Ouray Viney
In reply to this post by Darren Ball
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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use

------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use



------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use




--

------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: No statistics/results for test

Darren Ball
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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use

------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use



------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use




--

------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use



------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: No statistics/results for test

Darren Ball
Also, it seems as though the socket is opened to the console 6372 from the process (there are two, but as the process is spun up upon request from the console, another comes up specific for that test), but it goes to CLOSE_WAIT very quickly.  This happens while my initialization is actively happening. I can see logging happening during this time.  I have no insight as to issues with class loading times (errors are not present).
I am incrementally building java side again to see what is the breaking point during initialization.



On Mon, Sep 14, 2015 at 8:02 PM, Darren Ball <[hidden email]> wrote:
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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use

------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use



------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use




--

------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use




------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: No statistics/results for test

Ouray Viney
I made similar observations.  I wrote some pssh bash shell scripts; they monitored the remote grinder agents using netstat.  I recall seeing the same re: worker processor (when the JVM was initializing); sockets would open then change state almost immediately.  Same exact grinder environment - I could simply swap out the script and things would be 100% correct - working as expected.

I traced it using a profiler but don't have the setup at the moment nor any conclusive results to share.

Ouray Viney

On Sep 14, 2015, at 8:38 PM, Darren Ball <[hidden email]> wrote:

Also, it seems as though the socket is opened to the console 6372 from the process (there are two, but as the process is spun up upon request from the console, another comes up specific for that test), but it goes to CLOSE_WAIT very quickly.  This happens while my initialization is actively happening. I can see logging happening during this time.  I have no insight as to issues with class loading times (errors are not present).
I am incrementally building java side again to see what is the breaking point during initialization.



On Mon, Sep 14, 2015 at 8:02 PM, Darren Ball <[hidden email]> wrote:
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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use

------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use



------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use




--

------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use



------------------------------------------------------------------------------
_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use

------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: No statistics/results for test

Marc Holden
That is interesting for sure.  Have you tried to re-order the classpath?  Does the exception occur in only certain 'weight' categories and if so, does that category load different classes which may conflict with other classes on the classpath?  Could this be a permissions issue on the database where the users has not been granted select rights on system tables?  Could the CscAppPerf be swallowing any exceptions? 

How much memory is allocated to the heap?  

Sometimes, when we are seeing very strange behavior (although we have not seen the behavior you are seeing) we clean out the python cache dir and that seems to help.

Getting a good look at the agent output should shed some light on things!

-Marc

On Mon, Sep 14, 2015 at 9:51 PM Ouray Viney <[hidden email]> wrote:
I made similar observations.  I wrote some pssh bash shell scripts; they monitored the remote grinder agents using netstat.  I recall seeing the same re: worker processor (when the JVM was initializing); sockets would open then change state almost immediately.  Same exact grinder environment - I could simply swap out the script and things would be 100% correct - working as expected.

I traced it using a profiler but don't have the setup at the moment nor any conclusive results to share.


Ouray Viney

On Sep 14, 2015, at 8:38 PM, Darren Ball <[hidden email]> wrote:

Also, it seems as though the socket is opened to the console 6372 from the process (there are two, but as the process is spun up upon request from the console, another comes up specific for that test), but it goes to CLOSE_WAIT very quickly.  This happens while my initialization is actively happening. I can see logging happening during this time.  I have no insight as to issues with class loading times (errors are not present).
I am incrementally building java side again to see what is the breaking point during initialization.



On Mon, Sep 14, 2015 at 8:02 PM, Darren Ball <[hidden email]> wrote:
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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use

------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use



------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use




--

------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use



------------------------------------------------------------------------------
_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use
------------------------------------------------------------------------------
_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use

------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: No statistics/results for test

Darren Ball
So this problem is solved (for now!) in my setup.  No extra HW, same logic, but moved my tracking mechanism from ConcurrentHashMap to HashMap.
The dataset retrieval seem to be blocking and this was causing issues talking to the console port.  This communication mechanism is in need of recoding in my opinion.  Their should be no way to block it, if the protocol will close out the port in that short of a time (~< 20 seconds and this port goes down).

My classpath is massive btw (not by choice, but the application is somewhat large), it has never had an issue to date.

In your case, it might be different, but stepping through the test code helped.  I built it back up from scratch, piece by piece and discovered this was an issue.  Seeing how post initialization the tracking object is read-only, I had no need for concurrency protection, so I just removed it.  If in future, I do, I can solve this by threading the activity if need be.

-Darren

On Tue, Sep 15, 2015 at 7:49 AM, Marc Holden <[hidden email]> wrote:
That is interesting for sure.  Have you tried to re-order the classpath?  Does the exception occur in only certain 'weight' categories and if so, does that category load different classes which may conflict with other classes on the classpath?  Could this be a permissions issue on the database where the users has not been granted select rights on system tables?  Could the CscAppPerf be swallowing any exceptions? 

How much memory is allocated to the heap?  

Sometimes, when we are seeing very strange behavior (although we have not seen the behavior you are seeing) we clean out the python cache dir and that seems to help.

Getting a good look at the agent output should shed some light on things!

-Marc

On Mon, Sep 14, 2015 at 9:51 PM Ouray Viney <[hidden email]> wrote:
I made similar observations.  I wrote some pssh bash shell scripts; they monitored the remote grinder agents using netstat.  I recall seeing the same re: worker processor (when the JVM was initializing); sockets would open then change state almost immediately.  Same exact grinder environment - I could simply swap out the script and things would be 100% correct - working as expected.

I traced it using a profiler but don't have the setup at the moment nor any conclusive results to share.


Ouray Viney

On Sep 14, 2015, at 8:38 PM, Darren Ball <[hidden email]> wrote:

Also, it seems as though the socket is opened to the console 6372 from the process (there are two, but as the process is spun up upon request from the console, another comes up specific for that test), but it goes to CLOSE_WAIT very quickly.  This happens while my initialization is actively happening. I can see logging happening during this time.  I have no insight as to issues with class loading times (errors are not present).
I am incrementally building java side again to see what is the breaking point during initialization.



On Mon, Sep 14, 2015 at 8:02 PM, Darren Ball <[hidden email]> wrote:
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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use

------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use



------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use




--

------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use



------------------------------------------------------------------------------
_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use
------------------------------------------------------------------------------
_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use

------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use



------------------------------------------------------------------------------

_______________________________________________
grinder-use mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/grinder-use
Loading...