Please help review and approve one change
Xiaohua Wang
xiaohuaw at gmail.com
Wed Dec 20 07:15:24 UTC 2017
Added to trace HTTP request call flow in nginx.
Especially for performance or load test purpose.
Because info level log is not enough,
and debug log is too much which impacts performance a lot.
Currently, two scenarios are supported.
1) trace any point in source code like before/after function entry, or
middle of function.
2) trace any call flow which takes longer time than specific latency
between two check point.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.nginx.org/pipermail/nginx-devel/attachments/20171220/a09658ce/attachment-0001.html>
-------------- next part --------------
# HG changeset patch
# User Xiaohua Wang <xiaohuaw at gmail.com>
# Date 1513591776 -28800
# Mon Dec 18 18:09:36 2017 +0800
# Node ID 1cf1d4a74783573da28793f39b924fa551fdfb65
# Parent d3235149d17f7745d3ac246a6cdcc81a56698f7b
Added to trace http request call flow in nginx.
Especillay for performance or load test purpose.
Because info level log is not enough,
and debug log is too much which impacts performace a lot.
Currently, two scenarios are supported.
1) trace any piont in source code like before/after function entry, or middle of function.
2) trace any call flow which takes longer time than specific latency between two check point.
diff -r d3235149d17f -r 1cf1d4a74783 auto/modules
--- a/auto/modules Thu Dec 07 17:09:36 2017 +0300
+++ b/auto/modules Mon Dec 18 18:09:36 2017 +0800
@@ -74,6 +74,7 @@
src/http/ngx_http_config.h \
src/http/ngx_http_core_module.h \
src/http/ngx_http_cache.h \
+ src/http/ngx_http_call_trace.h \
src/http/ngx_http_variables.h \
src/http/ngx_http_script.h \
src/http/ngx_http_upstream.h \
@@ -101,6 +102,11 @@
HTTP_SRCS="$HTTP_SRCS $HTTP_FILE_CACHE_SRCS"
fi
+ if [ $HTTP_CALL_TRACE = YES ]; then
+ have=NGX_HTTP_CALL_TRACE . auto/have
+ HTTP_SRCS="$HTTP_SRCS $HTTP_CALL_TRACE_SRCS"
+ fi
+
if [ $HTTP_SSI = YES ]; then
HTTP_POSTPONE=YES
diff -r d3235149d17f -r 1cf1d4a74783 auto/options
--- a/auto/options Thu Dec 07 17:09:36 2017 +0300
+++ b/auto/options Mon Dec 18 18:09:36 2017 +0800
@@ -54,6 +54,7 @@
NGX_HTTP_UWSGI_TEMP_PATH=
NGX_HTTP_SCGI_TEMP_PATH=
+HTTP_CALL_TRACE=NO
HTTP_CACHE=YES
HTTP_CHARSET=YES
HTTP_GZIP=YES
@@ -212,6 +213,7 @@
--without-http) HTTP=NO ;;
--without-http-cache) HTTP_CACHE=NO ;;
+ --with-http-call-trace) HTTP_CALL_TRACE=YES ;;
--http-log-path=*) NGX_HTTP_LOG_PATH="$value" ;;
--http-client-body-temp-path=*) NGX_HTTP_CLIENT_TEMP_PATH="$value" ;;
diff -r d3235149d17f -r 1cf1d4a74783 auto/sources
--- a/auto/sources Thu Dec 07 17:09:36 2017 +0300
+++ b/auto/sources Mon Dec 18 18:09:36 2017 +0800
@@ -253,3 +253,6 @@
HTTP_FILE_CACHE_SRCS=src/http/ngx_http_file_cache.c
+
+
+HTTP_CALL_TRACE_SRCS=src/http/ngx_http_call_trace.c
diff -r d3235149d17f -r 1cf1d4a74783 src/http/ngx_http_call_trace.c
--- /dev/null Thu Jan 01 00:00:00 1970 +0000
+++ b/src/http/ngx_http_call_trace.c Mon Dec 18 18:09:36 2017 +0800
@@ -0,0 +1,645 @@
+
+/*
+ * Copyright (C) Xiaohua Wang
+ * Copyright (C) Nginx, Inc.
+ */
+
+
+#include <ngx_config.h>
+#include <ngx_core.h>
+#include <ngx_http.h>
+#include <ngx_http_request.h>
+#include <ngx_http_call_trace.h>
+
+
+#define NGX_HTTP_CALL_TRACE_ENABLE 1
+#define NGX_HTTP_CALL_TRACE_LOG_PRX "ngx-call-trace:"
+#define NGX_HTTP_CALL_TRACE_DEPTH_HEADER_NAME "x-ngx-call-trace-depth"
+#define NGX_HTTP_CALL_TRACE_HEADER_NAME_PREFIX "x-ngx-call-trace-"
+#define NGX_HTTP_CALL_CHECK_COUNT_HEADER_NAME "x-ngx-call-check-count"
+#define NGX_HTTP_CALL_CHECK_HEADER_NAME_PREFIX "x-ngx-call-check-"
+#define NGX_HTTP_CALL_TRACE_MAX_DEPTH 990
+#define NGX_HTTP_CALL_CHECK_MAX_COUNT 990
+
+
+static const char NUMBER[10] = "0123456789";
+
+
+static ngx_table_elt_t *
+search_headers_out(ngx_http_request_t *r, u_char *name, size_t len);
+static char*
+generate_call_trace_header_key(ngx_http_request_t *r, ngx_int_t depth);
+static char*
+generate_call_trace_header_value(ngx_http_request_t *r,
+ const char* trace_point_name);
+static ngx_int_t
+ngx_http_add_call_trace_internal(ngx_http_request_t *r,
+ const char *trace_point_name);
+static ngx_int_t
+ngx_http_print_call_trace_exceeds_latency_internal(ngx_http_request_t *r,
+ ngx_int_t latency);
+static char*
+generate_call_check_header_key(ngx_http_request_t *r, ngx_int_t count);
+static ngx_int_t
+ngx_http_add_call_check_internal(ngx_http_request_t *r,
+ const char *check_point_name);
+static ngx_table_elt_t *
+search_check_point_from_headers_out(ngx_http_request_t *r,
+ const char *check_point_name);
+static ngx_int_t
+ngx_http_print_call_check_latency_internal(ngx_http_request_t *r,
+ const char *check_point_name, ngx_int_t latency);
+
+
+static ngx_table_elt_t *
+search_headers_out(ngx_http_request_t *r, u_char *name, size_t len) {
+ ngx_list_part_t *part;
+ ngx_table_elt_t *h;
+ ngx_uint_t i;
+
+ /*
+ Get the first part of the list. There is usual only one part.
+ */
+ part = &r->headers_out.headers.part;
+ h = part->elts;
+
+ /*
+ Headers list array may consist of more than one part,
+ so loop through all of it
+ */
+ for (i = 0; /* void */ ; i++) {
+ if (i >= part->nelts) {
+ if (part->next == NULL) {
+ break;
+ }
+
+ part = part->next;
+ h = part->elts;
+ i = 0;
+ }
+
+ if (len != h[i].key.len || ngx_strncasecmp(name, h[i].key.data, len) != 0) {
+ continue;
+ }
+ return &h[i];
+ }
+ return NULL;
+}
+
+
+static char*
+generate_call_trace_header_key(ngx_http_request_t *r, ngx_int_t depth){
+ ngx_int_t call_trace_header_key_len;
+ char *call_trace_header_key;
+ ngx_int_t i, tens;
+ i = depth;
+ /*like "x-mfdn-call-trace-001", "x-mfdn-call-trace-900"*/
+ call_trace_header_key_len = ngx_strlen(NGX_HTTP_CALL_TRACE_HEADER_NAME_PREFIX) + 3 + 1;
+ call_trace_header_key = ngx_pcalloc(r->pool, call_trace_header_key_len);
+ strcpy(call_trace_header_key, NGX_HTTP_CALL_TRACE_HEADER_NAME_PREFIX);
+ if (i < 10){
+ call_trace_header_key[call_trace_header_key_len-4] = NUMBER[0];
+ call_trace_header_key[call_trace_header_key_len-3] = NUMBER[0];
+ call_trace_header_key[call_trace_header_key_len-2] = NUMBER[i];
+ call_trace_header_key[call_trace_header_key_len-1] = '\0';
+ }else if (i<100){
+ call_trace_header_key[call_trace_header_key_len-4] = NUMBER[0];
+ call_trace_header_key[call_trace_header_key_len-3] = NUMBER[(i/10)];
+ call_trace_header_key[call_trace_header_key_len-2] = NUMBER[(i%10)];
+ call_trace_header_key[call_trace_header_key_len-1] = '\0';
+ }else if (i<1000){
+ tens = (i - (i/100)*100);
+ call_trace_header_key[call_trace_header_key_len-4] = NUMBER[(i/100)];
+ call_trace_header_key[call_trace_header_key_len-3] = NUMBER[(tens/10)];
+ call_trace_header_key[call_trace_header_key_len-2] = NUMBER[(tens%10)];
+ call_trace_header_key[call_trace_header_key_len-1] = '\0';
+ }else{
+ call_trace_header_key[call_trace_header_key_len-4] = NUMBER[9];
+ call_trace_header_key[call_trace_header_key_len-3] = NUMBER[9];
+ call_trace_header_key[call_trace_header_key_len-2] = NUMBER[9];
+ call_trace_header_key[call_trace_header_key_len-1] = '\0';
+ }
+ return call_trace_header_key;
+}
+
+
+static char*
+generate_call_trace_header_value(ngx_http_request_t *r, const char* trace_point_name){
+ ngx_int_t call_trace_header_value_len;
+ char *call_trace_header_value;
+ time_t now;
+ now = ngx_time();
+ char now_str[NGX_INT64_LEN + 1] = {'\0'};
+ // ngx_log_error(NGX_LOG_WARN, r->connection->log, 0, "%s request_pointer: '%p', '%T' ",
+ // NGX_HTTP_CALL_TRACE_LOG_PRX, r, now);
+ sprintf(now_str, "%ld", now);
+ /*"timestamp-trace_point_name", like "1511324061-start ngx_http_nproxy_upstream_init"*/
+ call_trace_header_value_len = ngx_strlen(now_str) + 1 + ngx_strlen(trace_point_name) + 1;
+ call_trace_header_value = ngx_pcalloc(r->pool, call_trace_header_value_len);
+ strcpy(call_trace_header_value, now_str);
+ call_trace_header_value[ngx_strlen(now_str)] = '-';
+ strcpy(&(call_trace_header_value[ngx_strlen(now_str)+1]), trace_point_name);
+ call_trace_header_value[call_trace_header_value_len -1 ] = '\0';
+ return call_trace_header_value;
+}
+
+
+static ngx_int_t
+ngx_http_add_call_trace_internal(ngx_http_request_t *r, const char *trace_point_name){
+ ngx_table_elt_t *h;
+ ngx_int_t depth;
+ u_char *call_trace_header_key;
+ u_char *call_trace_header_value;
+ u_char *depth_value;
+ ngx_int_t tens;
+ if (r == NULL || trace_point_name == NULL){
+ return NGX_ERROR;
+ }
+ if (r->pool == NULL){
+ // ngx_log_error(NGX_LOG_WARN, r->connection->log, 0,
+ // "%s request_pointer: '%p' can't add call trace point %s due to request pool is NULL.",
+ // NGX_HTTP_CALL_TRACE_LOG_PRX, r, trace_point_name);
+ return NGX_ERROR;
+ }
+ h = search_headers_out(r, (u_char *)NGX_HTTP_CALL_TRACE_DEPTH_HEADER_NAME,
+ ngx_strlen(NGX_HTTP_CALL_TRACE_DEPTH_HEADER_NAME));
+
+ if (h == NULL){
+ /*
+ Need to add call trace depth header here
+ */
+ h = ngx_list_push(&r->headers_out.headers);
+ if (h == NULL) {
+ return NGX_ERROR;
+ }
+ ngx_str_set(&h->key, NGX_HTTP_CALL_TRACE_DEPTH_HEADER_NAME);
+ ngx_str_set(&h->value, "1");
+ h->hash = 0;//0, for internel usage, not send out, and 1 will send it out to client
+
+ depth = 1;
+ }else{
+ depth = ngx_atoi(h->value.data, h->value.len);
+ depth ++;
+ }
+
+ if (depth > NGX_HTTP_CALL_TRACE_MAX_DEPTH){
+ // ngx_log_error(NGX_LOG_WARN, r->connection->log, 0, "%s request_pointer: '%p' can't add call trace point %s, due to call trace depth %d exceeds %d.",
+ // NGX_HTTP_CALL_TRACE_LOG_PRX, r, trace_point_name, depth, NGX_HTTP_CALL_TRACE_MAX_DEPTH);
+ return NGX_ERROR;
+ }
+
+ if (depth < 10){
+ depth_value = ngx_pcalloc(r->pool, 2);
+ depth_value[0] = NUMBER[depth];
+ depth_value[1] = '\0';
+ h->value.data = depth_value;
+ h->value.len = 1;
+ }else if( depth < 100){
+ depth_value = ngx_pcalloc(r->pool, 3);
+ depth_value[0] = NUMBER[(depth/10)];
+ depth_value[1] = NUMBER[(depth%10)];
+ depth_value[2] = '\0';
+ h->value.data = depth_value;
+ h->value.len = 2;
+ }else if(depth < 1000){
+ depth_value = ngx_pcalloc(r->pool, 4);
+ depth_value[0] = NUMBER[(depth/100)];
+ tens = (depth - (depth/100)*100);
+ depth_value[1] = NUMBER[tens/10];
+ depth_value[2] = NUMBER[tens%10];
+ depth_value[3] = '\0';
+ h->value.data = depth_value;
+ h->value.len = 3;
+ }else{
+ ngx_log_error(NGX_LOG_WARN, r->connection->log, 0, "%s request_pointer: '%p'"
+ " can't add call trace point %s due to call trace depth %d"
+ " can't support more than 1000.",
+ NGX_HTTP_CALL_TRACE_LOG_PRX, r, trace_point_name, depth);
+ return NGX_ERROR;
+ }
+
+ h = ngx_list_push(&r->headers_out.headers);
+ if (h == NULL) {
+ return NGX_ERROR;
+ }
+
+ call_trace_header_key = (u_char *)generate_call_trace_header_key(r, depth);
+ call_trace_header_value = (u_char *)generate_call_trace_header_value(r, trace_point_name);
+
+ h->key.data = call_trace_header_key;
+ h->key.len = ngx_strlen(call_trace_header_key);
+ h->value.data = call_trace_header_value;
+ h->value.len = ngx_strlen(call_trace_header_value);
+ h->hash = 0;//0, for internel usage, not send out, and 1 will send it out to client
+
+ return NGX_OK;
+}
+
+
+ngx_int_t
+ngx_http_add_call_trace(ngx_http_request_t *r, const char *trace_point_name){
+#if (NGX_HTTP_CALL_TRACE_ENABLE)
+ return ngx_http_add_call_trace_internal(r, trace_point_name);
+#else
+ ngx_http_add_call_trace_internal(NULL,NULL);
+ return NGX_OK;
+#endif
+}
+
+
+static void
+ngx_http_print_call_trace_with_level(ngx_http_request_t *r, ngx_uint_t level){
+ ngx_table_elt_t *h;
+ ngx_int_t depth;
+ u_char *call_trace_header;
+ ngx_int_t i;
+ if (r == NULL){
+ return;
+ }
+ if (r->pool == NULL){
+ return;
+ }
+ h = search_headers_out(r, (u_char *)NGX_HTTP_CALL_TRACE_DEPTH_HEADER_NAME,
+ ngx_strlen(NGX_HTTP_CALL_TRACE_DEPTH_HEADER_NAME));
+ if (h == NULL){
+ return;
+ }
+ depth = ngx_atoi(h->value.data,h->value.len);
+ ngx_log_error(level, r->connection->log, 0, "%s request_pointer: '%p', depth: '%d' ",
+ NGX_HTTP_CALL_TRACE_LOG_PRX, r, depth);
+
+ for (i=1; i< depth+1; i++ ){
+ call_trace_header = (u_char *)generate_call_trace_header_key(r, i);
+
+ // ngx_log_error(NGX_LOG_DEBUG, r->connection->log, 0, "%s request_pointer: '%p', try to print call trace header '%s' ",
+ // NGX_HTTP_CALL_TRACE_LOG_PRX, r, call_trace_header);
+
+ h = search_headers_out(r, call_trace_header, ngx_strlen(call_trace_header));
+ if (h == NULL){
+ ngx_log_error(level, r->connection->log, 0, "%s request_pointer: '%p',"
+ " can't find call trace header '%s' ",
+ NGX_HTTP_CALL_TRACE_LOG_PRX, r, call_trace_header);
+ continue;
+ }
+ ngx_log_error(level, ngx_cycle->log, 0, "%s request_pointer: '%p', '%s' : '%s'",
+ NGX_HTTP_CALL_TRACE_LOG_PRX, r, h->key.data, h->value.data);
+ }
+}
+
+
+void
+ngx_http_print_call_trace_warn_level(ngx_http_request_t *r){
+#if (NGX_HTTP_CALL_TRACE_ENABLE)
+ ngx_http_print_call_trace_with_level(r, NGX_LOG_WARN);
+#else
+ ngx_http_print_call_trace_with_level(NULL,NGX_LOG_WARN);
+#endif
+}
+
+
+void
+ngx_http_print_call_trace_debug_level(ngx_http_request_t *r){
+#if (NGX_HTTP_CALL_TRACE_ENABLE)
+ ngx_http_print_call_trace_with_level(r, NGX_LOG_DEBUG);
+#else
+ ngx_http_print_call_trace_with_level(NULL,NGX_LOG_DEBUG);
+#endif
+}
+
+
+/* latency in second*/
+static ngx_int_t
+ngx_http_print_call_trace_exceeds_latency_internal(ngx_http_request_t *r, ngx_int_t latency){
+ ngx_table_elt_t *h;
+ ngx_int_t depth;
+ u_char *call_trace_header;
+ u_char *s2;
+ ngx_int_t i;
+ time_t first_trace_time, last_trace_time;
+ if (r == NULL){
+ return NGX_ERROR;
+ }
+ h = search_headers_out(r, (u_char *)NGX_HTTP_CALL_TRACE_DEPTH_HEADER_NAME
+ , ngx_strlen(NGX_HTTP_CALL_TRACE_DEPTH_HEADER_NAME));
+ if (h == NULL){
+ return NGX_ERROR;
+ }
+ depth = ngx_atoi(h->value.data, h->value.len);
+ if (depth <=1 ){
+ return NGX_ERROR;
+ }
+ depth = ngx_atoi(h->value.data,h->value.len);
+ // ngx_log_error(NGX_LOG_WARN, r->connection->log, 0, "%s request_pointer: '%p', '%d' ",
+ // NGX_HTTP_CALL_TRACE_LOG_PRX, r, depth);
+ call_trace_header = (u_char *)generate_call_trace_header_key(r, 1);
+ h = search_headers_out(r, call_trace_header, ngx_strlen((const char*)call_trace_header));
+ if (h == NULL){
+ ngx_log_error(NGX_LOG_WARN, r->connection->log, 0, "%s request_pointer: '%p',"
+ " can't find first call trace header '%s' ",
+ NGX_HTTP_CALL_TRACE_LOG_PRX, r, call_trace_header);
+ return NGX_ERROR;
+ }
+ s2 = ngx_strnstr(h->value.data, "-", NGX_INT64_LEN);
+ first_trace_time = ngx_atotm(h->value.data, s2-h->value.data);
+
+ call_trace_header = (u_char *)generate_call_trace_header_key(r, depth);
+ h = search_headers_out(r, call_trace_header, ngx_strlen(call_trace_header));
+ if (h == NULL){
+ ngx_log_error(NGX_LOG_WARN, r->connection->log, 0, "%s request_pointer: '%p',"
+ " can't find last call trace header '%s' ",
+ NGX_HTTP_CALL_TRACE_LOG_PRX, r, call_trace_header);
+ return NGX_ERROR;
+ }
+ s2 = ngx_strnstr(h->value.data, "-", NGX_INT64_LEN);
+ last_trace_time = ngx_atotm(h->value.data, s2-h->value.data);
+
+ if ((last_trace_time - first_trace_time) < latency
+ && (depth < NGX_HTTP_CALL_TRACE_MAX_DEPTH)){
+ return NGX_ERROR;
+ }
+ // ngx_log_error(NGX_LOG_WARN, r->connection->log, 0, "%s request_pointer: '%p', first_trace_time '%T' last_trace_time '%T' ",
+ // NGX_HTTP_CALL_TRACE_LOG_PRX, r, last_trace_time, first_trace_time);
+
+ ngx_log_error(NGX_LOG_WARN, r->connection->log, 0, "%s request_pointer: '%p',"
+ " call trace latency '%d' exceeds '%d' ",
+ NGX_HTTP_CALL_TRACE_LOG_PRX, r, last_trace_time - first_trace_time, latency);
+ for (i=1; i< depth+1; i++ ){
+ call_trace_header = (u_char *)generate_call_trace_header_key(r, i);
+
+ // ngx_log_error(NGX_LOG_DEBUG, r->connection->log, 0, "%s request_pointer: '%p', try to print call trace header '%s' ",
+ // NGX_HTTP_CALL_TRACE_LOG_PRX, r, call_trace_header);
+
+ h = search_headers_out(r, call_trace_header, ngx_strlen(call_trace_header));
+ if (h == NULL){
+ ngx_log_error(NGX_LOG_WARN, r->connection->log, 0, "%s request_pointer: '%p',"
+ " can't find call trace header '%s' ",
+ NGX_HTTP_CALL_TRACE_LOG_PRX, r, call_trace_header);
+ continue;
+ }
+ // ngx_log_error(NGX_LOG_WARN, ngx_cycle->log, 0, "%s request_pointer: '%p', '%s' : '%s'",
+ // NGX_HTTP_CALL_TRACE_LOG_PRX, r, h->key.data, h->value.data);
+ // ngx_cycle->log print out in master
+ ngx_log_error(NGX_LOG_WARN, r->connection->log, 0, "%s request_pointer: '%p',"
+ " '%s' : '%s'",
+ NGX_HTTP_CALL_TRACE_LOG_PRX, r, h->key.data, h->value.data);
+ }
+ return (last_trace_time - first_trace_time);
+}
+
+
+/* latency in second*/
+ngx_int_t
+ngx_http_print_call_trace_exceeds_latency(ngx_http_request_t *r, ngx_int_t latency){
+ ngx_int_t rv;
+ rv = NGX_OK;
+#if (NGX_HTTP_CALL_TRACE_ENABLE)
+ rv = ngx_http_print_call_trace_exceeds_latency_internal(r, latency);
+#else
+ ngx_http_print_call_trace_exceeds_latency_internal(NULL,0);
+ rv = NGX_OK;
+#endif
+ return rv;
+}
+
+
+static char*
+generate_call_check_header_key(ngx_http_request_t *r, ngx_int_t count){
+ ngx_int_t call_check_header_key_len;
+ char *call_check_header_key;
+ ngx_int_t i, tens;
+ i = count;
+ /*like "x-mfdn-call-check-001", "x-mfdn-call-check-900"*/
+ call_check_header_key_len = ngx_strlen(NGX_HTTP_CALL_CHECK_HEADER_NAME_PREFIX) + 3 + 1;
+ call_check_header_key = ngx_pcalloc(r->pool, call_check_header_key_len);
+ strcpy(call_check_header_key, NGX_HTTP_CALL_CHECK_HEADER_NAME_PREFIX);
+ if (i < 10){
+ call_check_header_key[call_check_header_key_len-4] = NUMBER[0];
+ call_check_header_key[call_check_header_key_len-3] = NUMBER[0];
+ call_check_header_key[call_check_header_key_len-2] = NUMBER[i];
+ call_check_header_key[call_check_header_key_len-1] = '\0';
+ }else if (i<100){
+ call_check_header_key[call_check_header_key_len-4] = NUMBER[0];
+ call_check_header_key[call_check_header_key_len-3] = NUMBER[(i/10)];
+ call_check_header_key[call_check_header_key_len-2] = NUMBER[(i%10)];
+ call_check_header_key[call_check_header_key_len-1] = '\0';
+ }else if (i<1000){
+ tens = (i - (i/100)*100);
+ call_check_header_key[call_check_header_key_len-4] = NUMBER[(i/100)];
+ call_check_header_key[call_check_header_key_len-3] = NUMBER[(tens/10)];
+ call_check_header_key[call_check_header_key_len-2] = NUMBER[(tens%10)];
+ call_check_header_key[call_check_header_key_len-1] = '\0';
+ }else{
+ call_check_header_key[call_check_header_key_len-4] = NUMBER[9];
+ call_check_header_key[call_check_header_key_len-3] = NUMBER[9];
+ call_check_header_key[call_check_header_key_len-2] = NUMBER[9];
+ call_check_header_key[call_check_header_key_len-1] = '\0';
+ }
+ return call_check_header_key;
+}
+
+
+static ngx_int_t
+ngx_http_add_call_check_internal(ngx_http_request_t *r,
+ const char *check_point_name){
+ ngx_table_elt_t *h;
+ ngx_int_t count;
+ u_char *call_check_header_key;
+ u_char *call_check_header_value;
+ u_char *count_value;
+ ngx_int_t tens;
+ if (r == NULL || check_point_name == NULL){
+ return NGX_ERROR;
+ }
+ if (r->pool == NULL){
+ // ngx_log_error(NGX_LOG_WARN, r->connection->log, 0, "%s request_pointer: '%p' can't add call check point %s due to request pool is NULL.",
+ // NGX_HTTP_CALL_TRACE_LOG_PRX, r, trace_point_name);
+ return NGX_ERROR;
+ }
+ h = search_headers_out(r, (u_char *)NGX_HTTP_CALL_CHECK_COUNT_HEADER_NAME
+ , ngx_strlen(NGX_HTTP_CALL_CHECK_COUNT_HEADER_NAME));
+
+ if (h == NULL){
+ /*
+ Need to add call check header here
+ */
+ h = ngx_list_push(&r->headers_out.headers);
+ if (h == NULL) {
+ return NGX_ERROR;
+ }
+ ngx_str_set(&h->key, NGX_HTTP_CALL_CHECK_COUNT_HEADER_NAME);
+ ngx_str_set(&h->value, "1");
+ h->hash = 0;//0, for internel usage, not send out, and 1 will send it out to client
+
+ count = 1;
+ }else{
+ count = ngx_atoi(h->value.data, h->value.len);
+ count ++;
+ }
+
+ if (count > NGX_HTTP_CALL_CHECK_MAX_COUNT){
+ // ngx_log_error(NGX_LOG_WARN, r->connection->log, 0, "%s request_pointer: '%p' can't add call check point %s, due to call check count %d exceeds %d.",
+ // NGX_HTTP_CALL_TRACE_LOG_PRX, r, trace_point_name, depth, NGX_HTTP_CALL_CHECK_MAX_COUNT);
+ return NGX_ERROR;
+ }
+
+ if (count < 10){
+ count_value = ngx_pcalloc(r->pool, 2);
+ count_value[0] = NUMBER[count];
+ count_value[1] = '\0';
+ h->value.data = count_value;
+ h->value.len = 1;
+ }else if( count < 100){
+ count_value = ngx_pcalloc(r->pool, 3);
+ count_value[0] = NUMBER[(count/10)];
+ count_value[1] = NUMBER[(count%10)];
+ count_value[2] = '\0';
+ h->value.data = count_value;
+ h->value.len = 2;
+ }else if(count < 1000){
+ count_value = ngx_pcalloc(r->pool, 4);
+ count_value[0] = NUMBER[(count/100)];
+ tens = (count - (count/100)*100);
+ count_value[1] = NUMBER[tens/10];
+ count_value[2] = NUMBER[tens%10];
+ count_value[3] = '\0';
+ h->value.data = count_value;
+ h->value.len = 3;
+ }else{
+ ngx_log_error(NGX_LOG_WARN, r->connection->log, 0, "%s request_pointer: '%p' "
+ "can't add call check point %s due to call check count %d "
+ "can't support more than 1000.",
+ NGX_HTTP_CALL_TRACE_LOG_PRX, r, check_point_name, count);
+ return NGX_ERROR;
+ }
+
+ h = ngx_list_push(&r->headers_out.headers);
+ if (h == NULL) {
+ return NGX_ERROR;
+ }
+
+ call_check_header_key = (u_char *)generate_call_check_header_key(r, count);
+ call_check_header_value = (u_char *)generate_call_trace_header_value(r, check_point_name);
+
+ h->key.data = call_check_header_key;
+ h->key.len = ngx_strlen(call_check_header_key);
+ h->value.data = call_check_header_value;
+ h->value.len = ngx_strlen(call_check_header_value);
+ h->hash = 0;//0, for internel usage, not send out, and 1 will send it out to client
+ ngx_log_error(NGX_LOG_WARN, r->connection->log, 0, "%s request_pointer: '%p',"
+ " add call check header '%s' : '%s'",
+ NGX_HTTP_CALL_TRACE_LOG_PRX, r, h->key.data, h->value.data);
+ return NGX_OK;
+}
+
+
+static ngx_table_elt_t *
+search_check_point_from_headers_out(ngx_http_request_t *r,
+ const char *check_point_name) {
+ ngx_list_part_t *part;
+ ngx_table_elt_t *h;
+ ngx_uint_t i;
+ size_t key_prefix_len, key_len;
+ u_char* name_start_pos;
+ key_prefix_len = ngx_strlen(NGX_HTTP_CALL_CHECK_HEADER_NAME_PREFIX);
+ key_len = key_prefix_len + 3;
+
+ /*
+ Get the first part of the list. There is usual only one part.
+ */
+ part = &r->headers_out.headers.part;
+ h = part->elts;
+
+ /*
+ Headers list array may consist of more than one part,
+ so loop through all of it
+ */
+ for (i = 0; /* void */ ; i++) {
+ if (i >= part->nelts) {
+ if (part->next == NULL) {
+ break;
+ }
+
+ part = part->next;
+ h = part->elts;
+ i = 0;
+ }
+ // ngx_log_error(NGX_LOG_WARN, r->connection->log, 0, "%s request_pointer: '%p', key.data '%s', key.len '%d', key.value.data '%s', key len '%d', check_point_name '%s', ngx_strlen(check_point_name) '%d' ",
+ // NGX_HTTP_CALL_TRACE_LOG_PRX, r, h[i].key.data, h[i].key.len,h[i].value.data, key_len, check_point_name, ngx_strlen(check_point_name));
+
+ if (key_len != h[i].key.len) {
+ continue;
+ }
+ if (ngx_strncasecmp(h[i].key.data, (u_char*)NGX_HTTP_CALL_CHECK_HEADER_NAME_PREFIX, key_prefix_len) != 0) {
+ // ngx_log_error(NGX_LOG_WARN, r->connection->log, 0, "%s request_pointer: '%p', key prefix not equal. ",
+ // NGX_HTTP_CALL_TRACE_LOG_PRX, r);
+ continue;
+ }
+ name_start_pos = ngx_strnstr(h[i].value.data, "-", NGX_INT64_LEN) + 1;
+ if (ngx_strncasecmp(name_start_pos, (u_char*)check_point_name, ngx_strlen(check_point_name)) != 0) {
+ // ngx_log_error(NGX_LOG_WARN, r->connection->log, 0, "%s request_pointer: '%p', value not equal '%s'. ",
+ // NGX_HTTP_CALL_TRACE_LOG_PRX, r, name_start_pos);
+ continue;
+ }
+ return &h[i];
+ }
+ return NULL;
+}
+
+
+static ngx_int_t
+ngx_http_print_call_check_latency_internal(ngx_http_request_t *r,
+ const char *check_point_name, ngx_int_t latency){
+ ngx_table_elt_t *h;
+ u_char *call_trace_header;
+ u_char *s2;
+ time_t first_trace_time;
+ ngx_int_t check_latency;
+ if (r == NULL || check_point_name == NULL){
+ return NGX_ERROR;
+ }
+ if (r->pool == NULL){
+ return NGX_ERROR;
+ }
+ call_trace_header = (u_char *)generate_call_trace_header_key(r, 1);
+ h = search_headers_out(r, call_trace_header, ngx_strlen(call_trace_header));
+ if (h == NULL){
+ ngx_log_error(NGX_LOG_WARN, r->connection->log, 0, "%s request_pointer: '%p',"
+ " can't find first call trace header '%s' ",
+ NGX_HTTP_CALL_TRACE_LOG_PRX, r, call_trace_header);
+ return NGX_ERROR;
+ }
+ s2 = ngx_strnstr(h->value.data, "-", NGX_INT64_LEN);
+ first_trace_time = ngx_atotm(h->value.data, s2-h->value.data);
+ check_latency = ngx_time() - first_trace_time;
+ if (check_latency < latency){
+ return NGX_ERROR;
+ }
+ //check whether already met this check point
+ h = search_check_point_from_headers_out(r, check_point_name);
+ if (h != NULL){
+ // ngx_log_error(NGX_LOG_WARN, r->connection->log, 0, "%s request_pointer: '%p', already met call check point '%s', latency '%d' exceeds '%d' ",
+ // NGX_HTTP_CALL_TRACE_LOG_PRX, r, check_point_name, check_latency, latency);
+ return NGX_ERROR;
+ }
+ ngx_http_add_call_check_internal(r, check_point_name);
+ ngx_log_error(NGX_LOG_WARN, r->connection->log, 0, "%s request_pointer: '%p',"
+ "first time meet call check point '%s', latency '%d' exceeds '%d' ",
+ NGX_HTTP_CALL_TRACE_LOG_PRX, r, check_point_name, check_latency, latency);
+ return check_latency;
+}
+
+
+/* latency in second*/
+ngx_int_t
+ngx_http_print_call_check_latency(ngx_http_request_t *r, const char *check_point_name, ngx_int_t latency){
+ ngx_int_t rv;
+ rv = NGX_ERROR;
+#if (NGX_HTTP_CALL_TRACE_ENABLE)
+ rv = ngx_http_print_call_check_latency_internal(r, check_point_name, latency);
+#else
+ ngx_http_print_call_check_latency_internal(NULL, NULL, 0);
+ rv = NGX_OK;
+#endif
+ return rv;
+}
+
diff -r d3235149d17f -r 1cf1d4a74783 src/http/ngx_http_call_trace.h
--- /dev/null Thu Jan 01 00:00:00 1970 +0000
+++ b/src/http/ngx_http_call_trace.h Mon Dec 18 18:09:36 2017 +0800
@@ -0,0 +1,89 @@
+
+/*
+ * Copyright (C) Xiaohua Wang
+ * Copyright (C) Nginx, Inc.
+ */
+
+
+#ifndef _NGX_HTTP_CALL_TRACE_H_INCLUDED_
+#define _NGX_HTTP_CALL_TRACE_H_INCLUDED_
+
+/*
+ * Added to trace http request call flow in nginx,
+ * especillay for performance or load test purpose.
+ * Because info level log is not enough,
+ * and debug log is too much which impacts performace a lot.
+ * Currently, two scenarios are supported.
+ * 1) trace any piont in source code like before/after function entry, or middle of function.
+ * 2) trace any call flow which takes longer time than specific latency between two check point.
+ * Please find an example at the end of this file.
+ */
+
+#include <ngx_config.h>
+#include <ngx_core.h>
+#include <ngx_http.h>
+#include <ngx_http_request.h>
+
+#if (NGX_HTTP_CALL_TRACE)
+
+ngx_int_t ngx_http_add_call_trace(ngx_http_request_t *r,
+ const char *trace_point_name);
+void ngx_http_print_call_trace_warn_level(ngx_http_request_t *r);
+void ngx_http_print_call_trace_debug_level(ngx_http_request_t *r);
+ngx_int_t ngx_http_print_call_trace_exceeds_latency(ngx_http_request_t *r,
+ ngx_int_t latency);
+ngx_int_t ngx_http_print_call_check_latency(ngx_http_request_t *r,
+ const char *check_point_name, ngx_int_t latency);
+
+#else /*(NGX_HTTP_CALL_TRACE)*/
+
+inline ngx_int_t ngx_http_add_call_trace(ngx_http_request_t *r,
+ const char *trace_point_name){
+ return NGX_OK;
+}
+inline void ngx_http_print_call_trace_warn_level(ngx_http_request_t *r){
+ return;
+}
+inline void ngx_http_print_call_trace_debug_level(ngx_http_request_t *r){
+ return;
+}
+inline ngx_int_t ngx_http_print_call_trace_exceeds_latenc(ngx_http_request_t *r,
+ ngx_int_t latency){
+ return NGX_OK;
+}
+inline ngx_int_t ngx_http_print_call_check_latency(ngx_http_request_t *r,
+ const char *check_point_name, ngx_int_t latency){
+ return NGX_OK;
+}
+
+#endif /*(NGX_HTTP_CALL_TRACE)*/
+
+#endif /* _NGX_HTTP_CALL_TRACE_H_INCLUDED_ */
+
+/*
+ * For example:
+ * void
+ * ngx_http_process_request(ngx_http_request_t *r)
+ * {
+ * ngx_connection_t *c;
+ * ngx_http_add_call_trace(r, "start ngx_http_process_request");
+ * ...
+ * }
+ *
+ * static void
+ * ngx_http_request_handler(ngx_event_t *ev)
+ * {
+ * ngx_connection_t *c;
+ * ngx_http_request_t *r;
+ *
+ * c = ev->data;
+ * r = c->data;
+ * ngx_http_add_call_trace(r, "start ngx_http_request_handler");
+ * ngx_http_set_log_request(c->log, r);
+ * ...
+ * }
+ *
+ * In error log, trace messages will be printed as following. call sequence:timestampe-check point name.
+ * 'x-ngx-call-trace-001' : '1513586413-start ngx_http_process_request'
+ * 'x-ngx-call-trace-002' : '1513586413-start ngx_http_finalize_request'
+ */
\ No newline at end of file
More information about the nginx-devel
mailing list