It looks like it is taking a lot of time at the end of your requests. 41.19 at the 95th percentile seems high, but it depends on how big your responses are.
Do you have large responses? What version of ATS are you running? Do you have any plugins running? -Bryan > On Oct 25, 2016, at 12:58 AM, Paolo Barbato <[email protected]> wrote: > > Hi Bryan, > > thanks to point me to that script. > > After a couple of days here the results: > > [root@cache paolob]# grep 'Slow Request' > /usr/local/var/log/trafficserver/diags.log | perl slow_log_report.pl > key total count mean median > 95th 99th min max > ua_begin 0.82 1571951.00 0.00 0.00 > 0.00 0.00 0.00 0.01 > ua_first_read 2.02 1571951.00 0.00 0.00 > 0.00 0.00 0.00 0.01 > ua_read_header_done 85.10 1571951.00 0.00 0.00 > 0.00 0.00 0.00 5.63 > cache_open_read_begin 87.68 801688.00 0.00 0.00 > 0.00 0.00 0.00 5.63 > cache_open_read_end 1357.89 801688.00 0.00 0.00 > 0.01 0.02 0.00 5.63 > dns_lookup_begin 6386.42 1518318.00 0.00 0.00 > 0.00 0.01 0.00 92.87 > dns_lookup_end 39132.35 1518318.00 0.03 0.00 > 0.06 0.13 0.00 92.87 > server_connect 171053.55 1506039.00 0.11 0.00 > 0.06 0.12 0.00 636.65 > server_first_read 122307.94 743473.00 0.16 0.06 > 0.37 1.35 0.00 512.89 > server_read_header_done 122428.83 743473.00 0.16 0.06 > 0.37 1.35 0.00 512.89 > server_close 193729.20 653255.00 0.30 0.07 > 0.47 2.47 0.00 4646.52 > ua_close 175533286.53 1571951.00 111.67 0.29 > 41.19 157.10 0.00 14401.00 > sm_finish 175550504.61 1571951.00 111.68 0.29 > 41.19 157.17 0.00 14401.00 > NOTE: Times are in seconds > > It seems to not too bad, right ? > > Regards, > Paolo. > >> On 20 Oct 2016, at 23:24, Bryan Call <[email protected] >> <mailto:[email protected]>> wrote: >> >> Yes, the configuration option for slow log is in milliseconds. Setting it >> to 1 is a good value. >> >> You can also run a reporting script that I use to process the slow logs. >> https://github.com/apache/trafficserver/blob/master/tools/slow_log_report.pl >> <https://github.com/apache/trafficserver/blob/master/tools/slow_log_report.pl> >> >> Commands for slow log processing: >> wget —no-check-certificate -P ~/ >> https://raw.githubusercontent.com/apache/trafficserver/master/tools/slow_log_report.pl >> >> <https://imsva91-ctp.trendmicro.com/wis/clicktime/v1/query?url=https%3a%2f%2fraw.githubusercontent.com%2fapache%2ftrafficserver%2fmaster%2ftools%2fslow%5flog%5freport.pl&umid=A72EDA11-3F52-8D05-90B0-7AD4DA931D39&auth=bd96fefaa6fd290f4fa376a16803b93f75516c9c-574cb5906d3237d233da783141f0b0cf9eb79fe7>; >> chmod 755 ~/slow_log_report.pl; >> grep 'Slow Request' /usr/local/var/log/trafficserver/diags.log | >> ~/slow_log_report.pl >> >> -Bryan >> >> >> >> >>> On Oct 19, 2016, at 11:50 PM, Paolo Barbato <[email protected] >>> <mailto:[email protected]>> wrote: >>> >>> Hi Bryan, >>> >>> congratulation for recent nomination. >>> >>> >>>> On 19 Oct 2016, at 17:33, Bryan Call <[email protected] >>>> <mailto:[email protected]>> wrote: >>>> >>>> Are the response times slow on the ATS server? >>> >>> I say not. ATS behaves fast as I can see (I’m switching from squid), >>> although I’v not precise metrics. Time to time a new web page request hang >>> at client side, when ATS is in the middle. >>> >>> >>>> If so, you can turn on slow log and see where the requests are slowing >>>> down. >>> >>> see bottom lines >>> >>>> Can you give some details on the type of requests TLS/SSL vs non-encrypted >>> >>> From application stats on uplink ATS cache server does 40% SSL (443) and >>> 35% (80). >>> >>>> or http/1.1 vs http/2? >>>> >>> Actually I’ve CONFIG proxy.config.http2.enabled INT 0 >>> >>> >>>> Documentation on slow log: >>>> https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.config.en.html?highlight=slow%20log#proxy-config-http-slow-log-threshold >>>> >>>> <https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.config.en.html?highlight=slow%20log#proxy-config-http-slow-log-threshold> >>>> >>>> Example for slow log (times in seconds): >>>> $ sudo /usr/local/bin/traffic_ctl config set >>>> proxy.config.http.slow.log.threshold 1 >>> >>> This means 1 millisecond, is that a correct value to debug, or should I set >>> some seconds ? >>> >>>> $ tail /usr/local/var/log/trafficserver/diags.log >>>> [Oct 19 08:27:20.578] Server {0x2b7839272700} ERROR: [2] Slow Request: >>>> client_ip: 127.0.0.1:44630 url: http://www.yahoo.com/ >>>> <http://www.yahoo.com/> status: 301 unique id: redirection_tries: 0 >>>> bytes: 304 fd: 0 client state: 0 server state: 9 ua_begin: 0.000 >>>> ua_first_read: 0.000 ua_read_header_done: 0.000 cache_open_read_begin: >>>> 0.000 cache_open_read_end: 0.000 dns_lookup_begin: 0.000 dns_lookup_end: >>>> 0.000 server_connect: 0.000 server_first_read: 0.241 >>>> server_read_header_done: 0.241 server_close: 0.241 ua_close: 0.241 >>>> sm_finish: 0.241 plugin_active: -0.001 plugin_total: -0.001 >>>> >>>> >>> >>> >>> Regards, >>> Paolo. >>> >>> >>>> -Bryan >>>> >>>> >>>> >>>> >>>> >>>>> On Oct 19, 2016, at 4:46 AM, Paolo Barbato <[email protected] >>>>> <mailto:[email protected]>> wrote: >>>>> >>>>> I’m using ATS as forward proxy, with a cache of 50 GB on disk, and >>>>> 100/150 clients. In front there’s a CheckPoint firewall. >>>>> >>>>> ATS is installed on a CentOS 7.2 with 9 GB ram hosted on a VMWare farm. >>>>> >>>>> It works mostly fine, but time to time users (and me) observe hang when >>>>> loading pages, not specific urls. >>>>> >>>>> CPU load is really low as well as memory usage (no swap at all). >>>>> >>>>> Monitoring cache port 8080, I see more or less 600/800 established >>>>> connection per seconds during peak hours, with growing closed one that >>>>> top at 500 at end of the day . >>>>> >>>>> >>>>> If clients bypass ATS no issues are observed. >>>>> >>>>> Any hints on possible reasons? >>>>> >>>>> Regards, >>>>> paolo >>>>> >>>>> ------------------------------------------------------------------------------------------------ >>>>> Paolo Barbato >>>>> >>>>> Consorzio RFX >>>>> corso Stati Uniti,4 >>>>> 35127 Padova - Italy >>>>> Network Administrator >>>>> phone: +39 049 8295097 fax: +39 049 8700718 >>>>> ------------------------------------------------------------------------------------------------ >>>>> >>>> >>> >>> ------------------------------------------------------------------------------------------------ >>> Paolo Barbato >>> >>> Consorzio RFX >>> corso Stati Uniti,4 >>> 35127 Padova - Italy >>> Network Administrator >>> phone: +39 049 8295097 fax: +39 049 8700718 >>> ------------------------------------------------------------------------------------------------ >> > > ------------------------------------------------------------------------------------------------ > Paolo Barbato > > Consorzio RFX > <https://www.igi.cnr.it/>corso Stati Uniti,4 > > 35127 Padova - Italy > Network Administrator > phone: +39 049 8295097 fax: +39 049 8700718 > ------------------------------------------------------------------------------------------------ >
