Circular and random feed does not work as expected

[Damien Hardy]

Hello,

I try some Gatling simulation against one of my service.
Using a feed TSV file ( photo_queries.tsv ) containing  26 query strings as ${query}
Looks like :
query
/servlet/photo?memberId=00219l2onef1bire&height=35&width=26&ts=1348109861000
/servlet/photo?memberId=0021nwp1f2a9jd4z&height=35&width=26&ts=1339603511000
/servlet/photo?memberId=0021lpsbgdg9nzg&height=60&width=45&ts=1337034533000
[...]


Here is my Simulation scala code :

package photo
import com.excilys.ebi.gatling.core.Predef._
import com.excilys.ebi.gatling.http.Predef._
import com.excilys.ebi.gatling.jdbc.Predef._
import akka.util.duration._
import bootstrap._

class SimulationPhotoLoad extends Simulation {

 def apply = {

   val photoQueries = tsv("photo_queries.tsv").circular

   val urlBase = "http://10.40.0.2/"
   val httpConf = httpConfig.baseURL(urlBase).hostHeader("static")

   val scn = scenario("My scenario")
      .during(1 minutes) {
        feed(photoQueries)
        .exec(
          http("Photos")
          .get("${query}")
        )
        .pause(0 milliseconds, 100 milliseconds)
      }

   List(scn.configure.users(10).protocolConfig(httpConf))
  }
}


The report ends with 260 hits (26 * 10) almost reached in the first 10 seconds and waiting for other 110 seconds doing nothing.
change circular by random does nothing for that.

I excepted that queries were hit again and again during the 2 minutes of the tests resulting on much more hits on the plateform.

What is wrong with my code ?

Thank you for your kind answer.

Cheers,

--
Dam

[Stéphane Landelle]

Hi,

You can't pass query parameters in the get method, you have to use queryParam:

https://github.com/excilys/gatling/wiki/HTTP#wiki-query-params

Though, you have to provide parsed data in your feeder.

Could you try it and tell us if it then works as expected?

Stéphane

2012/12/17 Damien Hardy <dha...@viadeoteam.com>

[Damien Hardy]

Hi,

Thank you Stéphane.
Things seams better but lots of 400 errors now :/

