You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@trafficserver.apache.org by zw...@apache.org on 2021/07/28 22:42:40 UTC
[trafficserver] branch 9.1.x updated: Added missing milestones and
updated slow log report script (#8168)
This is an automated email from the ASF dual-hosted git repository.
zwoop pushed a commit to branch 9.1.x
in repository https://gitbox.apache.org/repos/asf/trafficserver.git
The following commit(s) were added to refs/heads/9.1.x by this push:
new 8a8f1b7 Added missing milestones and updated slow log report script (#8168)
8a8f1b7 is described below
commit 8a8f1b7856b4802f1503c73364c34b9bcb1a7cc4
Author: Bryan Call <bc...@apache.org>
AuthorDate: Mon Jul 26 16:27:40 2021 -0700
Added missing milestones and updated slow log report script (#8168)
Moved the cache open read end milestone to the end of the method
(cherry picked from commit 84cf02e6d87377d68cce8f687f6c001bc43aea47)
---
proxy/http/HttpSM.cc | 11 +++++++++--
tools/slow_log_report.pl | 12 ++++++------
2 files changed, 15 insertions(+), 8 deletions(-)
diff --git a/proxy/http/HttpSM.cc b/proxy/http/HttpSM.cc
index ad1f5c1..856c110 100644
--- a/proxy/http/HttpSM.cc
+++ b/proxy/http/HttpSM.cc
@@ -2623,7 +2623,6 @@ int
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));
@@ -2679,6 +2678,8 @@ HttpSM::state_cache_open_read(int event, void *data)
break;
}
+ milestones[TS_MILESTONE_CACHE_OPEN_READ_END] = Thread::get_hrtime();
+
return 0;
}
@@ -7231,11 +7232,14 @@ HttpSM::update_stats()
"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 "
@@ -7250,11 +7254,14 @@ HttpSM::update_stats()
"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),
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 @@ sub displayStat($)
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 @@ sub displayStat($)
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 @@ sub displayStat($)
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});