Add new metrics (#578)

Co-authored-by: Krish <>

Author: azkrishpy

.gitignore

@@ -71,3 +71,4 @@ benchmarks/dashboard-stack/package-lock.json
 
 # virtual environment
 .venv/
+.cache/

include/aws/s3/private/s3_request.h

@@ -31,6 +31,23 @@ struct aws_s3_request_metrics {
     struct aws_allocator *allocator;
 
     struct {
+        /* The time stamp when the request was first initiated by the client, including the very first attempt.
+         * This timestamp is set once at the beginning and never updated during retries. Timestamps are from
+         * `aws_high_res_clock_get_ticks`. This will always be available. */
+        int64_t s3_request_first_attempt_start_timestamp_ns;
+
+        /* The time stamp when the request completely finished (success or final failure), including all retry
+         * attempts. This is set when the request reaches its final state - either successful completion or
+         * exhaustion of all retry attempts. Timestamps are from `aws_high_res_clock_get_ticks`. This will
+         * be available with the last attempt. */
+        int64_t s3_request_last_attempt_end_timestamp_ns;
+
+        /* The total time duration for the complete request lifecycle from initial start to final completion,
+         * including all retry attempts, backoff delays, and connection establishment time
+         * (s3_request_last_attempt_end_timestamp_ns - s3_request_first_attempt_start_timestamp_ns). This represents the
+         * end-to-end user experience time. This will be available with the last attempt. */
+        int64_t s3_request_total_duration_ns;
+
         /* The time stamp when the request started by S3 client, which is prepared time by the client. Timestamps
          * are from `aws_high_res_clock_get_ticks`. This will always be available. */
         int64_t start_timestamp_ns;
@@ -90,6 +107,31 @@ struct aws_s3_request_metrics {
         /* The time duration for the request from start of delivery to finish of delivery (deliver_end_timestamp_ns -
          * deliver_start_timestamp_ns). When deliver_duration_ns is 0, means data not available. */
         int64_t deliver_duration_ns;
+
+        /* The time stamp when the request started to acquire connection. -1 means data not available. Timestamp
+         * are from `aws_high_res_clock_get_ticks` */
+        int64_t conn_acquire_start_timestamp_ns;
+        /* The time stamp when the request finished to acquire connection. -1 means data not available.
+         * Timestamp are from `aws_high_res_clock_get_ticks` */
+        int64_t conn_acquire_end_timestamp_ns;
+        /* The time duration for the request from start acquiring connection to finish acquiring connection
+         * (conn_acquire_end_timestamp_ns - conn_acquire_start_timestamp_ns). When conn_acquire_end_timestamp_ns is -1,
+         * means data not available. */
+        int64_t conn_acquire_duration_ns;
+
+        /* The time stamp when the request started to delay for retry. -1 means data not available. Timestamp
+         * are from `aws_high_res_clock_get_ticks` */
+        int64_t retry_delay_start_timestamp_ns;
+        /* The time stamp when the request finished to delay for retry. -1 means data not available.
+         * Timestamp are from `aws_high_res_clock_get_ticks` */
+        int64_t retry_delay_end_timestamp_ns;
+        /* The time duration for the request from start retry delay to finish retry delay (retry_delay_end_timestamp_ns
+         * - retry_delay_start_timestamp_ns). When retry_delay_end_timestamp_ns is -1, means data not available. */
+        int64_t retry_delay_duration_ns;
+
+        /* The time duration for the service call from connection acquisition to first response byte. -1 means data not
+         * available. */
+        int64_t service_call_duration_ns;
     } time_metrics;
 
     struct {
@@ -103,6 +145,8 @@ struct aws_s3_request_metrics {
         struct aws_string *host_address;
         /* The the request ID header value. */
         struct aws_string *request_id;
+        /* The the extended request ID header value. */
+        struct aws_string *extended_request_id;
         /* S3 operation name for the request */
         struct aws_string *operation_name;
         /* The type of request made */
@@ -113,7 +157,9 @@ struct aws_s3_request_metrics {
         /* The IP address of the request connected to */
         struct aws_string *ip_address;
         /* The pointer to the connection that request was made from */
-        void *connection_id;
+        void *connection_ptr;
+        /* The pointer to the request that the request attempt was made from */
+        void *request_ptr;
         /* The aws_thread_id_t to the thread that request ran on */
         aws_thread_id_t thread_id;
         /* The stream-id, which is the idex when the stream was activated. */
@@ -133,6 +179,13 @@ struct aws_s3_request {
     /* Linked list node used for queuing. */
     struct aws_linked_list_node node;
 
+    /* Timestamp when retry attempt started. Overwritten on each retry and copied to new attempt's setup data.
+     * -1 means data not available. Timestamp from `aws_high_res_clock_get_ticks` */
+    int64_t retry_start_timestamp_ns;
+    /* Timestamp when retry attempt ended. Overwritten on each retry and copied to new attempt's setup data.
+     * -1 means data not available. Timestamp from `aws_high_res_clock_get_ticks` */
+    int64_t retry_end_timestamp_ns;
+
     /* Linked list node used for tracking the request is active from HTTP level. */
     struct aws_linked_list_node cancellable_http_streams_list_node;
 
@@ -250,7 +303,7 @@ struct aws_s3_request {
 
         /* Returned request ID of this request. */
         struct aws_string *request_id;
-        /* Returned amz ID 2 of this request. */
+        /* Returned extended request id of this request. */
         struct aws_string *amz_id_2;
 
         /* The metrics for the request telemetry */

include/aws/s3/s3_client.h

@@ -1390,6 +1390,17 @@ int aws_s3_request_metrics_get_request_id(
     const struct aws_s3_request_metrics *metrics,
     const struct aws_string **out_request_id);
 
+/**
+ * Get the extended request ID from aws_s3_request_metrics.
+ * If unavailable, AWS_ERROR_S3_METRIC_DATA_NOT_AVAILABLE will be raised.
+ * If available, out_extended_request_id will be set to a string. Be warned this string's lifetime is tied to the
+ * metrics object.
+ **/
+AWS_S3_API
+int aws_s3_request_metrics_get_extended_request_id(
+    const struct aws_s3_request_metrics *metrics,
+    const struct aws_string **out_extended_request_id);
+
 /* Get the start time from aws_s3_request_metrics, which is when S3 client prepare the request to be sent. Always
  * available. Timestamp are from `aws_high_res_clock_get_ticks`  */
 AWS_S3_API
@@ -1563,10 +1574,14 @@ int aws_s3_request_metrics_get_ip_address(
     const struct aws_s3_request_metrics *metrics,
     const struct aws_string **out_ip_address);
 
-/* Get the id of connection that request was made from. AWS_ERROR_S3_METRIC_DATA_NOT_AVAILABLE will be raised if data
- * not available */
+/* Get the ptr address of connection that request was made from. AWS_ERROR_S3_METRIC_DATA_NOT_AVAILABLE will be raised
+ * if data not available */
 AWS_S3_API
-int aws_s3_request_metrics_get_connection_id(const struct aws_s3_request_metrics *metrics, size_t *out_connection_id);
+int aws_s3_request_metrics_get_connection_id(const struct aws_s3_request_metrics *metrics, size_t *out_connection_ptr);
+
+/* Get the pointer to the request that attempt was made from. Always available. */
+AWS_S3_API
+int aws_s3_request_metrics_get_request_ptr(const struct aws_s3_request_metrics *metrics, size_t *out_request_ptr);
 
 /* Get the thread ID of the thread that request was made from. AWS_ERROR_S3_METRIC_DATA_NOT_AVAILABLE will be raised if
  * data not available */
@@ -1604,6 +1619,70 @@ int aws_s3_request_metrics_get_error_code(const struct aws_s3_request_metrics *m
 AWS_S3_API
 uint32_t aws_s3_request_metrics_get_retry_attempt(const struct aws_s3_request_metrics *metrics);
 
+/* Get the request start timestamp from aws_s3_request_metrics. Always available. */
+AWS_S3_API
+void aws_s3_request_metrics_get_s3_request_first_attempt_start_timestamp_ns(
+    const struct aws_s3_request_metrics *metrics,
+    uint64_t *out_s3_request_first_attempt_start_time);
+
+/* Get the request end timestamp. AWS_ERROR_S3_METRIC_DATA_NOT_AVAILABLE will be raised if data not
+ * available. */
+AWS_S3_API
+int aws_s3_request_metrics_get_s3_request_last_attempt_end_timestamp_ns(
+    const struct aws_s3_request_metrics *metrics,
+    uint64_t *out_s3_request_last_attempt_end_time);
+
+/* Get the request duration. AWS_ERROR_S3_METRIC_DATA_NOT_AVAILABLE will be raised if data not
+ * available. */
+AWS_S3_API
+int aws_s3_request_metrics_get_s3_request_total_duration_ns(
+    const struct aws_s3_request_metrics *metrics,
+    uint64_t *out_request_duration);
+
+/* Get the connection acquire start timestamp. AWS_ERROR_S3_METRIC_DATA_NOT_AVAILABLE will be raised if data not
+ * available. */
+AWS_S3_API
+int aws_s3_request_metrics_get_conn_acquire_start_timestamp_ns(
+    const struct aws_s3_request_metrics *metrics,
+    uint64_t *out_conn_acquire_start_time);
+
+/* Get the connection acquire end timestamp. AWS_ERROR_S3_METRIC_DATA_NOT_AVAILABLE will be raised if data not
+ * available. */
+AWS_S3_API
+int aws_s3_request_metrics_get_conn_acquire_end_timestamp_ns(
+    const struct aws_s3_request_metrics *metrics,
+    uint64_t *out_conn_acquire_end_time);
+
+/* Get the connection acquire duration. AWS_ERROR_S3_METRIC_DATA_NOT_AVAILABLE will be raised if data not available. */
+AWS_S3_API
+int aws_s3_request_metrics_get_conn_acquire_duration_ns(
+    const struct aws_s3_request_metrics *metrics,
+    uint64_t *out_conn_acquire_duration);
+
+/* Get the retry delay start timestamp. AWS_ERROR_S3_METRIC_DATA_NOT_AVAILABLE will be raised if data not available. */
+AWS_S3_API
+int aws_s3_request_metrics_get_retry_delay_start_timestamp_ns(
+    const struct aws_s3_request_metrics *metrics,
+    uint64_t *out_retry_delay_start_time);
+
+/* Get the retry delay end timestamp. AWS_ERROR_S3_METRIC_DATA_NOT_AVAILABLE will be raised if data not available. */
+AWS_S3_API
+int aws_s3_request_metrics_get_retry_delay_end_timestamp_ns(
+    const struct aws_s3_request_metrics *metrics,
+    uint64_t *out_retry_delay_end_time);
+
+/* Get the retry delay duration. AWS_ERROR_S3_METRIC_DATA_NOT_AVAILABLE will be raised if data not available. */
+AWS_S3_API
+int aws_s3_request_metrics_get_retry_delay_duration_ns(
+    const struct aws_s3_request_metrics *metrics,
+    uint64_t *out_retry_delay_duration);
+
+/* Get the service call duration. AWS_ERROR_S3_METRIC_DATA_NOT_AVAILABLE will be raised if data not available. */
+AWS_S3_API
+int aws_s3_request_metrics_get_service_call_duration_ns(
+    const struct aws_s3_request_metrics *metrics,
+    uint64_t *out_service_call_duration);
+
 AWS_EXTERN_C_END
 AWS_POP_SANE_WARNING_LEVEL
 

source/s3_client.c

@@ -2166,6 +2166,16 @@ void aws_s3_client_update_connections_threaded(struct aws_s3_client *client) {
         } else if (!request->always_send && aws_s3_meta_request_has_finish_result(request->meta_request)) {
             /* Unless the request is marked "always send", if this meta request has a finish result, then finish the
              * request now and release it. */
+            /* Update the error code for the metrics of the request here since we never acquire/release a connection */
+            request->send_data.metrics->crt_info_metrics.error_code = AWS_ERROR_S3_CANCELED;
+
+            /* Record end times as well */
+            aws_high_res_clock_get_ticks(
+                (uint64_t *)&request->send_data.metrics->time_metrics.s3_request_last_attempt_end_timestamp_ns);
+            request->send_data.metrics->time_metrics.s3_request_total_duration_ns =
+                request->send_data.metrics->time_metrics.s3_request_last_attempt_end_timestamp_ns -
+                request->send_data.metrics->time_metrics.s3_request_first_attempt_start_timestamp_ns;
+
             s_s3_client_meta_request_finished_request(client, request->meta_request, request, AWS_ERROR_S3_CANCELED);
             request = aws_s3_request_release(request);
         } else if (
@@ -2299,6 +2309,8 @@ static void s_s3_client_acquired_retry_token(
     /* TODO: not a blocker, consider managing the life time of aws_s3_client from aws_s3_endpoint to simplify usage */
     aws_s3_client_acquire(client);
 
+    aws_high_res_clock_get_ticks((uint64_t *)&request->send_data.metrics->time_metrics.conn_acquire_start_timestamp_ns);
+
     client->vtable->acquire_http_connection(
         endpoint->http_connection_manager, s_s3_client_on_acquire_http_connection, connection);
 
@@ -2356,6 +2368,11 @@ static void s_s3_client_on_acquire_http_connection(
         goto error_retry;
     }
 
+    aws_high_res_clock_get_ticks((uint64_t *)&request->send_data.metrics->time_metrics.conn_acquire_end_timestamp_ns);
+    request->send_data.metrics->time_metrics.conn_acquire_duration_ns =
+        request->send_data.metrics->time_metrics.conn_acquire_end_timestamp_ns -
+        request->send_data.metrics->time_metrics.conn_acquire_start_timestamp_ns;
+
     connection->http_connection = incoming_http_connection;
     aws_s3_meta_request_send_request(meta_request, connection);
     aws_s3_client_release(client); /* kept since this callback was registered */
@@ -2455,6 +2472,7 @@ void aws_s3_client_notify_connection_finished(
         }
 
         /* Ask the retry strategy to schedule a retry of the request. */
+        aws_high_res_clock_get_ticks((uint64_t *)&request->retry_start_timestamp_ns);
         if (aws_retry_strategy_schedule_retry(
                 connection->retry_token, error_type, s_s3_client_retry_ready, connection)) {
 
@@ -2476,6 +2494,12 @@ void aws_s3_client_notify_connection_finished(
 
 reset_connection:
 
+    aws_high_res_clock_get_ticks(
+        (uint64_t *)&request->send_data.metrics->time_metrics.s3_request_last_attempt_end_timestamp_ns);
+    request->send_data.metrics->time_metrics.s3_request_total_duration_ns =
+        request->send_data.metrics->time_metrics.s3_request_last_attempt_end_timestamp_ns -
+        request->send_data.metrics->time_metrics.s3_request_first_attempt_start_timestamp_ns;
+
     if (connection->retry_token != NULL) {
         /* If we have a retry token and successfully finished, record that success. */
         if (finish_code == AWS_S3_CONNECTION_FINISH_CODE_SUCCESS) {
@@ -2544,6 +2568,8 @@ static void s_s3_client_retry_ready(struct aws_retry_token *token, int error_cod
     struct aws_s3_request *request = connection->request;
     AWS_PRECONDITION(request);
 
+    aws_high_res_clock_get_ticks((uint64_t *)&request->retry_end_timestamp_ns);
+
     struct aws_s3_meta_request *meta_request = request->meta_request;
     AWS_PRECONDITION(meta_request);
 

source/s3_meta_request.c

@@ -1380,6 +1380,10 @@ static int s_s3_meta_request_incoming_headers(
         }
         if (request->send_data.amz_id_2 == NULL && aws_byte_cursor_eq(name, &g_amz_id_2_header_name)) {
             request->send_data.amz_id_2 = aws_string_new_from_cursor(connection->request->allocator, value);
+            if (collect_metrics) {
+                request->send_data.metrics->req_resp_info_metrics.extended_request_id =
+                    aws_string_new_from_cursor(connection->request->allocator, value);
+            }
         }
         if (collect_metrics) {
             aws_http_headers_add(request->send_data.metrics->req_resp_info_metrics.response_headers, *name, *value);
@@ -1518,13 +1522,19 @@ static void s_s3_meta_request_stream_metrics(
     s3_metrics->time_metrics.send_end_timestamp_ns = http_metrics->send_end_timestamp_ns;
     s3_metrics->time_metrics.sending_duration_ns = http_metrics->sending_duration_ns;
     s3_metrics->time_metrics.receive_start_timestamp_ns = http_metrics->receive_start_timestamp_ns;
+
+    if (s3_metrics->time_metrics.receive_start_timestamp_ns != -1) {
+        s3_metrics->time_metrics.service_call_duration_ns = s3_metrics->time_metrics.receive_start_timestamp_ns -
+                                                            s3_metrics->time_metrics.conn_acquire_start_timestamp_ns;
+    }
+
     s3_metrics->time_metrics.receive_end_timestamp_ns = http_metrics->receive_end_timestamp_ns;
     s3_metrics->time_metrics.receiving_duration_ns = http_metrics->receiving_duration_ns;
 
     s3_metrics->crt_info_metrics.stream_id = http_metrics->stream_id;
 
     /* Also related metrics from the request/response. */
-    s3_metrics->crt_info_metrics.connection_id = (void *)connection->http_connection;
+    s3_metrics->crt_info_metrics.connection_ptr = (void *)connection->http_connection;
     const struct aws_socket_endpoint *endpoint = aws_http_connection_get_remote_endpoint(connection->http_connection);
     request->send_data.metrics->crt_info_metrics.ip_address =
         aws_string_new_from_c_str(request->allocator, endpoint->address);
@@ -1902,6 +1912,7 @@ static struct aws_s3_request_metrics *s_s3_request_finish_up_and_release_metrics
             aws_high_res_clock_get_ticks((uint64_t *)&metrics->time_metrics.end_timestamp_ns);
             metrics->time_metrics.total_duration_ns =
                 metrics->time_metrics.end_timestamp_ns - metrics->time_metrics.start_timestamp_ns;
+            aws_high_res_clock_get_ticks((uint64_t *)&metrics->time_metrics.s3_request_last_attempt_end_timestamp_ns);
         }
 
         if (meta_request->telemetry_callback != NULL) {