10:14:54.614 [WARN ] c.e.e.g.h.a.GatlingAsyncHandlerActor - Request 'Photos' failed : Check 'in' failed, found 400 but expected Range(200, 201, 202, 203, 204, 205, 206, 207, 208, 209, 210)
10:14:55.194 [WARN ] c.e.e.g.h.a.GatlingAsyncHandlerActor - Request 'Photos' failed : Check 'in' failed, found 400 but expected Range(200, 201, 202, 203, 204, 205, 206, 207, 208, 209, 210)
10:14:55.438 [WARN ] c.e.e.g.h.a.GatlingAsyncHandlerActor - Request 'Photos' failed : Check 'in' failed, found 400 but expected Range(200, 201, 202, 203, 204, 205, 206, 207, 208, 209, 210)
10:14:55.937 [WARN ] c.e.e.g.h.a.GatlingAsyncHandlerActor - Request 'Photos' failed : Check 'in' failed, found 400 but expected Range(200, 201, 202, 203, 204, 205, 206, 207, 208, 209, 210)
10:14:57.564 [WARN ] c.e.e.g.h.a.GatlingAsyncHandlerActor - Request 'Photos' failed : Check 'in' failed, found 400 but expected Range(200, 201, 202, 203, 204, 205, 206, 207, 208, 209, 210)
================================================================================
2012-12-18 10:14:57                                                 140s elapsed
---- My scenario ---------------------------------------------------------------
Users  : [#################################################################]100%
          waiting:0     / running:0     / done:10  
---- Requests ------------------------------------------------------------------
> Photos                                                     OK=230    KO=1339 
================================================================================

How can I log KO requests so that I can find out what's wrong with them ?

Cheers,

--
Dam

PS : google group inteface remove my reply to you post (that I didn't receive) so you may get this as a doubleton.

[Stéphane Landelle]

Hi Damien,

You can lower the log level in logback.xml conf file:

https://github.com/excilys/gatling/wiki/Configuration#wiki-config-files

Cheers,

Stéphane

2012/12/18 Damien Hardy <dha...@viadeoteam.com>

[Damien Hardy]

Thank you Stéphane

It seams that parameters are not set most of the time (230 OK queries seams to be constant in my simulation) random policy give the same result:

11:13:20.681 [DEBUG] c.e.e.g.h.a.GatlingAsyncHandlerActor - Request 'Photos' failed : Check 'in' failed, found 400 but expected Range(200, 201, 202, 203, 204, 205, 206, 207, 208, 209, 210)
request was:http://10.40.0.2//servlet/photo    GET    headers:    Host:static
response was:
status=
400 Bad Request
headers=
"Connection=close"; "Content-Encoding=identity"; "Content-Length=971"; "Content-Type=text/html;charset=utf-8"; "Date=Tue, 18 Dec 2012 10:13:20 GMT"; "Server=Apache"; "Vary=Accept-Encoding,User-Agent"

================================================================================
2012-12-18 11:13:20                                                 140s elapsed

---- My scenario ---------------------------------------------------------------
Users  : [#################################################################]100%
          waiting:0     / running:0     / done:10  
---- Requests ------------------------------------------------------------------

> Photos                                                     OK=230    KO=1374 
================================================================================

Cheers,

2012/12/18 Stéphane Landelle <slan...@excilys.com>

--
Dam

[Nicolas Rémond]

Would it be possible to see your current simulation script ?

[Damien Hardy]

Of course :)

Here it is :

package photo
import com.excilys.ebi.gatling.core.Predef._
import com.excilys.ebi.gatling.http.Predef._
import com.excilys.ebi.gatling.jdbc.Predef._
import akka.util.duration._
import bootstrap._

class SimulationPhotoLoad extends Simulation {

 def apply = {

   val photoQueries = tsv("photo_queries.tsv").random

   val urlBase = "http://10.40.0.2/"
   val httpConf = httpConfig.baseURL(urlBase).hostHeader("static")

   val scn = scenario("My scenario")

      .during(2 minutes) {

        feed(photoQueries)
        .exec(
          http("Photos")
          .get("${query}")

          .queryParam("memberId", "${memberId}")
          .queryParam("height", "${height}")
          .queryParam("width", "${width}")
          .queryParam("ts", "${ts}")

        )
        .pause(0 milliseconds, 100 milliseconds)
      }

   List(scn.configure.users(10).protocolConfig(httpConf).ramp(20))
  }
}


I transform my feed file as (tsv):
query    memberId    height    width    ts
/servlet/photo    0021el2on8f1bire    35    26    1348109861000
/servlet/photo    0021nfp132a9jd4z    35    26    1339603511000
/servlet/photo    0021lpgbzdg9nzg    60    45    1337034533000
/servlet/photo    002okfgh1qp0vs4    40    40    1306580914000

2012/12/18 Nicolas Rémond <nicolas...@gmail.com>

--

Damien HARDY

IT Infrastructure Architect

Viadeo - 30 rue de la Victoire - 75009 Paris - France

T : +33 1 80 48 39 73 – F : +33 1 42 93 22 56

[Stéphane Landelle]

Would you have, by any chance, set up your text editor so that it automatically replaces tabs (like those in your tsv file) with spaces?

2012/12/18 Damien Hardy <dha...@viadeoteam.com>

[Damien Hardy]

Good question but nope :
hexdump -C user-files/data/photo_queries.tsv | head
00000000  71 75 65 72 79 09 6d 65  6d 62 65 72 49 64 09 68  |query.memberId.h|
00000010  65 69 67 68 74 09 77 69  64 74 68 09 74 73 0a 2f  |eight.width.ts./|
00000020  73 65 72 76 6c 65 74 2f  70 68 6f 74 6f 09 30 30  |servlet/photo.00|
00000030  32 31 65 6c 32 6f 6e 38  66 31 62 69 72 65 09 33  |21el2on8f1bire.3|


"0x09" is TAB

2012/12/18 Stéphane Landelle <slan...@excilys.com>

[Damien Hardy]

By the way, replacing with coma (",") and changing tsv by csv in scala give the same result.

2012/12/18 Damien Hardy <dha...@viadeoteam.com>

Good question but nope :
hexdump -C user-files/data/photo_queries.tsv | head
00000000  71 75 65 72 79 09 6d 65  6d 62 65 72 49 64 09 68  |query.memberId.h|
00000010  65 69 67 68 74 09 77 69  64 74 68 09 74 73 0a 2f  |eight.width.ts./|
00000020  73 65 72 76 6c 65 74 2f  70 68 6f 74 6f 09 30 30  |servlet/photo.00|
00000030  32 31 65 6c 32 6f 6e 38  66 31 62 69 72 65 09 33  |21el2on8f1bire.3|


"0x09" is TAB

--
Dam

[Damien Hardy]

Thanks to Stéphane I clean my feed file from 3 wrong lines that genereta 400 bad requests (don't know why but this is not subject).

Now I have a feed file of 23 lines and report looks like :

================================================================================
2012-12-18 15:22:51                                                 140s elapsed

---- My scenario ---------------------------------------------------------------
Users  : [#################################################################]100%
          waiting:0     / running:0     / done:10  
---- Requests ------------------------------------------------------------------

> Photos                                                     OK=230    KO=0    
================================================================================

Only 230 instead of ... plenty during the 2 minutes(circular or random give the same result)

#The code :

package photo
import com.excilys.ebi.gatling.core.Predef._
import com.excilys.ebi.gatling.http.Predef._
import com.excilys.ebi.gatling.jdbc.Predef._
import akka.util.duration._
import bootstrap._

class SimulationPhotoLoad extends Simulation {

   def apply = {

     val photoQueries = tsv("photo_queries.tsv").circular

     val urlBase = "http://10.40.0.2"

     val httpConf = httpConfig.baseURL(urlBase)

                    .hostHeader("static")

     val scn = scenario("My scenario")
        .during(2 minutes) {

          feed(photoQueries)
          .exec(
            http("Photos")
            .get("${query}")
            .queryParam("memberId", "${memberId}")
            .queryParam("height", "${height}")
            .queryParam("width", "${width}")
            .queryParam("ts", "${ts}")
          )
          .pause(0 milliseconds, 100 milliseconds)
        }
      List(scn.configure.users(10).protocolConfig(httpConf).ramp(20))
   }
}

#The feed file head :

query    memberId    height    width    ts

/servlet/photo    00219a2on8f1bire    35    26    1348109861000
/servlet/photo    0021nbp132a9jd4z    35    26    1339603511000
/servlet/photo    0021lpcbzdg9nzg    60    45    1337034533000
/servlet/photo    002okdft1qp0vs4    40    40    1306580914000

2012/12/18 Damien Hardy <dha...@viadeoteam.com>

[Nicolas Rémond]

Hi,

I just ran a quick test on my machine. I created a web-server that doesn't do anything (see serve-tornado.py) and used your simulation against it :

================================================================================

2012-12-18 16:27:55                                                 140s elapsed

---- My scenario ---------------------------------------------------------------

Users  : [#################################################################]100%

          waiting:0     / running:0     / done:10   

---- Requests ------------------------------------------------------------------

> Photos                                                     OK=18828  KO=0     

================================================================================

So, when you say "Only 230 instead of ... plenty during the 2 minutes(circular or random give the same result)"

Have you measure a higher traffic on the server ? What is the max response time of this servlet ?

Given that downloading photos may create a high traffic, you may also want to check your bandwith. 

cheers

Nicolas

[Damien Hardy]

Hmm I have the same result than you with the local tornado service.

But if all requests are done in the few 20 seconds what is it waiting for in the rest of the test ? ...(#headache)

And why 230 (as 10 users * 23 lines in feed ) ?
You can see the progress of the test in the capture join
and the stats (for 3 minutes of tests):

Requests		Executions				Response Time (ms)
		Total	OK	KO		Min	Max	Mean	Std Dev	95th pct	99th pct	Req/s
Global Information		230	230	0		160	330	166	23	170	320	1
Photos		230	230	0		160	330	166	23	170	320	1

2012/12/18 Nicolas Rémond <nicolas...@gmail.com>

[Nicolas Rémond]

Bizarre. 

Have you used the same TSV file in my simulation against the Tornado web server ?

[Damien Hardy]

Nope, mine just changing target for the localhost Tornado

Sorry for flooding. I try to give maximum of data to understand.

To complete here is some apachebench :
 ab -H "Host: static" -n 500 -c 10 "http://10.40.0.2/servlet/photo?memberId=002qben1yiboxvs&height=40&width=40&ts=1346331406000"
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking 10.40.0.2 (be patient)
Completed 100 requests
Completed 200 requests
Completed 300 requests
Completed 400 requests
Completed 500 requests
Finished 500 requests


Server Software:        Apache
Server Hostname:        10.40.0.2
Server Port:            80

Document Path:          /servlet/photo?memberId=

002qben1yiboxvs&height=40&width=40&ts=1346331406000
Document Length:        1311 bytes

Concurrency Level:      10
Time taken for tests:   16.343 seconds
Complete requests:      500
Failed requests:        0
Write errors:           0
Total transferred:      801500 bytes
HTML transferred:       655500 bytes
Requests per second:    30.59 [#/sec] (mean)
Time per request:       326.858 [ms] (mean)
Time per request:       32.686 [ms] (mean, across all concurrent requests)
Transfer rate:          47.89 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:      158  162  63.1    158    1158
Processing:   160  164  39.8    161     791
Waiting:      160  161   1.1    161     164
Total:        317  326  89.8    319    1949

Percentage of the requests served within a certain time (ms)
  50%    319
  66%    320
  75%    321
  80%    321
  90%    322
  95%    322
  98%    323
  99%    326
 100%   1949 (longest request)


So try it with 1 line feed (the same):

query    memberId    height    width    ts

/servlet/photo    002qben1yiboxvs    40    40    1346331406000


================================================================================
2012-12-18 17:29:21                                                 200s elapsed

---- My scenario ---------------------------------------------------------------
Users  : [#################################################################]100%
          waiting:0     / running:0     / done:10  
---- Requests ------------------------------------------------------------------

> Photos                                                     OK=10     KO=0    
================================================================================


Remove the feed part from the Simulation (hardcoded paramater and querry) :

package photo
import com.excilys.ebi.gatling.core.Predef._
import com.excilys.ebi.gatling.http.Predef._
import com.excilys.ebi.gatling.jdbc.Predef._
import akka.util.duration._
import bootstrap._

class SimulationPhotoLoad extends Simulation {

   def apply = {

     val urlBase = "http://10.40.0.2"
     //val urlBase = "http://localhost:8888"

     val httpConf = httpConfig.baseURL(urlBase)
                    .hostHeader("static")

     val scn = scenario("My scenario")

        .during(3 minutes) {
          exec(
            http("Photos")
            .get("/servlet/photo")
            .queryParam("memberId", "002qben1yiboxvs")
            .queryParam("height", "40")
            .queryParam("width", "40")
            .queryParam("ts", "1346331406000")

          )
          .pause(0 milliseconds, 100 milliseconds)
        }
      List(scn.configure.users(10).protocolConfig(httpConf).ramp(20))
   }
}

================================================================================
2012-12-18 17:37:48                                                 200s elapsed

---- My scenario ---------------------------------------------------------------
Users  : [#################################################################]100%
          waiting:0     / running:0     / done:10  
---- Requests ------------------------------------------------------------------

> Photos                                                     OK=10     KO=0    
================================================================================

So feed part is not guilty ...

[Nicolas Rémond]

Ok, by using your prod server, I'm able to reproduce

Hope you don't mind.

I'll try to have a look asap.

package basic

import com.excilys.ebi.gatling.core.Predef._

import com.excilys.ebi.gatling.http.Predef._

import akka.util.duration._

import bootstrap._

class BasicExampleSimulation extends Simulation {

   def apply = {

     val urlBase = "http://static9.viadeo-static.com"

     val httpConf = httpConfig.baseURL(urlBase)

     val scn = scenario("My scenario")

        .during(2 minutes) {

          exec(

            http("Photos")

            .get("/servlet/photo")

            .queryParam("memberId", "002va4fhz5qsscl")

            .queryParam("height", "40")

            .queryParam("width", "40")

            .queryParam("ts", "1293559910000")

          )

        }

      List(scn.configure.users(2).protocolConfig(httpConf).ramp(20))

   }

}

query    memberId    height    width    ts

/servlet/photo    002qben1yiboxvs    40    40    1346331406000


================================================================================

2012-12-18 17:29:21                                                 200s elapsed

---- My scenario ---------------------------------------------------------------
Users  : [#################################################################]100%
          waiting:0     / running:0     / done:10  
---- Requests ------------------------------------------------------------------

> Photos                                                     OK=10     KO=0    
================================================================================


Remove the feed part from the Simulation (hardcoded paramater and querry) :

package photo
import com.excilys.ebi.gatling.core.Predef._
import com.excilys.ebi.gatling.http.Predef._
import com.excilys.ebi.gatling.jdbc.Predef._
import akka.util.duration._
import bootstrap._

class SimulationPhotoLoad extends Simulation {

   def apply = {

     val urlBase = "http://10.40.0.2"
     //val urlBase = "http://localhost:8888"

     val httpConf = httpConfig.baseURL(urlBase)
                    .hostHeader("static9.viadeo-static.com")

     val scn = scenario("My scenario")

        .during(3 minutes) {
          exec(
            http("Photos")
            .get("/servlet/photo")
            .queryParam("memberId", "002qben1yiboxvs")
            .queryParam("height", "40")
            .queryParam("width", "40")

            .queryParam("ts", "1346331406000")

          )
          .pause(0 milliseconds, 100 milliseconds)
        }
      List(scn.configure.users(10).protocolConfig(httpConf).ramp(20))
   }
}

================================================================================
2012-12-18 17:37:48                                                 200s elapsed

---- My scenario ---------------------------------------------------------------
Users  : [#################################################################]100%
          waiting:0     / running:0     / done:10  
---- Requests ------------------------------------------------------------------

> Photos                                                     OK=10     KO=0    
================================================================================

So feed part is not guilty ...

2012/12/18 Nicolas Rémond <nicolas...@gmail.com>

[Stéphane Landelle]

Damn!

I tested it with the latest Gatling 1.4.0-SNAPSHOT (sorry, I'm in a hurry and this version has better logging) and it works perfectly fine.

Do you think you could try it out?

http://repository-gatling.forge.cloudbees.com/snapshot/com/excilys/ebi/gatling/highcharts/gatling-charts-highcharts/1.4.0-SNAPSHOT/

See logback.xml for enabling logs on HTTP requests and responses.

Here's your migrated simulation:

package photo

import com.excilys.ebi.gatling.core.Predef._

import com.excilys.ebi.gatling.http.Predef._

import com.excilys.ebi.gatling.jdbc.Predef._

import akka.util.duration._

import bootstrap._

class SimulationPhotoLoad extends Simulation {

   val photoQueries = tsv("photo_queries.tsv").random

   val urlBase = "http://10.40.0.2"

   val httpConf = httpConfig.baseURL(urlBase)

   val scn = scenario("My scenario")

      .during(2 minutes) {

        feed(photoQueries)

        .exec(

          http("Photos")

          .get("${query}")

          .queryParam("memberId", "${memberId}")

          .queryParam("height", "${height}")

          .queryParam("width", "${width}")

          .queryParam("ts", "${ts}")

        )

        .pause(0 milliseconds, 100 milliseconds)

      }

   setUp(scn.users(10).protocolConfig(httpConf).ramp(20))

}

2012/12/18 Damien Hardy <dha...@viadeoteam.com>

[Nicolas Rémond]

Found it !

The responses from your server have these headers :

"Accept-Ranges=bytes"; 

"Age=0"; 

"Cache-Control=public, max-age=2592000"; 

"Connection=Keep-Alive"; 

"Content-Length=1137"; 

"Content-Type=image/jpeg"; 

"Date=Tue, 18 Dec 2012 21:09:18 GMT"; 

"Expires=Thu, 17 Jan 2013 21:09:18 GMT"; 

"Last-Modified=Tue, 28 Dec 2010 18:11:50 GMT"; 

"Server=Apache"

By default, Gatling take these directives into account. So, in your case, you should define the httpConfig like that : 

val httpConf = httpConfig

.baseURL(baseURL)

.disableCaching

[Stéphane Landelle]

@Nico Nice job! I think someone also ran into the same puzzle some time ago, so we should write something down on this topic in the FAQ.

@Damien As Nicolas stated, you can disable this feature, but IMHO, if you want to simulate real users behavior, you'd better keep the default set up and consider the behavior is the expected one.

Cheers,

Stéphane

2012/12/18 Nicolas Rémond <nicolas...@gmail.com>

[Damien Hardy]

Great ! Thank you every one.
With cache disabled it work as I was excepting it (like jmeter does)
Now I understand my mistake.

Thank you.

2012/12/19 Stéphane Landelle <slan...@excilys.com>

[Nicolas Rémond]

Cool :)

Thanks for the feedback.

Nicolas