Reported timing

classic Classic list List threaded Threaded
6 messages Options
Reply | Threaded
Open this post in threaded view
|

Reported timing

Sean Tiley
Hello,
I am using Grinder 3.11 and am trying to better understand the reported timing in the console.

I have extracted several columns from the Console 'results' tab  and just left the Test, Description and Mean Time columns

200 Page 2 - Login      478
201 GET start.swe -    356
202 GET login.css -    4.66
203 GET swen_tp.js -  4.19
204 GET log7_d.gif -    2.9
205 GET login.js -       2.92
206 GET swecmhi.js - 2.71
207 GET swi_top.js -   2.76
208 GET swecoon.js - 3.28
209 GET do-not.png -  3.14
210 GET logint.jpg -    3.31
211 GET loginr.jpg -    2.66
212 GET transt.gif -    2.6
213 GET favcon.ico -  3.57

I had always assumed that the Page 2 - Login mean time of 478 was simply the sum of all the times for all the gets that comprise page 2 (201-> 213).
Adding up those times individually I get 394.7 

I am wondering what the 478 number represents as it clearly is not the sum of the others

Any insight would be appreciated.

Thanks
Sean



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

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

Re: Reported timing

Gary Mulder-3
Hi Sean,

Without looking at your code, does the 478 include sleep time?

Regards,
Gary


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

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

Re: Reported timing

Sean Tiley
Hi Gary. Good thought i will have a look in the morning.  I may be remembering incorrectly  but i thought that sleep times were varied within a normal distribution across runs which may make answering that interesting.  Let me have a look and i will report back.

Sean

On Thu, Dec 17, 2015, 3:00 PM Gary Mulder <[hidden email]> wrote:
Hi Sean,

Without looking at your code, does the 478 include sleep time?

Regards,
Gary

------------------------------------------------------------------------------
_______________________________________________
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
|

Re: Reported timing

Sean Tiley

Hi Gary,
I ran the test once and captured the following stats from the console

200 Page 2 - Login   631
201 GET start.swe -  338
202 GET login.css -  18
203 GET swen_tp.js - 18
204 GET log7_d.gif - 19
205 GET login.js -   7
206 GET swecmhi.js - 20
207 GET swi_top.js - 23
208 GET swecoon.js - 17
209 GET do-not.png - 10
210 GET logint.jpg - 29
211 GET loginr.jpg - 13
212 GET transt.gif - 18
213 GET favcon.ico - 9

Adding times for 201-213 gives 539.  That leaves a difference of 92.


my page 2 function looks like this, (unnecessary bits removed).  There are 2 explicit sleeps in the page 2 code for a total of 62, leaving 30 unaccounted for.


  def page2(self):
    """GET start.swe (requests 201-213)."""
    result = request201.GET(...)
    request202.GET(...)
    request203.GET(...)
    request204.GET(...)
    request205.GET(...)
    request206.GET(...)
    request207.GET(....)
    request208.GET(...)

    grinder.sleep(15)

    request209.GET(...)
    request210.GET(...)
    request211.GET(...)
    request212.GET(...)

    grinder.sleep(47)

    request213.GET(...)
    return result

 
In the __call__
I have the following

  def __call__(self):
    grinder.getStatistics().setDelayReports(True)
    """Called for every run performed by the worker thread."""
    self.page1()      # GET / (request 101)

    grinder.sleep(47)
    self.page2()      # GET start.swe (requests 201-213)

    grinder.sleep(10188)
    self.page3()      # POST start.swe (request 301)

......snip


There is an explicit sleep of 47 between page 1 and 2 but I think the times here are varied slightly automatically from thread to thread and not counted in the reported times? 

So not really sure where the addidional time comes from?

Any thoughts are welcomed

Thanks
Sean


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

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

Re: Reported timing

Gary Mulder-3
I'd remove the sleeps and confirm that you still have missing time.

Regards,
Gary

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

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

Re: Reported timing

Marc Holden
In reply to this post by Sean Tiley
Hi Sean,

Have you tried to ignoring the few sample sets that come in and allow the test to run for a few minutes.  There may be class loading/caching/instrumentation/networking latency you are experiencing. 

-Marc  

On Fri, Dec 18, 2015 at 10:37 AM Sean Tiley <[hidden email]> wrote:

Hi Gary,
I ran the test once and captured the following stats from the console

200 Page 2 - Login   631
201 GET start.swe -  338
202 GET login.css -  18
203 GET swen_tp.js - 18
204 GET log7_d.gif - 19
205 GET login.js -   7
206 GET swecmhi.js - 20
207 GET swi_top.js - 23
208 GET swecoon.js - 17
209 GET do-not.png - 10
210 GET logint.jpg - 29
211 GET loginr.jpg - 13
212 GET transt.gif - 18
213 GET favcon.ico - 9

Adding times for 201-213 gives 539.  That leaves a difference of 92.


my page 2 function looks like this, (unnecessary bits removed).  There are 2 explicit sleeps in the page 2 code for a total of 62, leaving 30 unaccounted for.


  def page2(self):
    """GET start.swe (requests 201-213)."""
    result = request201.GET(...)
    request202.GET(...)
    request203.GET(...)
    request204.GET(...)
    request205.GET(...)
    request206.GET(...)
    request207.GET(....)
    request208.GET(...)

    grinder.sleep(15)

    request209.GET(...)
    request210.GET(...)
    request211.GET(...)
    request212.GET(...)

    grinder.sleep(47)

    request213.GET(...)
    return result

 
In the __call__
I have the following

  def __call__(self):
    grinder.getStatistics().setDelayReports(True)
    """Called for every run performed by the worker thread."""
    self.page1()      # GET / (request 101)

    grinder.sleep(47)
    self.page2()      # GET start.swe (requests 201-213)

    grinder.sleep(10188)
    self.page3()      # POST start.swe (request 301)

......snip


There is an explicit sleep of 47 between page 1 and 2 but I think the times here are varied slightly automatically from thread to thread and not counted in the reported times? 

So not really sure where the addidional time comes from?

Any thoughts are welcomed

Thanks


Sean

------------------------------------------------------------------------------
_______________________________________________
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