detailed transaction time logs

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

detailed transaction time logs

Mateusz Zajakala
Hi,

I'm trying to debug a reverse proxy which occasionally takes longer than usual time to serve a client. I can see in the logs e.g. that the request took 10 times the usual amount of time for similar file, however I can't say whether it was caused by the origin side or client side (i.e. was the issue when retrieving content from origin or serving it to client).

Is there any way to get more detailed logs for response time? I'm looking at 'ttms' value, is there any log to indicate "origin connection time", "time between sending request to origin and finishing reading response", "time between starting and finishing serving response to client" etc. That would help with optimizing...

If there is nothing in the logs, maybe there is some useful statistic I should look into?

Thanks
Mateusz
Reply | Threaded
Open this post in threaded view
|

Re: detailed transaction time logs

Sudheer Vinukonda-2
You may try turning on slow logs that record more detailed individual milestones (time taken for each internal state during the transaction lifecycle) for transactions that take longer than a specified duration.


- Sudheer

On Nov 21, 2016, at 3:19 AM, Mateusz Zajakala <[hidden email]> wrote:

Hi,

I'm trying to debug a reverse proxy which occasionally takes longer than usual time to serve a client. I can see in the logs e.g. that the request took 10 times the usual amount of time for similar file, however I can't say whether it was caused by the origin side or client side (i.e. was the issue when retrieving content from origin or serving it to client).

Is there any way to get more detailed logs for response time? I'm looking at 'ttms' value, is there any log to indicate "origin connection time", "time between sending request to origin and finishing reading response", "time between starting and finishing serving response to client" etc. That would help with optimizing...

If there is nothing in the logs, maybe there is some useful statistic I should look into?

Thanks
Mateusz
Reply | Threaded
Open this post in threaded view
|

Re: detailed transaction time logs

Mateusz Zajakala
Sudheer,

this is exactly what I was looking for. Many thanks!

Mateusz

On Mon, Nov 21, 2016 at 2:39 PM, Sudheer Vinukonda <[hidden email]> wrote:
You may try turning on slow logs that record more detailed individual milestones (time taken for each internal state during the transaction lifecycle) for transactions that take longer than a specified duration.


- Sudheer

On Nov 21, 2016, at 3:19 AM, Mateusz Zajakala <[hidden email]> wrote:

Hi,

I'm trying to debug a reverse proxy which occasionally takes longer than usual time to serve a client. I can see in the logs e.g. that the request took 10 times the usual amount of time for similar file, however I can't say whether it was caused by the origin side or client side (i.e. was the issue when retrieving content from origin or serving it to client).

Is there any way to get more detailed logs for response time? I'm looking at 'ttms' value, is there any log to indicate "origin connection time", "time between sending request to origin and finishing reading response", "time between starting and finishing serving response to client" etc. That would help with optimizing...

If there is nothing in the logs, maybe there is some useful statistic I should look into?

Thanks
Mateusz

Reply | Threaded
Open this post in threaded view
|

Re: detailed transaction time logs

Miles Libbey
In ATS 6+ you use custom logging to log Milestone data about
transactions ("{Milestone field name}ms" and {Milestone field
name1-Milestone field name2}msdms). Milestones are here:
https://docs.trafficserver.apache.org/en/latest/developer-guide/api/functions/TSHttpTxnMilestoneGet.en.html#c.TSHttpTxnMilestoneGet
So, I think Origin time to first byte would be
%<{TS_MILESTONE_SERVER_FIRST_READ-TS_MILESTONE_SERVER_FIRST_CONNECT}msdms>

miles

On Mon, Nov 21, 2016 at 5:58 AM, Mateusz Zajakala <[hidden email]> wrote:

> Sudheer,
>
> this is exactly what I was looking for. Many thanks!
>
> Mateusz
>
> On Mon, Nov 21, 2016 at 2:39 PM, Sudheer Vinukonda
> <[hidden email]> wrote:
>>
>> You may try turning on slow logs that record more detailed individual
>> milestones (time taken for each internal state during the transaction
>> lifecycle) for transactions that take longer than a specified duration.
>>
>>
>> https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.config.en.html#proxy-config-http-slow-log-threshold
>>
>> - Sudheer
>>
>> On Nov 21, 2016, at 3:19 AM, Mateusz Zajakala <[hidden email]> wrote:
>>
>> Hi,
>>
>> I'm trying to debug a reverse proxy which occasionally takes longer than
>> usual time to serve a client. I can see in the logs e.g. that the request
>> took 10 times the usual amount of time for similar file, however I can't say
>> whether it was caused by the origin side or client side (i.e. was the issue
>> when retrieving content from origin or serving it to client).
>>
>> Is there any way to get more detailed logs for response time? I'm looking
>> at 'ttms' value, is there any log to indicate "origin connection time",
>> "time between sending request to origin and finishing reading response",
>> "time between starting and finishing serving response to client" etc. That
>> would help with optimizing...
>>
>> If there is nothing in the logs, maybe there is some useful statistic I
>> should look into?
>>
>> Thanks
>> Mateusz
>
>
Reply | Threaded
Open this post in threaded view
|

Re: detailed transaction time logs

Mateusz Zajakala
Thanks,

it seems that for problematic transactions all time is spent between "server_read_header_done" (almost always at 0.000) and "server_close" (even 5.000 and more). My guess is that I need to look into low-level network performance (drivers/tcp bottlenecks), because all time is spent transfering HTTP data?

One thing is not clear though, how is it possible that "server_read_header_done" is always at 0 and it is AFTER http response headers are already parsed? This could mean that connection to origin is fast and only transfering the actual content (file) takes time, but my origin (httpd 2.4.6) reports that it took max 1 microsecond to serve the file (all files are served from RAM).

