Re: Bad TPS number reported by the console

Hello Phil,

I have reproduced the issue to a very simple use case.
See the attached files.

you only need to put the core.py and dummy.py in a test_implementations
package.

when launched with:
grinder.processes=1
grinder.threads=2
grinder.runs=10
grinder.script=test.py

I have  60 successful tests instead of 20


cheers,
Olivier



2013/10/13 olivier merlin <[email protected]>

> Hello Phil,
>
> Impl is a Jython object. All Impl inherit from the Core(class) which is an
> Abstract class.
>
> I have found a workaround ... i have suppressed all other calls to impl
> and keep only the impl.sendData() instrumented call.
> Now the numbers are correct.
>
> I will try to reduce the use case to something simpler ... there is
> something strange behind - i don't understand why it was running before.
>
>
> Thanks,
>
>
>
>
>
>
>
> 2013/10/13 Philip Aston <[email protected]>
>
>>  There may well be a bug here. Is impl a Java object, or a Jython object?
>>
>> I just tried to reproduce this, but weirdly I can't even reproduce the
>> issue I'd seen with helloworld.py.
>>
>> If impl is a Java object, try this workaround:
>>
>>  class SendDataFilter(Test.InstrumentationFilter):
>>   def matches(self, method):
>>     return method.name == "sendData"
>>
>> sendDataFilter = SendDataFilter()
>> # ...
>>
>> Test(testId, line.getTestName()).record(impl, sendDataFilter)
>>
>>
>> - Phil
>>
>>
>> On 13/10/13 15:35, olivier merlin wrote:
>>
>> Hello Phil,
>>
>>  I see better where the problem is around
>> This has nothing to do with overloaded method but to the scope of
>> instrumentation when we have dynamic instrumentation.
>> The Test( ).record(impl.sendData) is dynamic and re-evaluated at each run.
>> The proof is below:
>>
>>  The code logic is the following:
>>
>>  __call__
>>     foreach line of scenario:
>>
>>           # get the protocol implementation
>>          # this can be ejb, http, http apache, database, command ...
>>          #
>>          impl.getImplementation()
>>
>>  (...)
>>          # for debugging
>>          impl.setFullRunID(fullIDWithLine)
>>
>>           # for load balancing on any criteria
>>           impl.setProcessID(processNumber)
>>          impl.setThreadID(threadNumber)
>>          impl.setRunID(runNumber)
>>          impl.setLineID(iCntProcessed)
>>
>>  (...)
>>           #  replace data with all templates and contextual data
>> (memorized data from previous call)
>>           submitCmd = impl.newProcessLine(line, self.memMgr)
>>
>>  (...)
>>            # ======= Tests are dynamic !
>>            if testNumbers.has_key(line.getTestName()):
>>                testId = testNumbers[line.getTestName()]
>>             else:
>>                testId = processNumber*testRangeSize+len(testNumbers)+1
>>                testNumbers[line.getTestName()] = testId
>>
>>  (...)
>>          Test(testId, line.getTestName()).record(impl.sendData)
>> (...)
>>          spResp = impl.sendData(submitCmd, ...)
>>
>>  If i run for 10 runs in one thread, i get 64 success test which is
>> exactly :  1 + 7x9
>> The run=0, instruments only one call (impl.senData) - because the Test is
>> created just before the call.
>> For each run>0, the instrumentation record each call to impl although it
>> should record impl.sendData only.
>>
>>  To be completely sure of this behavior, i have commented out 5 impl.xxx
>> calls above and i have got 19 transactions recorded as successful.
>> 1+2x9=19
>>
>>  This proves that the instrumentation does not apply to the
>> impl.sendData() method but the whole object impl.
>>
>>  The question is :
>> Could we consider this as a bug ?
>> The same code was working with version <= 3.5 with the getattr() method.
>>
>>  Do you see a workaround i could apply ?
>>
>>
>>  Thanks again for your help,
>> Olivier
>>
>>
>>
>>
>> 2013/10/12 Philip Aston <[email protected]>
>>
>>>  No, there's no way to trace what is instrumented. There should be -
>>> please open a Feature Request.
>>>
>>> So you are now definitely instrumenting the sendData method and not the
>>> getattr result? (E.g. Test(...).record(impl.sendData))
>>>
>>> If so, is sendData() overloaded - are there many variants of the
>>> sendData method?
>>>
>>> - Phil
>>>
>>>
>>> On 11/10/13 17:45, olivier merlin wrote:
>>>
>>> Hello Phil,
>>>
>>>  I really don't understand, i have used your new instrumentation method
>>> and i have still the problem
>>> if i launch one thread with 2 runs, i have:
>>>  Thread, Run, Test, Start time (ms since Epoch), Test time, Errors,
>>> SyncML
>>> 0, 0, 1, 1381509722862, 1, 0, 0.0
>>> 0, 1, 1, 1381509722867, 0, 0, 0.0
>>> 0, 1, 1, 1381509722867, 0, 0, 0.0
>>> 0, 1, 1, 1381509722867, 0, 0, 0.0
>>> 0, 1, 1, 1381509722867, 0, 0, 0.0
>>> 0, 1, 1, 1381509722867, 0, 0, 0.0
>>> 0, 1, 1, 1381509722867, 2, 0, 0.0
>>> 0, 1, 1, 1381509722871, 0, 0, 0.0
>>>
>>>  as you can see, the run 1 is executed 7 times.
>>> Very strange ??
>>> Do you have an idea on how i can trace the instrumentation ?
>>>
>>>  cheers,
>>> Olivier
>>>
>>>
>>> 2013/10/6 Philip Aston <[email protected]>
>>>
>>>>  This is to do with what you are instrumenting, not the logging.
>>>>
>>>> getattr will return some internal Jython object that represents the
>>>> bound method. You're instrumenting all methods of this internal Jython
>>>> object. When you invoke it, the call path is crossing multiple (7!)
>>>> instrumented methods, but that's completely down to how Jython is
>>>> implemented.
>>>>
>>>> Instead I think you should try to instrument the sendData method
>>>> itself. Try something like:
>>>>
>>>> Test(...).record(impl.sendData)
>>>>
>>>> ...
>>>>
>>>> spResp = impl.sendData(....)
>>>>
>>>>
>>>> - Phil
>>>>
>>>>
>>>>
>>>>
>>>>
>>>> On 02/10/13 10:35, olivier merlin wrote:
>>>>
>>>> Hello,
>>>>
>>>>  I try to switch our grinder framework to grinder 3.11 and i get a
>>>> problem on the TPS count.
>>>>
>>>>  When i inject a constant rate of 3 TPS, after a period of X minutes,
>>>> the console write a throughput of 21 TPS so x7 the real throughput.
>>>>
>>>>  When looking in the grinder-data_X.log file i see that 3 thread per
>>>> second is there but each threads write in the data log 7 times !
>>>>
>>>>  I'm quite sure it's a problem of instrumentation somewhere similar to
>>>> the bug entered by Phil on the #234  helloworld sample double counts<http://sourceforge.net/p/grinder/bugs/234/>
>>>>
>>>>  *We are using the old way for instrumenting:*
>>>> (...)
>>>>  testSubmit = Test(testId, line.getTestName()).wrap(getattr(impl,
>>>> "sendData"))
>>>>  (...)
>>>> spResp = testSubmit(submitCmd,
>>>> line.isMemorized(),line.getLastTemplate(), self.memMgr)
>>>>  (...)
>>>>
>>>>  The impl is a protocol implementation that may change between test -
>>>> that implements sendData() method.
>>>> The problem is perhaps that i switch the logs to logback
>>>>  (grinder.logger) in all the implementations (like the #234) ... thus
>>>> leading to a test record for each logging ?
>>>>
>>>>  Do i have to completely change my way of instrumenting ?
>>>> Or do i have to use distinct logger from the grinder.logger to avoid
>>>> this king of problem ...
>>>>
>>>>  Does someone encounter the same trouble ?
>>>>
>>>>  cheers,
>>>> Olivier
>>>>
>>>>
>>>
>>>
>>> ------------------------------------------------------------------------------
>>> October Webinars: Code for Performance
>>> Free Intel webinars can help you accelerate application performance.
>>> Explore tips for MPI, OpenMP, advanced profiling, and more. Get the most
>>> from
>>> the latest Intel processors and coprocessors. See abstracts and register
>>> >
>>>
>>> http://pubads.g.doubleclick.net/gampad/clk?id=60134071&iu=/4140/ostg.clktrk
>>> _______________________________________________
>>> grinder-use mailing list
>>> [email protected]
>>> https://lists.sourceforge.net/lists/listinfo/grinder-use
>>>
>>>
>>
>>
>> ------------------------------------------------------------------------------
>> October Webinars: Code for Performance
>> Free Intel webinars can help you accelerate application performance.
>> Explore tips for MPI, OpenMP, advanced profiling, and more. Get the most from
>> the latest Intel processors and coprocessors. See abstracts and register >http://pubads.g.doubleclick.net/gampad/clk?id=60134071&iu=/4140/ostg.clktrk
>>
>>
>>
>> _______________________________________________
>> grinder-use mailing listgrinder-use-5NWGOfrQmneRv+LV9MX5ugtCRVl27V+i0wdF1cv0I5s@public.gmane.org://lists.sourceforge.net/lists/listinfo/grinder-use
>>
>>
>>
>>
>> ------------------------------------------------------------------------------
>> October Webinars: Code for Performance
>> Free Intel webinars can help you accelerate application performance.
>> Explore tips for MPI, OpenMP, advanced profiling, and more. Get the most
>> from
>> the latest Intel processors and coprocessors. See abstracts and register >
>>
>> http://pubads.g.doubleclick.net/gampad/clk?id=60134071&iu=/4140/ostg.clktrk
>> _______________________________________________
>> grinder-use mailing list
>> [email protected]
>> https://lists.sourceforge.net/lists/listinfo/grinder-use
>>
>>
>

------------------------------------------------------------------------------
October Webinars: Code for Performance
Free Intel webinars can help you accelerate application performance.
Explore tips for MPI, OpenMP, advanced profiling, and more. Get the most from 
the latest Intel processors and coprocessors. See abstracts and register >
http://pubads.g.doubleclick.net/gampad/clk?id=60134071&iu=/4140/ostg.clktrk

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

from net.grinder.script.Grinder import grinder
from net.grinder.script import Test
import types
import test_implementations
import logging 
logging.basicConfig(level=logging.DEBUG,
                    format='%(asctime)s %(name)-12s %(levelname)-8s %(message)s',
                    datefmt='%m-%d %H:%M',
                    filename='c:/temp/test.log',
                    filemode='w')

loaded_implementations={}
testName='dummy'
testNumbers={}

def getImplementation(protocol):   
    myModule = getattr(test_implementations, protocol)
    if isinstance(myModule, types.ModuleType):
        a_module = getattr(myModule, protocol)
        try:
            impl = a_module()
        except:
            logging.exception('FATAL - Line.__init__() - Unable to load protocol %s' % (protocol))
    return impl
    
class TestRunner:
       
    def __init__(self):        
        self.first=True

    def __call__(self):
        impl = getImplementation('dummy')
        Test(1, testName).record(impl.sendData)
        impl.foo()
        impl.foo2()
        grinder.sleep(100)
        impl.sendData('hello world !')

def init():
    import os
    import logging
         
    for module in os.listdir(__path__[0]):
        if not module.startswith('_') and  module[-3:] == '.py':
            print __name__+'.'+module[:-3]
            try:
                __import__(__name__+'.'+module[:-3])
            except:
                logging.exception("Something awful happened!")
                print 'WARN (ignored) - import error for module %s' % (module[:-3])

init()

from net.grinder.script.Grinder import grinder
import logging 

properties=grinder.properties
logger=logging.getLogger('core')

class core:
    def __init__(self):
        self.core='initialized'
        
    def foo(self):
        logger.info('(%d,%d) foo called' % (grinder.threadNumber,grinder.runNumber))
    
    def foo2(self):
        logger.info('(%d,%d) foo2 called'% (grinder.threadNumber,grinder.runNumber))
        
    def sendData(self,message):
        sResp = self.__class__+'is an abstract class - Not implemented'
        return sResp

from net.grinder.script.Grinder import grinder
from core import core
import logging
logger=logging.getLogger('dummy')
    
class dummy(core):    
    def __init__(self):       
        core.__init__(self)
    
    def sendData(self,message):
        logger.info('%d,%d) %s' % (grinder.threadNumber, grinder.runNumber, message))