commit 84cf02e6d87377d68cce8f687f6c001bc43aea47
author Bryan Call <bcall@apache.org> Mon Jul 26 16:27:40 2021 -0700
committer GitHub <noreply@github.com> Mon Jul 26 16:27:40 2021 -0700
tree 03f8c98c303b2f4d090662fb7075ed58a8193eb7
parent ceb2b387199685cc70c067017b4a720339623e43

Added missing milestones and updated slow log report script (#8168)

Moved the cache open read end milestone to the end of the method

proxy/http/HttpSM.cc

diff --git a/proxy/http/HttpSM.cc b/proxy/http/HttpSM.cc
index 1d697ba..67d18b8 100644
--- a/proxy/http/HttpSM.cc
+++ b/proxy/http/HttpSM.cc
@@ -2659,7 +2659,6 @@
 HttpSM::state_cache_open_read(int event, void *data)
 {
   STATE_ENTER(&HttpSM::state_cache_open_read, event);
-  milestones[TS_MILESTONE_CACHE_OPEN_READ_END] = Thread::get_hrtime();
 
   pending_action.clear_if_action_is(reinterpret_cast<Action *>(data));
 
@@ -2715,6 +2714,8 @@
     break;
   }
 
+  milestones[TS_MILESTONE_CACHE_OPEN_READ_END] = Thread::get_hrtime();
+
   return 0;
 }
 
@@ -7287,11 +7288,14 @@
           "fd: %d "
           "client state: %d "
           "server state: %d "
+          "tls_handshake: %.3f "
           "ua_begin: %.3f "
           "ua_first_read: %.3f "
           "ua_read_header_done: %.3f "
           "cache_open_read_begin: %.3f "
           "cache_open_read_end: %.3f "
+          "cache_open_write_begin: %.3f "
+          "cache_open_write_end: %.3f "
           "dns_lookup_begin: %.3f "
           "dns_lookup_end: %.3f "
           "server_connect: %.3f "
@@ -7306,11 +7310,14 @@
           "plugin_total: %.3f",
           sm_id, client_ip, t_state.client_info.src_addr.host_order_port(), ua_txn ? ua_txn->get_protocol_string() : "-1",
           url_string, status, unique_id_string, redirection_tries, client_response_body_bytes, fd, t_state.client_info.state,
-          t_state.server_info.state, milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_UA_BEGIN),
+          t_state.server_info.state, milestones.difference_sec(TS_MILESTONE_TLS_HANDSHAKE_START, TS_MILESTONE_TLS_HANDSHAKE_END),
+          milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_UA_BEGIN),
           milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_UA_FIRST_READ),
           milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_UA_READ_HEADER_DONE),
           milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_CACHE_OPEN_READ_BEGIN),
           milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_CACHE_OPEN_READ_END),
+          milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_CACHE_OPEN_WRITE_BEGIN),
+          milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_CACHE_OPEN_WRITE_END),
           milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_DNS_LOOKUP_BEGIN),
           milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_DNS_LOOKUP_END),
           milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_CONNECT),

tools/slow_log_report.pl

diff --git a/tools/slow_log_report.pl b/tools/slow_log_report.pl
index 81fb52d..317fa10 100755
--- a/tools/slow_log_report.pl
+++ b/tools/slow_log_report.pl
@@ -41,10 +41,10 @@
     printf("%25s %10s %10s %10s %10s %10s %10s %10s %10s\n",
         'key', 'total', 'count', 'mean', 'median', '95th', '99th', 'min', 'max');
     foreach my $key (
-        'ua_begin',            'ua_first_read',     'ua_read_header_done',     'cache_open_read_begin',
-        'cache_open_read_end', 'dns_lookup_begin',  'dns_lookup_end',          'server_connect',
-        'server_connect_end',  'server_first_read', 'server_read_header_done', 'server_close',
-        'ua_close',            'sm_finish'
+        'tls_handshake', 'ua_begin', 'ua_first_read', 'ua_read_header_done', 'cache_open_read_begin',
+        'cache_open_read_end', 'cache_open_write_begin', 'cache_open_write_end', 'dns_lookup_begin',
+        'dns_lookup_end', 'server_connect', 'server_connect_end',  'server_first_read',
+        'server_read_header_done', 'server_close', 'ua_close', 'sm_finish', 'plugin_active', 'plugin_total'
       )
     {
 
@@ -64,7 +64,7 @@
         my $mean   = 0;
         $mean = $total / $count if $count > 0;
 
-        printf("%25s %10.2f %10.2f %10.2f %10.2f %10.2f %10.2f %10.2f %10.2f\n",
+        printf("%25s %10.4f %10.4f %10.4f %10.4f %10.4f %10.4f %10.4f %10.4f\n",
             $key, $total, $count, $mean, $median, $p95th, $p99th, $min, $max);
     }
     print "NOTE: Times are in seconds\n";
@@ -78,7 +78,7 @@
         s/unique id/unique_id/;
         s/server state/server_state/;
         s/client state/client_state/;
-        if (m|Slow Request: .+ (ua_begin: .+)|) {
+        if (m|Slow Request: .+ (tls_handshake: .+)|) {
             my %data = split(/: | /, $1);
             foreach my $key (keys %data) {
                 next if (!defined $data{$key});