Any ideas where I should look to find what takes so much time on those occastional slow requests?

Thanks a lot!
Mat




On Mon, Nov 21, 2016 at 5:41 PM, Miles Libbey <[hidden email]> wrote:
In ATS 6+ you use custom logging to log Milestone data about
transactions ("{Milestone field name}ms" and {Milestone field
name1-Milestone field name2}msdms). Milestones are here:
https://docs.trafficserver.apache.org/en/latest/developer-guide/api/functions/TSHttpTxnMilestoneGet.en.html#c.TSHttpTxnMilestoneGet
So, I think Origin time to first byte would be
%<{TS_MILESTONE_SERVER_FIRST_READ-TS_MILESTONE_SERVER_FIRST_CONNECT}msdms>

miles

On Mon, Nov 21, 2016 at 5:58 AM, Mateusz Zajakala <[hidden email]> wrote:
> Sudheer,
>
> this is exactly what I was looking for. Many thanks!
>
> Mateusz
>
> On Mon, Nov 21, 2016 at 2:39 PM, Sudheer Vinukonda
> <[hidden email]> wrote:
>>
>> You may try turning on slow logs that record more detailed individual
>> milestones (time taken for each internal state during the transaction
>> lifecycle) for transactions that take longer than a specified duration.
>>
>>
>> https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.config.en.html#proxy-config-http-slow-log-threshold
>>
>> - Sudheer
>>
>> On Nov 21, 2016, at 3:19 AM, Mateusz Zajakala <[hidden email]> wrote:
>>
>> Hi,
>>
>> I'm trying to debug a reverse proxy which occasionally takes longer than
>> usual time to serve a client. I can see in the logs e.g. that the request
>> took 10 times the usual amount of time for similar file, however I can't say
>> whether it was caused by the origin side or client side (i.e. was the issue
>> when retrieving content from origin or serving it to client).
>>
>> Is there any way to get more detailed logs for response time? I'm looking
>> at 'ttms' value, is there any log to indicate "origin connection time",
>> "time between sending request to origin and finishing reading response",
>> "time between starting and finishing serving response to client" etc. That
>> would help with optimizing...
>>
>> If there is nothing in the logs, maybe there is some useful statistic I
>> should look into?
>>
>> Thanks
>> Mateusz
>
>

Reply | Threaded
Open this post in threaded view
|

Re: detailed transaction time logs

Sudheer Vinukonda-2
ATS by default supports connection pools on the Origin side (meaning, idle (persistent) connections are reused for subsequent requests). This may be the reason why you probably see the server header read done in no time.

For tuning the transfer time, if you are not already using it, you may enable chunked encoding (HTTP/1.1+). Also, is your origin physically outside the ATS box or are you running it on the same host? There are some tcp socket settings you can tune in ats records config (e.g so_linger, nagle etc).

- Sudheer

On Nov 22, 2016, at 10:51 AM, Mateusz Zajakala <[hidden email]> wrote:

Thanks,

it seems that for problematic transactions all time is spent between "server_read_header_done" (almost always at 0.000) and "server_close" (even 5.000 and more). My guess is that I need to look into low-level network performance (drivers/tcp bottlenecks), because all time is spent transfering HTTP data?

One thing is not clear though, how is it possible that "server_read_header_done" is always at 0 and it is AFTER http response headers are already parsed? This could mean that connection to origin is fast and only transfering the actual content (file) takes time, but my origin (httpd 2.4.6) reports that it took max 1 microsecond to serve the file (all files are served from RAM).

Any ideas where I should look to find what takes so much time on those occastional slow requests?

Thanks a lot!
Mat




On Mon, Nov 21, 2016 at 5:41 PM, Miles Libbey <[hidden email]> wrote:
In ATS 6+ you use custom logging to log Milestone data about
transactions ("{Milestone field name}ms" and {Milestone field
name1-Milestone field name2}msdms). Milestones are here:
https://docs.trafficserver.apache.org/en/latest/developer-guide/api/functions/TSHttpTxnMilestoneGet.en.html#c.TSHttpTxnMilestoneGet
So, I think Origin time to first byte would be
%<{TS_MILESTONE_SERVER_FIRST_READ-TS_MILESTONE_SERVER_FIRST_CONNECT}msdms>

miles

On Mon, Nov 21, 2016 at 5:58 AM, Mateusz Zajakala <[hidden email]> wrote:
> Sudheer,
>
> this is exactly what I was looking for. Many thanks!
>
> Mateusz
>
> On Mon, Nov 21, 2016 at 2:39 PM, Sudheer Vinukonda
> <[hidden email]> wrote:
>>
>> You may try turning on slow logs that record more detailed individual
>> milestones (time taken for each internal state during the transaction
>> lifecycle) for transactions that take longer than a specified duration.
>>
>>
>> https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.config.en.html#proxy-config-http-slow-log-threshold
>>
>> - Sudheer
>>
>> On Nov 21, 2016, at 3:19 AM, Mateusz Zajakala <[hidden email]> wrote:
>>
>> Hi,
>>
>> I'm trying to debug a reverse proxy which occasionally takes longer than
>> usual time to serve a client. I can see in the logs e.g. that the request
>> took 10 times the usual amount of time for similar file, however I can't say
>> whether it was caused by the origin side or client side (i.e. was the issue
>> when retrieving content from origin or serving it to client).
>>
>> Is there any way to get more detailed logs for response time? I'm looking
>> at 'ttms' value, is there any log to indicate "origin connection time",
>> "time between sending request to origin and finishing reading response",
>> "time between starting and finishing serving response to client" etc. That
>> would help with optimizing...
>>
>> If there is nothing in the logs, maybe there is some useful statistic I
>> should look into?
>>
>> Thanks
>> Mateusz
>
>