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 2020/05/05 04:26:54 UTC
[trafficserver] 01/02: Adding logging fields for collapsed
forwarding metrics (#6708)
This is an automated email from the ASF dual-hosted git repository.
zwoop pushed a commit to branch 9.0.x
in repository https://gitbox.apache.org/repos/asf/trafficserver.git
commit 3b4982b650984f8e1fd66c3b039e6cffbbf636f4
Author: Evan Zelkowitz <ez...@apache.org>
AuthorDate: Mon Apr 27 19:54:43 2020 -0700
Adding logging fields for collapsed forwarding metrics (#6708)
* 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. * -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
* Remove creation of cache_sm object since logaccess cannot use its destructor. Using the access functions directly
* 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
* Update documentation for cccs value
(cherry picked from commit 0ec63fc9df3810b68ab80864bf3f559c56c02aac)
---
doc/admin-guide/logging/formatting.en.rst | 10 ++++++
proxy/logging/Log.cc | 15 +++++++++
proxy/logging/LogAccess.cc | 55 +++++++++++++++++++++++++++++++
proxy/logging/LogAccess.h | 3 ++
4 files changed, 83 insertions(+)
diff --git a/doc/admin-guide/logging/formatting.en.rst b/doc/admin-guide/logging/formatting.en.rst
index 8fa5edd..c81f435 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,13 @@ 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;
+ -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:
diff --git a/proxy/logging/Log.cc b/proxy/logging/Log.cc
index 42f8dc3..8be6bd7 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 32b2e19..08f5b0a 100644
--- a/proxy/logging/LogAccess.cc
+++ b/proxy/logging/LogAccess.cc
@@ -2635,6 +2635,61 @@ LogAccess::marshal_client_http_transaction_priority_dependence(char *buf)
-------------------------------------------------------------------------*/
int
+LogAccess::marshal_cache_read_retries(char *buf)
+{
+ if (buf) {
+ int64_t id = 0;
+ if (m_http_sm) {
+ id = m_http_sm->get_cache_sm().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) {
+ id = m_http_sm->get_cache_sm().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; // default - no collapse attempt
+ if (m_http_sm) {
+ SquidLogCode code = m_http_sm->t_state.squid_codes.log_code;
+
+ // 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;
+ }
+ }
+
+ marshal_int(buf, id);
+ }
+ return INK_MIN_ALIGN;
+}
+/*-------------------------------------------------------------------------
+ -------------------------------------------------------------------------*/
+
+int
LogAccess::marshal_http_header_field(LogField::Container container, char *field, char *buf)
{
char *str = nullptr;
diff --git a/proxy/logging/LogAccess.h b/proxy/logging/LogAccess.h
index e9090d3..b29e6f4 100644
--- a/proxy/logging/LogAccess.h
+++ b/proxy/logging/LogAccess.h
@@ -252,6 +252,9 @@ public:
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
//