Not able to correlate the response times values in simulation log file and chart for group requests

[Ashwani]

Hi,
I am trying to understand the group response time. My scenario is like this

One Group
{
    1. Execute a create request
    2. Loop with pause of 1 sec for each iteration - exec a function to 
        check resource is created in DB 
}

I see below data in simulation log file for above group requests(3 in number).
USER CreatePerson START 1699723901433
REQUEST async CreatePerson API 1699723901453 1699723901462 OK
REQUEST async CreatePerson API 1699723914616 1699723914619 OK
REQUEST async CreatePerson API 1699723916633 1699723916636 OK
GROUP async 1699723901430 1699723918647 15 OK
USER CreatePerson END 1699723919661

The difference of group response time 1699723918647-1699723901430= 17,217 (approx. 17 secs)
I don’t see these details in any chart. Each group was waiting for approx. 5 secs.
I am using the version 3.9. I want to see approx. how much time each group request took (mean 5 secs). But it is showing the value of 15 ms for a group in stats(4-5 ms for api call and rest for wait I guess)

Thanks

[slandelle]

exec a function to check resource is created in DB

This is most likely your culprit. I’m pretty sure this has 2 issues:

1. it’s very long
2. it’s a blocking operation, which is something that’s absolutely forbidden in an exec block as explained in the documentation:

Those functions are executed in Gatling’s shared threads, so you must absolutely avoid performing long blocking operations in there, such as remote API calls.

[Ashwani]

My requirement is exactly like this Measure response time of async call

I want to calculate the time taken by each group(api call and wait time for a resource that is created) - mean, percentile etc. So what should I do to check if the resource is created in backend or not if I can’t use exec?
Also exec is calling a function which returns immediately. it is not a long blocking operation.

[slandelle]

Somehow, you’re performing a long operation. Gatling is not inventing this time spent.

And if you’re performing something like a JDBC call or some other blocking operation (not idea how “check resource is created in DB” is implemented, but it doesn’t seem to be implemented with Gatling HTTP), you’re blocking all the virtual users that are sharing the same IO thread.

Try to implement your “check resource is created in DB” as an HTTP API and rely on Gatling HTTP for calling it instead of custom code inside a function.

[sbrevet]

Hi @Ashwani,

As stated in the How to Ask a Question topic, please provide a reproducer.

I think there is 2 different things here:

1. In the log, you see 17 seconds for a group. As @slandelle mentioned, it is very likely that you have long exec functions.
2. In the report, you see 15ms instead of your expected 5seconds => Do you watch the cumulated response time (only time from gatling requests) or group duration?

Help us to help you with a clear definition of what you are doing (with a reproducer) and what you see (screenshots?)

Cheers!

[Ashwani]

Here is my code. I am just using one VU. I am simulating async behavior. I create a record and delay (around 5-8 secs) creating it for sometime. in the second part I am running asLongAs loop trying to find that record. Once it is found, the group is finished. The second part can be executing till the record is found(using normal http client. Can convert to gatling http to see the change). Three requests with 24 secs roughly means 7-8 secs for each group.

ChainBuilder search =
            group("async").on(
                    repeat(3, "n").on((feed(jdbcFeeder)
                            .exec(
                                    http("CreatePerson API")
                                            .post("/owners/new").body(StringBody("#{person_request}"))
                                            .check(status().is(200))
                            ).pause(1).asLongAs(session -> !dataAvailable(session))
                            .on(
                                    exec(this::checkPersonGenerated)
                            )
                            .pause(1)))).pause(1);


    HttpProtocolBuilder httpProtocol = http.baseUrl("http://ash.acme.com:8443")
            .acceptHeader("text/html,application/xhtml+xml,application/xml")
            .acceptLanguageHeader("en-US,en;q=0.5")
            .acceptEncodingHeader("gzip, deflate").contentTypeHeader("application/json");
    ScenarioBuilder scenarioBuilder = scenario("CreatePerson").exec(search);

    {
        setUp(scenarioBuilder.injectOpen(atOnceUsers(1))).protocols(httpProtocol);
    }

[slandelle]

So your group duration is equal to:
3 x (“CreatePerson API” response time + 1 + asLongAs times x (checkPersonGenerated + 1))

