I have a Simulation which contains 3 scenarios, shared among the users. The attached file shows the Gatling2.0 version, but I saw the same problem with the Gatling1.5 version. What happens - sometimes - is that one of the scenarios appears to execute far more often than it really does. The attached file includes this setup:
setUp(scn_a.inject(ramp(users / 2 ) over (rampup)),
scn_b.inject(ramp(users / 4) over (rampup)),
scn_c.inject(ramp(users / 4) over (rampup)))
.protocols(httpConf)
and what I see in the output is scn_a and scn_c occuring as expected, but scn_b apparently running wild. While the others execute in the hundreds, scn_b appears to execute hundreds of thousands of times. All of these apparent executions appear in the simulation.log file as taking 0 or 1 millisecond and returning OK. The vast majority of those requests are not actually sent and never show up on the server.
Is there a known explanation for this or is there something in the way my Simulation is constructed that might be causing this? The scenarios are all using session attributes to generate a different random code each time.
Thanks very much
Tom
sample.scala (2.55 KB)
Can you reproduce with current snapshot?
slf4j and logback form a pair that has to be aligned. It seems that you have some old version of one of these two in your classpath and it clashes with the other one.
Hi Tom,
“far more often than it really does”: could you elaborate, please? How much is “far more often”?
Are the additional requests duplicates of expected requests, maybe logged with a KO status?
Cheers,
Stéphane
I now have it compiling with the May 31 SNAPSHOT and am attempting to reproduce - the behavior is sporadic and can appear immediately or several minutes into the run.
By “far more often” I meant, as originally reported: “While the others execute in the hundreds, scn_b appears to execute hundreds of thousands of times.”
I have logging to File now set to INFO so if and when I reproduce the issue I’ll be able to report more details
thanks
tom
Ok - it did reproduce just now, and using the latest SNAPSHOT jar files. I’ve attached a document describing the results
reproduced_gatling_scenario_notes.rtf (10.7 KB)
sample.scala (2.65 KB)
Just one silly question: could it be that the request that’s executed a lot more than expected actually replies with Last-Modified or ETag headers, so that next requests for a given virtual user replies with 304, hence very very fast? Gatling enables HTTP cache by default.
I’m not sure I understand. I’m not seeing the request reach the server at all (in either the nginx access or error logs)
My httpConf has “disableCaching” included
val httpConf = http
.baseURL(“http://THE_URL”)
.acceptCharsetHeader(“ISO-8859-1,utf-8;q=0.7,;q=0.7")
.acceptHeader("text/html,application/xhtml+xml,application/xml;q=0.9,/*;q=0.8”)
.acceptEncodingHeader(“gzip, deflate”)
.acceptLanguageHeader(“fr,fr-fr;q=0.8,en-us;q=0.5,en;q=0.3”)
.disableCaching
I don’t find any Last-Modified or ETag entries anywhere in the TRACE logs, if that’s where they might be. I do see “Using cached Channel” sometimes. Is there a gatling cache in memory or disk? If so, is there any way to clear it after a test run?
8593 [GatlingSystem-akka.actor.default-dispatcher-15] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider -
Using cached Channel [id: 0x9223d529, /10.182.57.125:60378 => THE_URL/50.19.247.113:80]
for request
DefaultHttpRequest(chunked: false)
GET /?postalCode=R4V&countryCode=CA HTTP/1.1
Host: THE_URL
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,/;q=0.8
Accept-Language: fr,fr-fr;q=0.8,en-us;q=0.5,en;q=0.3
Accept-Encoding: gzip,deflate
Connection: keep-alive
User-Agent: Gatling/2.0
8593 [New I/O worker #14] DEBUG c.n.h.c.p.n.NettyConnectionsPool - Adding uri: 4789726571975720583-77http://THE_URL:80 for channel [id: 0xb38d5157, /10.182.57.125:60205 => THE_URL/50.19.247.113:80]
8593 [GatlingSystem-akka.actor.default-dispatcher-5] TRACE i.g.http.ahc.AsyncHandlerActor -
Request:
ca_zip: OK
On closer inspection I am seeing ~4000 such requests per second in the nginx access logs, which does correspond to the rate I’m seeing in Gatling. nginx is instantly responding to each of these with 200 and not passing them on to the backend process (unicorn).
Wouhou: I promised to treat myself a beer once this was solved! Cheers!
So, why are all those scenarios being generated?
You mean “those requests”?
You don’t have any pause or any pacing in your during loop, so every virtual user send a new request as soon as it has received the response. If nginx replies in 1ms, you’ll end up having each virtual user send 1000 requests/sec.
Ok - I get it now. Thanks very much.
Things should be getting back to normal once you’ve figured out why nginx doesn’t propagate the requests to the back-end.
Good luck!