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