So first, is your group at the right place? You’re measuring how long it takes to process CreatePerson 3 times. Shouldn’t you measure how long it takes to process CreatePerson once? In this case, the group should be inside the repeat loop, not the other way around.

Then, you didn’t provide any information about how many times the asLongAs loop ends up being executed, nor how long checkPersonGenerated takes. This is were the extra seconds are being spent. If you want to debug this, you should add some debug printing there (logback).

Finally, if checkPersonGenerated is a blocking call (JDBC maybe?), it will harm performance under load. How bad depends on how long it takes.

[Ashwani]

Hi,
This is my requirement. I need to measure how much time an async call takes to finish. Gatling calls an API, it immediately returns a response/ack and behind the scenes the task is picked up from queue and once finished, the database is updated. I will either have an API to query that resource(which will eventually check DB) or I need to directly query DB. The resource might take few secs to get generated in DB. Let me know the best way how to do it?

Group(Async API, Query API/DB Query). I need to measure the time for this group to complete. I am not asking where the time has gone.

So first, is your group at the right place?

I have corrected the group. Attaching the code. I guess now it is correct.

Then, you didn’t provide any information about how many times the asLongAs loop ends up being executed, nor how long checkPersonGenerated takes.

The loop should execute till it gets the resource that should have been created. To avoid bombarding query API, I am introducing a delay.

This is were the extra seconds are being spent.

Yes, I know

Finally, if checkPersonGenerated is a blocking call (JDBC maybe?), it will harm performance under load. How bad depends on how long it takes.

I am not asking where the time has lost. I know. As I mentioned above, I have switched to API call which eventually queries DB only. It is fast. Please see the simulation logs attached.

Let me know if attached logs are as it should be.

ChainBuilder search =
            repeat(3, "n").on((feed(jdbcFeeder).exec(session -> {
                        Object req = session.get("person_request");
                        return session;
                    }).group("Async")
                    .on(
                            exec(
                                    http("CreatePerson API")
                                            .post("/owners/new").body(StringBody("#{person_request}"))
                                            .check(status().is(200))
                            ).pause(1).asLongAs(session -> !dataAvailable(session))
                                    .on(
                                            //exec(this::checkPersonGenerated)

                                            exec(
                                                    http("Find Person API")
                                                            .post("/owners").body(StringBody(findPersonJson(searchLastName)))
                                                            .check(status().is(200)).check(bodyString().saveAs(
                                                                    "person-resp"))

                                            ).exec(this::checkPersonGenerated).pause(2)
                                    )))
                                    .pause(1));

One question, For group timing, why it is showing 19ms, 3ms, 3ms. The difference of start and end time which is what I want is coming to be 13 sec, 1 sec, 1 sec approx. That is what I want.

I have executed group 3 times. Only one group I could introduce artificial delay in create a resource at the backend.

[slandelle]

Important note: this log file is an internal datastore for the reports module generation. Format is an internal and subject to changes without prior notice. Don’t build custom components on top of it.

19, 3 and 3 are the cumulated response times, not the duration.
The duration is the difference between the first 2 timestamps.

The 1st group iteration took 13136ms: “CreatePerson API” + 1s pause + 6 * (“Find Person API” + 2s pause).

The 2nd and 3rd group iterations were way faster as “Find Person API” was not executed, most likely because dataAvailable returned true.

Note: weird that “Find Person API” is a POST.

[Ashwani]

Thanks Understood. Currently I see following graphs for group duration

Could I do something to see the stats like below for group duration instead of group response times. The above graphs are just showing the distributions only.

[Ashwani]

@slandelle

Note: weird that “Find Person API” is a POST.

Kindly ignore. It is not real world API.

@slandelle

The 2nd and 3rd group iterations were way faster as “Find Person API” was not executed, most likely because dataAvailable returned true.

Yes, I think I need to reset the flag in session. It is checking the flag in session

private boolean dataAvailable(Session session) {
        try {
            return session.getBoolean("data_avail");
        } catch (Exception e) {
            return false;
        }
    }

[slandelle]

Yes, I think I need to reset the flag in session. It is checking the flag in session

Absolutely, at the beginning or at the end or your repeat loop

[slandelle]

@Ashwani

Could I do something to see the stats like below for group duration instead of group response times. The above graphs are just showing the distributions only.

Gatling Enterprise: