From 81dd498951a96769bb4865400bc6189ae4ac945e Mon Sep 17 00:00:00 2001 From: Evan Zelkowitz Date: Thu, 23 Apr 2020 20:52:15 +0000 Subject: [PATCH 1/4] Adding logging fields for collapsed forwarding metrics This adds 3 new log fields for transaction output (since collapsed forwarding is transaction based) * crra - The number of read retry attempts for this transaction. If no CF has been done (it has not attempted a write) then this is just the read lock contention. If a write has been attempted then this value gets reset to 0 as it attempts more reads post-write-fail. * cwra - The number of write retry attempts. This will be either the number based on write lock contention, or it can be the max-write-retries+1. If it is max+1 that means that we have hit the max attempts because the lock was being held by another writer and so this transaction fell back to read retries and attempted to be collapsed * cccs - Collapsed connection success. This is just 0/1. 0 if a connection either was not attempted to be collapsed, did not need to be collapsed, or it was attempted but ended up going to the origin anyway. If it is 1 then this transaction hit its max write retries but successfully got a cache HIT during its read retries post-write-failure --- doc/admin-guide/logging/formatting.en.rst | 11 +++++ proxy/logging/Log.cc | 15 +++++++ proxy/logging/LogAccess.cc | 52 +++++++++++++++++++++++ proxy/logging/LogAccess.h | 3 ++ 4 files changed, 81 insertions(+) diff --git a/doc/admin-guide/logging/formatting.en.rst b/doc/admin-guide/logging/formatting.en.rst index 8fa5eddd348..e9081059493 100644 --- a/doc/admin-guide/logging/formatting.en.rst +++ b/doc/admin-guide/logging/formatting.en.rst @@ -151,6 +151,9 @@ Cache Details .. _chm: .. _cwr: .. _cwtr: +.. _crra: +.. _cwra: +.. _cccs: These log fields reveal details of the |TS| proxy interaction with its own cache while attempting to service incoming client requests. @@ -173,6 +176,14 @@ cwr Proxy Cache Cache Write Result. Specifies the result of attempting to (``WL_MISS``), write interrupted (``INTR``), error while writing (``ERR``), or cache write successful (``FIN``). cwt Proxy Cache Cache Write Transform Result. +crra Proxy Cache Cache read retry attempts to read the object from cache. +cwra Proxy Cache Cache write retry attempts to write a fresh or updated + object to cache. +cccs Proxy Cache Cache collapsed connection success; true or false if the + cache lookup failed, a write was attempt but failed due to + being blocked on the write by another request. Will be true + if the subsequent lookup succeeded after the write failure or + false if the request had to go upstream. ===== ============== ========================================================== .. _admin-logging-fields-txn: diff --git a/proxy/logging/Log.cc b/proxy/logging/Log.cc index 42f8dc38276..8be6bd7035c 100644 --- a/proxy/logging/Log.cc +++ b/proxy/logging/Log.cc @@ -892,6 +892,21 @@ Log::init_fields() global_field_list.add(field, false); field_symbol_hash.emplace("ctid", field); + field = new LogField("cache_read_retry_attempts", "crra", LogField::dINT, &LogAccess::marshal_cache_read_retries, + &LogAccess::unmarshal_int_to_str); + global_field_list.add(field, false); + field_symbol_hash.emplace("crra", field); + + field = new LogField("cache_write_retry_attempts", "cwra", LogField::dINT, &LogAccess::marshal_cache_write_retries, + &LogAccess::unmarshal_int_to_str); + global_field_list.add(field, false); + field_symbol_hash.emplace("cwra", field); + + field = new LogField("cache_collapsed_connection_success", "cccs", LogField::dINT, + &LogAccess::marshal_cache_collapsed_connection_success, &LogAccess::unmarshal_int_to_str); + global_field_list.add(field, false); + field_symbol_hash.emplace("cccs", field); + field = new LogField("client_transaction_priority_weight", "ctpw", LogField::sINT, &LogAccess::marshal_client_http_transaction_priority_weight, &LogAccess::unmarshal_int_to_str); global_field_list.add(field, false); diff --git a/proxy/logging/LogAccess.cc b/proxy/logging/LogAccess.cc index 32b2e19cabe..68bf4584f99 100644 --- a/proxy/logging/LogAccess.cc +++ b/proxy/logging/LogAccess.cc @@ -2631,6 +2631,58 @@ LogAccess::marshal_client_http_transaction_priority_dependence(char *buf) return INK_MIN_ALIGN; } +/*------------------------------------------------------------------------- + -------------------------------------------------------------------------*/ + +int +LogAccess::marshal_cache_read_retries(char *buf) +{ + if (buf) { + int64_t id = 0; + if (m_http_sm) { + HttpCacheSM csm = m_http_sm->get_cache_sm(); + id = csm.get_open_read_tries(); + } + marshal_int(buf, id); + } + return INK_MIN_ALIGN; +} + +/*------------------------------------------------------------------------- + -------------------------------------------------------------------------*/ + +int +LogAccess::marshal_cache_write_retries(char *buf) +{ + if (buf) { + int64_t id = 0; + if (m_http_sm) { + HttpCacheSM csm = m_http_sm->get_cache_sm(); + id = csm.get_open_write_tries(); + } + marshal_int(buf, id); + } + return INK_MIN_ALIGN; +} + +int +LogAccess::marshal_cache_collapsed_connection_success(char *buf) +{ + if (buf) { + int64_t id = 0; + if (m_http_sm) { + HttpCacheSM csm = m_http_sm->get_cache_sm(); + SquidLogCode code = m_http_sm->t_state.squid_codes.log_code; + if ((csm.get_open_write_tries() == (m_http_sm->t_state.txn_conf->max_cache_open_write_retries + 1)) && + ((code == SQUID_LOG_TCP_HIT) || (code == SQUID_LOG_TCP_MEM_HIT) || (code == SQUID_LOG_TCP_DISK_HIT))) { + id = 1; + } + } + + marshal_int(buf, id); + } + return INK_MIN_ALIGN; +} /*------------------------------------------------------------------------- -------------------------------------------------------------------------*/ diff --git a/proxy/logging/LogAccess.h b/proxy/logging/LogAccess.h index e9090d3538d..b29e6f4d650 100644 --- a/proxy/logging/LogAccess.h +++ b/proxy/logging/LogAccess.h @@ -252,6 +252,9 @@ class LogAccess inkcoreapi int marshal_cache_lookup_url_canon(char *); // STR inkcoreapi int marshal_client_sni_server_name(char *); // STR inkcoreapi int marshal_version_build_number(char *); // STR + inkcoreapi int marshal_cache_read_retries(char *); // INT + inkcoreapi int marshal_cache_write_retries(char *); // INT + inkcoreapi int marshal_cache_collapsed_connection_success(char *); // INT // named fields from within a http header // From 4fbe914d904a1fa362ec8b28e95e1dc0852967d2 Mon Sep 17 00:00:00 2001 From: Evan Zelkowitz Date: Fri, 24 Apr 2020 20:27:44 +0000 Subject: [PATCH 2/4] Remove creation of cache_sm object since logaccess cannot use its destructor. Using the access functions directly --- proxy/logging/LogAccess.cc | 9 +++------ 1 file changed, 3 insertions(+), 6 deletions(-) diff --git a/proxy/logging/LogAccess.cc b/proxy/logging/LogAccess.cc index 68bf4584f99..73b9a7ef2ac 100644 --- a/proxy/logging/LogAccess.cc +++ b/proxy/logging/LogAccess.cc @@ -2640,8 +2640,7 @@ LogAccess::marshal_cache_read_retries(char *buf) if (buf) { int64_t id = 0; if (m_http_sm) { - HttpCacheSM csm = m_http_sm->get_cache_sm(); - id = csm.get_open_read_tries(); + id = m_http_sm->get_cache_sm().get_open_read_tries(); } marshal_int(buf, id); } @@ -2657,8 +2656,7 @@ LogAccess::marshal_cache_write_retries(char *buf) if (buf) { int64_t id = 0; if (m_http_sm) { - HttpCacheSM csm = m_http_sm->get_cache_sm(); - id = csm.get_open_write_tries(); + id = m_http_sm->get_cache_sm().get_open_write_tries(); } marshal_int(buf, id); } @@ -2671,9 +2669,8 @@ LogAccess::marshal_cache_collapsed_connection_success(char *buf) if (buf) { int64_t id = 0; if (m_http_sm) { - HttpCacheSM csm = m_http_sm->get_cache_sm(); SquidLogCode code = m_http_sm->t_state.squid_codes.log_code; - if ((csm.get_open_write_tries() == (m_http_sm->t_state.txn_conf->max_cache_open_write_retries + 1)) && + if ((m_http_sm->get_cache_sm().get_open_write_tries() == (m_http_sm->t_state.txn_conf->max_cache_open_write_retries + 1)) && ((code == SQUID_LOG_TCP_HIT) || (code == SQUID_LOG_TCP_MEM_HIT) || (code == SQUID_LOG_TCP_DISK_HIT))) { id = 1; } From ad3cb994b4da1584f34ac44591a79b946ae48ccc Mon Sep 17 00:00:00 2001 From: Evan Zelkowitz Date: Mon, 27 Apr 2020 18:17:38 +0000 Subject: [PATCH 3/4] Changed log values: * -1: Attempted CF but failed and went to origin * 0: Did not need to collapse, either already had to go to origin or was a hit * 1: Attempted CF and got a hit on retry read attempts --- proxy/logging/LogAccess.cc | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/proxy/logging/LogAccess.cc b/proxy/logging/LogAccess.cc index 73b9a7ef2ac..08f5b0a79ce 100644 --- a/proxy/logging/LogAccess.cc +++ b/proxy/logging/LogAccess.cc @@ -2667,12 +2667,18 @@ int LogAccess::marshal_cache_collapsed_connection_success(char *buf) { if (buf) { - int64_t id = 0; + int64_t id = 0; // default - no collapse attempt if (m_http_sm) { SquidLogCode code = m_http_sm->t_state.squid_codes.log_code; - if ((m_http_sm->get_cache_sm().get_open_write_tries() == (m_http_sm->t_state.txn_conf->max_cache_open_write_retries + 1)) && + + // We increment open_write_tries beyond the max when we want to jump back to the read state for collapsing + if ((m_http_sm->get_cache_sm().get_open_write_tries() > (m_http_sm->t_state.txn_conf->max_cache_open_write_retries)) && ((code == SQUID_LOG_TCP_HIT) || (code == SQUID_LOG_TCP_MEM_HIT) || (code == SQUID_LOG_TCP_DISK_HIT))) { + // Attempted collapsed connection and got a hit, success id = 1; + } else if (m_http_sm->get_cache_sm().get_open_write_tries() > (m_http_sm->t_state.txn_conf->max_cache_open_write_retries)) { + // Attempted collapsed connection with no hit, failure, we can also get +2 retries in a failure state + id = -1; } } From dbfbcfab83cb8f142e44e0d1703c8b6291acf68a Mon Sep 17 00:00:00 2001 From: Evan Zelkowitz Date: Mon, 27 Apr 2020 18:23:39 +0000 Subject: [PATCH 4/4] Update documentation for cccs value --- doc/admin-guide/logging/formatting.en.rst | 9 ++++----- 1 file changed, 4 insertions(+), 5 deletions(-) diff --git a/doc/admin-guide/logging/formatting.en.rst b/doc/admin-guide/logging/formatting.en.rst index e9081059493..c81f4351629 100644 --- a/doc/admin-guide/logging/formatting.en.rst +++ b/doc/admin-guide/logging/formatting.en.rst @@ -179,11 +179,10 @@ cwt Proxy Cache Cache Write Transform Result. crra Proxy Cache Cache read retry attempts to read the object from cache. cwra Proxy Cache Cache write retry attempts to write a fresh or updated object to cache. -cccs Proxy Cache Cache collapsed connection success; true or false if the - cache lookup failed, a write was attempt but failed due to - being blocked on the write by another request. Will be true - if the subsequent lookup succeeded after the write failure or - false if the request had to go upstream. +cccs Proxy Cache Cache collapsed connection success; + -1: collapsing was attempted but failed, request went upstream + 0: collapsing was unnecessary + 1: attempted to collapse and got a cache hit on subsequent read attempts ===== ============== ========================================================== .. _admin-logging-fields-txn: