Response Time

[john.j...@gmail.com]

I would kindly like to know if there is a possibility on Glowroot to filter a response time specific to a method.
I am using glowroot central with a Glowroot-Agent with absolutely no change in code in my standalone Java based application.
The class which I am trying to monitor extends another and overrides the method that receives the requests. I am trying to monitor the response time of a method being called after the request is made.

I am creating a new instrumentation, adding the method name, and capturing the transactions. Doing so still gives me the total response time and not the response time of the method.

 

[Trask Stalnaker]

Hi John,

Thanks for posting! There are a couple of options:

* If you want to get your method timing as part of the overall transaction, you should see that timing in the Breakdown section already, e.g.

* If you want it to capture an entirely new transaction for that method, you can configure that in the Instrumentation (this is a new feature so you'll , e.g.

Let me know if this gets you what you are looking for.

Thanks,

Trask

[john.j...@gmail.com]

Hi Trask,

I want the timer to have the total response time of the method only.
If I select "capture a new transaction" the total response time remains the total but the breakdown shows only the method.

Thanks,

John

[Trask Stalnaker]

Hi John,

I don't think I'm understanding still.

The timer captures the how much time passes between entering the method and returning from the method.

Do you want to capture the time spent in the method body, but excluding other methods called inside of that method?

Thanks,

Trask

[john.j...@gmail.com]

Hi Trask,

I have a method which takes around 33ms to complete.

I want to capture the complete execution time of that method - the time entering the method and returning from the method.

I have created an instrumentation to capture a transaction for the specific method and I have set it to capture a new transaction but still it captures the time from the start of the request to the end of it.

In the above screenshot the breakdown has a total 5,318.6ms which is the execution time of the complete request not the method.

Thanks,

John

[Trask Stalnaker]

Hi John,

Thanks for the explanation.  I think I understand now, but I tried it out locally and didn't have any luck reproducing the same behavior.

Can you export the two Glowroot traces (the trace for the full request, and the trace for the method), and attach those?

Hopefully that will give me a better idea what might be happening.

Thanks,

Trask

[Trask Stalnaker]

Hi John,

One other question, are you configuring the Instrumentation via the UI? If so, can export and post the json for the Instrumentation?

Thanks,

Trask

[john.j...@gmail.com]

Hi Trask,

After restarting the glowroot-centeral, the response time of the first 2 transactions are always correct, the problem starts after the 3rd transaction where the response time is now the total and after that all the transactions start having the total as the response time.

Kindly find below the JSON for the instrumentation that I want. I have set the slow threshold to 0 just for testing.

Also, the transactions in the images below are similar and should have around the same response time.

{
  "className": "net.agi.AuthCard",
  "methodName": "doAuth",
  "methodParameterTypes": [
    "java.lang.String",
    "java.lang.String",
    "java.lang.String",
    "java.lang.String",
    "java.lang.String",
    "java.lang.String",
    "java.lang.String",
    "boolean"
  ],
  "captureKind": "transaction",
  "transactionType": "Service",
  "transactionNameTemplate": "doAuth",
  "transactionSlowThresholdMillis": 0,
  "alreadyInTransactionBehavior": "capture-new-transaction",
  "traceEntryMessageTemplate": "doAuth",
  "timerName": "doAuth"
}

Regards,

John

[Trask Stalnaker]

Can you expand the profile sections of those two traces? What do you have the profiling interval set to in your configuration?

Thanks,
Trask

[john.j...@gmail.com]

The profiling interval is set to 1000ms.

Regards,

John

[Trask Stalnaker]

Hi John,

The profile (5 samples taken at ~ 1000 millisecond intervals) seems to point to all of that time being inside of doAuth:

[john.j...@gmail.com]

Hi Trask,

Both transactions are similar yet with a different response time, the method doAuth only performs the http request which is shown in the trace (it ends at the 4th log info). The response time spent in doAuth is around 23ms as shown in screenshot 2a.

A thread starts in AuthCard.service before calling the method doAuth. That thread blocks the service from terminating for around 5 seconds. In 3a the response time 5283 which is marked as blocked time is the response time of that thread and not doAuth.

Regards,

John

[Trask Stalnaker]

Hi John,

I think I may still not be understanding.  This is what I am seeing when looking at that 5 second doAuth trace:

It looks like the doAuth() method starts, and initially calls AgiOperations.getVariable(), which gets stuck for ~5 seconds inside of AgiChannelImpl.sendCommand().

Then after AgiOperations.getVariable() returns, the doAuth() method proceeds and performs the "http client request" and the 4 "log info".

Maybe try adding a trace entry instrumentation on AgiOperations.getVariable() or AgiChannelImpl.sendCommand() to help fill in the trace entry timeline and better see what's happening?

Thanks,

Trask

[john.j...@gmail.com]

Hi Trask,

I would only like to monitor doAuth and nothing else from that class. The doAuth method logs and makes the request (whatever you see in the trace), there are no AGI operations done in the method. The AgiChannelImpl.sendCommand() is the one that blocks the service but it should not be there when I'm monitoring the method doAuth, that operation is done on a different thread. The thread blocks the service until the sendCommand is returned. The doAuth is inside the service and is not in the thread, the thread and the doAuth work in parallel and are completely independent.

I noticed that when I set the profiling interval to a high value such as 10000 in this case, to disable the feature, I start getting the correct response time (around 23ms). But once every few transaction I am still getting a transaction with a profile trace and the incorrect response time (around 5500ms).

Regards,

John

[Trask Stalnaker]

I'm confused.  You mention there are no AGI operations done in the doAuth() method, but I can see from the profile that AuthCard.doAuth() line 279 calls AgiOperations.getVariable().

[john.j...@gmail.com]

The profile is incorrect it includes part of the service. The correct profile should only have the lines below line 7 from 2a, while the profile trace in 3a is incomplete and incorrect. It has traces from the method and the thread.

[Trask Stalnaker]

Can you add this instrumentation and send an updated trace? (if it captures the new "send command" trace entry, expand its location stack trace for the screen shot)

{

  "className": "org.asteriskjava.fastagi.internal.AgiChannelImpl",

  "methodName": "sendCommand",

  "methodParameterTypes": [

    ".."

  ],

  "captureKind": "trace-entry",

  "traceEntryMessageTemplate": "send command",

  "traceEntryStackThresholdMillis": 0,

  "timerName": "send command"

}

Also, any chance you can send the AuthCard class file privately to me to review (trask.s...@gmail.com)?

Thanks,

Trask

[john.j...@gmail.com]

I was able to generate one of each. Kindly note that in both cases the service was blocked for 5 seconds.

[Trask Stalnaker]

Can you expand the profile in the last screenshot?

Thanks,
Trask

--
You received this message because you are subscribed to the Google Groups "Glowroot" group.
To unsubscribe from this group and stop receiving emails from it, send an email to glowroot+u...@googlegroups.com.
To post to this group, send email to glow...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/glowroot/51615ce3-3d03-4553-b0aa-057edbd18d50%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[john.j...@gmail.com]

[Trask Stalnaker]

The "location stack trace" in the new "send command" trace entries also shows that AuthCard.doAuth() calls AgiOperations.getVariable().

Are you sure this is not the case?

[john.j...@gmail.com]

Hi Trask,

AgiOperations.getVariable() is used two times at the very beginning in AuthCard.doAuth() but getVariable does not block. The traces given in the above pictures are correct, as well as their response times, but as you can see in 4 there is the gap in-front of the response time, the profile is showing AgiOperations.getVariable() is blocked but that cannot be true. The correct response should be as shown in picture 5.

In the above pic the gap in response time as if doAuth was waiting, including the getVariable().

Regards,

John

[Trask Stalnaker]

Can you add trace entry instrumentation on getVariable() also and re-post traces? I think that will help us explain the gap you pointed out:

{

  "className": "org.asteriskjava.fastagi.internal.AgiChannelImpl",

  "methodName": "getVariable",

  "methodParameterTypes": [

    ".."

  ],

  "captureKind": "trace-entry",

  "traceEntryMessageTemplate": "get variable",

  "traceEntryStackThresholdMillis": 0,

  "timerName": "get variable"

}

Thanks,

Trask