You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@trafficserver.apache.org by Mateusz Zajakala <za...@gmail.com> on 2016/11/21 11:19:35 UTC
detailed transaction time logs
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
Re: detailed transaction time logs
Posted by Sudheer Vinukonda <su...@yahoo.com>.
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 <za...@gmail.com> 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 <ml...@apache.org> 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 <za...@gmail.com> wrote:
>> > Sudheer,
>> >
>> > this is exactly what I was looking for. Many thanks!
>> >
>> > Mateusz
>> >
>> > On Mon, Nov 21, 2016 at 2:39 PM, Sudheer Vinukonda
>> > <su...@yahoo.com> 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 <za...@gmail.com> 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
>> >
>> >
>
Re: detailed transaction time logs
Posted by Mateusz Zajakala <za...@gmail.com>.
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 <ml...@apache.org> 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 <za...@gmail.com>
> wrote:
> > Sudheer,
> >
> > this is exactly what I was looking for. Many thanks!
> >
> > Mateusz
> >
> > On Mon, Nov 21, 2016 at 2:39 PM, Sudheer Vinukonda
> > <su...@yahoo.com> 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 <za...@gmail.com>
> 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
> >
> >
>
Re: detailed transaction time logs
Posted by Miles Libbey <ml...@apache.org>.
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 <za...@gmail.com> wrote:
> Sudheer,
>
> this is exactly what I was looking for. Many thanks!
>
> Mateusz
>
> On Mon, Nov 21, 2016 at 2:39 PM, Sudheer Vinukonda
> <su...@yahoo.com> 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 <za...@gmail.com> 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
>
>
Re: detailed transaction time logs
Posted by Mateusz Zajakala <za...@gmail.com>.
Sudheer,
this is exactly what I was looking for. Many thanks!
Mateusz
On Mon, Nov 21, 2016 at 2:39 PM, Sudheer Vinukonda <
sudheervinukonda@yahoo.com> 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 <za...@gmail.com> 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
>
>
Re: detailed transaction time logs
Posted by Sudheer Vinukonda <su...@yahoo.com>.
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 <za...@gmail.com> 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