Re: [Grinder-use] Bad TPS number reported by the console

[Philip A. <ph...@ma...>]

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||SendData||Filter(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 <ph...@ma... <mailto:ph...@ma...>>
>
>     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 <ph...@ma... <mailto:ph...@ma...>>
>>
>>         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
>     gri...@li...
>     <mailto:gri...@li...>
>     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
> gri...@li...
> https://lists.sourceforge.net/lists/listinfo/grinder-use