From f9cbee2172301df5a4aec7fa4107d36f90cfba7c Mon Sep 17 00:00:00 2001 From: Sudheer Vinukonda Date: Mon, 11 May 2020 11:53:10 -0700 Subject: [PATCH 1/4] Add metrics to track default inactivity timed out connections --- .../monitoring/statistics/core/network-io.en.rst | 1 + iocore/net/Net.cc | 6 ++++-- iocore/net/NetEvent.h | 2 ++ iocore/net/P_Net.h | 3 ++- iocore/net/UnixNet.cc | 13 +++++++++++++ iocore/net/UnixNetVConnection.cc | 4 ---- 6 files changed, 22 insertions(+), 7 deletions(-) diff --git a/doc/admin-guide/monitoring/statistics/core/network-io.en.rst b/doc/admin-guide/monitoring/statistics/core/network-io.en.rst index 5393086495a..bb25d4b2253 100644 --- a/doc/admin-guide/monitoring/statistics/core/network-io.en.rst +++ b/doc/admin-guide/monitoring/statistics/core/network-io.en.rst @@ -61,6 +61,7 @@ Network I/O :type: counter .. ts:stat:: global proxy.process.net.default_inactivity_timeout_applied integer +.. ts:stat:: global proxy.process.net.default_inactivity_timeout_count integer .. ts:stat:: global proxy.process.net.dynamic_keep_alive_timeout_in_count integer .. ts:stat:: global proxy.process.net.dynamic_keep_alive_timeout_in_total integer .. ts:stat:: global proxy.process.net.inactivity_cop_lock_acquire_failure integer diff --git a/iocore/net/Net.cc b/iocore/net/Net.cc index f5bbb886af7..c8992dd0b39 100644 --- a/iocore/net/Net.cc +++ b/iocore/net/Net.cc @@ -102,7 +102,8 @@ register_net_stats() const std::pair non_persistent[] = { {"proxy.process.net.accepts_currently_open", net_accepts_currently_open_stat}, {"proxy.process.net.connections_currently_open", net_connections_currently_open_stat}, - {"proxy.process.net.default_inactivity_timeout_applied", default_inactivity_timeout_stat}, + {"proxy.process.net.default_inactivity_timeout_applied", default_inactivity_timeout_applied_stat}, + {"proxy.process.net.default_inactivity_timeout_count", default_inactivity_timeout_count_stat}, {"proxy.process.net.dynamic_keep_alive_timeout_in_count", keep_alive_queue_timeout_count_stat}, {"proxy.process.net.dynamic_keep_alive_timeout_in_total", keep_alive_queue_timeout_total_stat}, {"proxy.process.socks.connections_currently_open", socks_connections_currently_open_stat}, @@ -130,7 +131,8 @@ register_net_stats() NET_CLEAR_DYN_STAT(socks_connections_currently_open_stat); NET_CLEAR_DYN_STAT(keep_alive_queue_timeout_total_stat); NET_CLEAR_DYN_STAT(keep_alive_queue_timeout_count_stat); - NET_CLEAR_DYN_STAT(default_inactivity_timeout_stat); + NET_CLEAR_DYN_STAT(default_inactivity_timeout_count_stat); + NET_CLEAR_DYN_STAT(default_inactivity_timeout_applied_stat); RecRegisterRawStat(net_rsb, RECT_PROCESS, "proxy.process.tcp.total_accepts", RECD_INT, RECP_NON_PERSISTENT, static_cast(net_tcp_accept_stat), RecRawStatSyncSum); diff --git a/iocore/net/NetEvent.h b/iocore/net/NetEvent.h index 2a0e8aca121..aedba75371a 100644 --- a/iocore/net/NetEvent.h +++ b/iocore/net/NetEvent.h @@ -71,6 +71,8 @@ class NetEvent ink_hrtime next_activity_timeout_at = 0; ink_hrtime submit_time = 0; + bool default_inactivity_timeout = false; + LINK(NetEvent, open_link); LINK(NetEvent, cop_link); LINKM(NetEvent, read, ready_link) diff --git a/iocore/net/P_Net.h b/iocore/net/P_Net.h index 15a55bb8bb6..79f63130444 100644 --- a/iocore/net/P_Net.h +++ b/iocore/net/P_Net.h @@ -51,7 +51,8 @@ enum Net_Stats { inactivity_cop_lock_acquire_failure_stat, keep_alive_queue_timeout_total_stat, keep_alive_queue_timeout_count_stat, - default_inactivity_timeout_stat, + default_inactivity_timeout_applied_stat, + default_inactivity_timeout_count_stat, net_fastopen_attempts_stat, net_fastopen_successes_stat, net_tcp_accept_stat, diff --git a/iocore/net/UnixNet.cc b/iocore/net/UnixNet.cc index 788c2ad6f07..c9d8ba1cec4 100644 --- a/iocore/net/UnixNet.cc +++ b/iocore/net/UnixNet.cc @@ -69,7 +69,20 @@ class InactivityCop : public Continuation continue; } + // set a default inactivity timeout if one is not set + if (ne->next_inactivity_timeout_at == 0 && nh.config.default_inactivity_timeout > 0) { + Debug("inactivity_cop", "vc: %p inactivity timeout not set, setting a default of %d", ne, + nh.config.default_inactivity_timeout); + ne->set_inactivity_timeout(HRTIME_SECONDS(nh.config.default_inactivity_timeout)); + ne->default_inactivity_timeout = true; + NET_INCREMENT_DYN_STAT(default_inactivity_timeout_applied_stat); + } + if (ne->next_inactivity_timeout_at && ne->next_inactivity_timeout_at < now) { + if (ne->default_inactivity_timeout) { + // track the connections that timed out due to default inactivity + NET_INCREMENT_DYN_STAT(default_inactivity_timeout_count_stat); + } if (nh.keep_alive_queue.in(ne)) { // only stat if the connection is in keep-alive, there can be other inactivity timeouts ink_hrtime diff = (now - (ne->next_inactivity_timeout_at - ne->inactivity_timeout_in)) / HRTIME_SECOND; diff --git a/iocore/net/UnixNetVConnection.cc b/iocore/net/UnixNetVConnection.cc index b5d2b89f95a..f85eb0f84d5 100644 --- a/iocore/net/UnixNetVConnection.cc +++ b/iocore/net/UnixNetVConnection.cc @@ -1352,10 +1352,6 @@ TS_INLINE void UnixNetVConnection::set_inactivity_timeout(ink_hrtime timeout_in) { Debug("socket", "Set inactive timeout=%" PRId64 ", for NetVC=%p", timeout_in, this); - if (timeout_in == 0) { - // set default inactivity timeout - timeout_in = HRTIME_SECONDS(nh->config.default_inactivity_timeout); - } inactivity_timeout_in = timeout_in; next_inactivity_timeout_at = Thread::get_hrtime() + inactivity_timeout_in; } From 8b680f649a098427f1b43c59aaa0070d13c5f8bc Mon Sep 17 00:00:00 2001 From: Sudheer Vinukonda Date: Mon, 11 May 2020 16:07:03 -0700 Subject: [PATCH 2/4] Add docs for the new stats --- .../monitoring/statistics/core/network-io.en.rst | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/doc/admin-guide/monitoring/statistics/core/network-io.en.rst b/doc/admin-guide/monitoring/statistics/core/network-io.en.rst index bb25d4b2253..d76442ececa 100644 --- a/doc/admin-guide/monitoring/statistics/core/network-io.en.rst +++ b/doc/admin-guide/monitoring/statistics/core/network-io.en.rst @@ -61,7 +61,13 @@ Network I/O :type: counter .. ts:stat:: global proxy.process.net.default_inactivity_timeout_applied integer + The total number of connections that had no transaction or connection level timer running on them and + had to fallback to the catch-all 'default_inactivity_timeout' + :type: counter .. ts:stat:: global proxy.process.net.default_inactivity_timeout_count integer + The total number of connections that were cleaned up due to 'default_inactivity_timeout' + :type: counter + .. ts:stat:: global proxy.process.net.dynamic_keep_alive_timeout_in_count integer .. ts:stat:: global proxy.process.net.dynamic_keep_alive_timeout_in_total integer .. ts:stat:: global proxy.process.net.inactivity_cop_lock_acquire_failure integer From 0c64856e7c204f27ac961631df2473954e8a9e69 Mon Sep 17 00:00:00 2001 From: Sudheer Vinukonda Date: Tue, 12 May 2020 11:07:04 -0700 Subject: [PATCH 3/4] Make default inactivity timeout detection more accurate (thanks Bryan) --- iocore/net/I_NetVConnection.h | 4 +++- iocore/net/NetEvent.h | 4 +++- iocore/net/P_UnixNetVConnection.h | 2 ++ iocore/net/UnixNet.cc | 5 ++--- iocore/net/UnixNetVConnection.cc | 15 +++++++++++++++ proxy/PluginVC.cc | 12 ++++++++++++ proxy/PluginVC.h | 2 ++ 7 files changed, 39 insertions(+), 5 deletions(-) diff --git a/iocore/net/I_NetVConnection.h b/iocore/net/I_NetVConnection.h index 7081af0bff6..1b35a1dbdf4 100644 --- a/iocore/net/I_NetVConnection.h +++ b/iocore/net/I_NetVConnection.h @@ -539,7 +539,9 @@ class NetVConnection : public VConnection, public PluginUserArgsnext_inactivity_timeout_at == 0 && nh.config.default_inactivity_timeout > 0) { Debug("inactivity_cop", "vc: %p inactivity timeout not set, setting a default of %d", ne, nh.config.default_inactivity_timeout); - ne->set_inactivity_timeout(HRTIME_SECONDS(nh.config.default_inactivity_timeout)); - ne->default_inactivity_timeout = true; + ne->set_default_inactivity_timeout(HRTIME_SECONDS(nh.config.default_inactivity_timeout)); NET_INCREMENT_DYN_STAT(default_inactivity_timeout_applied_stat); } if (ne->next_inactivity_timeout_at && ne->next_inactivity_timeout_at < now) { - if (ne->default_inactivity_timeout) { + if (ne->is_default_inactivity_timeout()) { // track the connections that timed out due to default inactivity NET_INCREMENT_DYN_STAT(default_inactivity_timeout_count_stat); } diff --git a/iocore/net/UnixNetVConnection.cc b/iocore/net/UnixNetVConnection.cc index f85eb0f84d5..0f29f60ef78 100644 --- a/iocore/net/UnixNetVConnection.cc +++ b/iocore/net/UnixNetVConnection.cc @@ -1356,6 +1356,21 @@ UnixNetVConnection::set_inactivity_timeout(ink_hrtime timeout_in) next_inactivity_timeout_at = Thread::get_hrtime() + inactivity_timeout_in; } +TS_INLINE void +UnixNetVConnection::set_default_inactivity_timeout(ink_hrtime timeout_in) +{ + Debug("socket", "Set default inactive timeout=%" PRId64 ", for NetVC=%p", timeout_in, this); + inactivity_timeout_in = 0; + default_inactivity_timeout = true; + next_inactivity_timeout_at = Thread::get_hrtime() + inactivity_timeout_in; +} + +TS_INLINE bool +UnixNetVConnection::is_default_inactivity_timeout() +{ + return (default_inactivity_timeout && inactivity_timeout_in == 0); +} + /* * Close down the current netVC. Save aside the socket and SSL information * and create new netVC in the current thread/netVC diff --git a/proxy/PluginVC.cc b/proxy/PluginVC.cc index f6cc4270592..97ee74f9b8f 100644 --- a/proxy/PluginVC.cc +++ b/proxy/PluginVC.cc @@ -886,6 +886,18 @@ PluginVC::set_inactivity_timeout(ink_hrtime timeout_in) } } +void +PluginVC::set_default_inactivity_timeout(ink_hrtime timeout_in) +{ + set_inactivity_timeout(timeout_in); +} + +bool +PluginVC::is_default_inactivity_timeout() +{ + return false; +} + void PluginVC::cancel_active_timeout() { diff --git a/proxy/PluginVC.h b/proxy/PluginVC.h index ce420fd5861..cb0460de0b2 100644 --- a/proxy/PluginVC.h +++ b/proxy/PluginVC.h @@ -89,6 +89,8 @@ class PluginVC : public NetVConnection, public PluginIdentity // Timeouts void set_active_timeout(ink_hrtime timeout_in) override; void set_inactivity_timeout(ink_hrtime timeout_in) override; + void set_default_inactivity_timeout(ink_hrtime timeout_in) override; + bool is_default_inactivity_timeout() override; void cancel_active_timeout() override; void cancel_inactivity_timeout() override; void add_to_keep_alive_queue() override; From 2930a13a927386b050d4233e5b04db940a68db49 Mon Sep 17 00:00:00 2001 From: Sudheer Vinukonda Date: Tue, 12 May 2020 11:22:50 -0700 Subject: [PATCH 4/4] Fix bug in setting the timeout_at --- iocore/net/UnixNetVConnection.cc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/iocore/net/UnixNetVConnection.cc b/iocore/net/UnixNetVConnection.cc index 0f29f60ef78..ca47deb4bfc 100644 --- a/iocore/net/UnixNetVConnection.cc +++ b/iocore/net/UnixNetVConnection.cc @@ -1362,7 +1362,7 @@ UnixNetVConnection::set_default_inactivity_timeout(ink_hrtime timeout_in) Debug("socket", "Set default inactive timeout=%" PRId64 ", for NetVC=%p", timeout_in, this); inactivity_timeout_in = 0; default_inactivity_timeout = true; - next_inactivity_timeout_at = Thread::get_hrtime() + inactivity_timeout_in; + next_inactivity_timeout_at = Thread::get_hrtime() + timeout_in; } TS_INLINE bool