Merge pull request #228 from chobits/for_pull_request

Feature: get the time to receive the first byte of data from proxy server

Author: chobits

README.md

@@ -38,6 +38,7 @@ Table of Contents
       * [$proxy_connect_send_timeout](#proxy_connect_send_timeout-1)
       * [$proxy_connect_resolve_time](#proxy_connect_resolve_time)
       * [$proxy_connect_connect_time](#proxy_connect_connect_time)
+      * [$proxy_connect_first_byte_time](#proxy_connect_first_byte_time)
       * [$proxy_connect_response](#proxy_connect_response-1)
    * [Compatibility](#compatibility)
       * [Nginx Compatibility](#nginx-compatibility)
@@ -480,6 +481,15 @@ Keeps time spent on establishing a connection with the upstream server; the time
 * Value of "-" means name resolving or connecting failed.
 
 
+$proxy_connect_first_byte_time
+---------------------------
+
+Keeps time to receive the first byte of data from the upstream server; the time is kept in seconds with millisecond resolution.
+
+* Value of "" means this module does not work on this request.
+* Value of "-" means name resolving, connecting or receving failed.
+
+
 $proxy_connect_response
 ---------------------------
 

ngx_http_proxy_connect_module.c

@@ -45,6 +45,7 @@ typedef struct {
 typedef struct {
     ngx_msec_t                       resolve_time;
     ngx_msec_t                       connect_time;
+    ngx_msec_t                       first_byte_time;
 
     /* TODO:
     off_t                            bytes_received;
@@ -133,6 +134,8 @@ static ngx_int_t ngx_http_proxy_connect_resolve_time_variable(ngx_http_request_t
     ngx_http_variable_value_t *v, uintptr_t data);
 static ngx_int_t ngx_http_proxy_connect_connect_time_variable(ngx_http_request_t *r,
     ngx_http_variable_value_t *v, uintptr_t data);
+static ngx_int_t ngx_http_proxy_connect_first_byte_time_variable(ngx_http_request_t *r,
+    ngx_http_variable_value_t *v, uintptr_t data);
 static ngx_int_t ngx_http_proxy_connect_variable_get_response(ngx_http_request_t *r,
     ngx_http_variable_value_t *v, uintptr_t data);
 static void ngx_http_proxy_connect_variable_set_response(ngx_http_request_t *r,
@@ -277,6 +280,10 @@ static ngx_http_variable_t  ngx_http_proxy_connect_vars[] = {
       ngx_http_proxy_connect_connect_time_variable, 0,
       NGX_HTTP_VAR_NOCACHEABLE, 0 },
 
+    { ngx_string("proxy_connect_first_byte_time"), NULL,
+      ngx_http_proxy_connect_first_byte_time_variable, 0,
+      NGX_HTTP_VAR_NOCACHEABLE, 0 },
+
     { ngx_string("proxy_connect_response"),
       ngx_http_proxy_connect_variable_set_response,
       ngx_http_proxy_connect_variable_get_response,
@@ -722,6 +729,13 @@ ngx_http_proxy_connect_tunnel(ngx_http_request_t *r,
                 do_write = 1;
                 b->last += n;
 
+                if (from_upstream) {
+                    if (u->state.first_byte_time == (ngx_msec_t) -1) {
+                        u->state.first_byte_time = ngx_current_msec
+                            - u->start_time;
+                    }
+                }
+
                 continue;
             }
 
@@ -1042,6 +1056,7 @@ ngx_http_proxy_connect_process_connect(ngx_http_request_t *r,
 
     u->start_time = ngx_current_msec;
     u->state.connect_time = (ngx_msec_t) -1;
+    u->state.first_byte_time = (ngx_msec_t) -1;
 
     rc = ngx_event_connect_peer(&u->peer);
 
@@ -2194,6 +2209,63 @@ ngx_http_proxy_connect_connect_time_variable(ngx_http_request_t *r,
 }
 
 
+static ngx_int_t
+ngx_http_proxy_connect_first_byte_time_variable(ngx_http_request_t *r,
+    ngx_http_variable_value_t *v, uintptr_t data)
+{
+    u_char                             *p;
+    size_t                              len;
+    ngx_msec_int_t                      ms;
+    ngx_http_proxy_connect_ctx_t       *ctx;
+    ngx_http_proxy_connect_upstream_t  *u;
+
+    if (r->method != NGX_HTTP_CONNECT) {
+        return NGX_OK;
+    }
+
+    v->valid = 1;
+    v->no_cacheable = 0;
+    v->not_found = 0;
+
+    ctx = ngx_http_get_module_ctx(r, ngx_http_proxy_connect_module);
+
+    if (ctx == NULL) {
+        v->not_found = 1;
+        return NGX_OK;
+    }
+
+    u = ctx->u;
+
+    if (u == NULL || !u->connected) {
+        v->not_found = 1;
+        return NGX_OK;
+    }
+
+    len = NGX_TIME_T_LEN + 4;
+
+    p = ngx_pnalloc(r->pool, len);
+    if (p == NULL) {
+        return NGX_ERROR;
+    }
+
+    v->data = p;
+
+    ms = u->state.first_byte_time;
+
+    if (ms != -1) {
+        ms = ngx_max(ms, 0);
+        p = ngx_sprintf(p, "%T.%03M", (time_t) ms / 1000, ms % 1000);
+
+    } else {
+        *p++ = '-';
+    }
+
+    v->len = p - v->data;
+
+    return NGX_OK;
+}
+
+
 static ngx_int_t
 ngx_http_proxy_connect_variable_get_response(ngx_http_request_t *r,
     ngx_http_variable_value_t *v, uintptr_t data)

t/http_proxy_connect_resolve_variables.t

@@ -78,9 +78,13 @@ events {
 http {
     %%TEST_GLOBALS_HTTP%%
 
+#    lua_load_resty_core off;
+
     log_format connect '$remote_addr - $remote_user [$time_local] "$request" '
                        '$status $body_bytes_sent var:$connect_host-$connect_port-$connect_addr '
-                       'resolve:$proxy_connect_resolve_time,connect:$proxy_connect_connect_time,';
+                       'resolve:$proxy_connect_resolve_time,'
+                       'connect:$proxy_connect_connect_time,'
+                       'fbt:$proxy_connect_first_byte_time,';
 
     access_log %%TESTDIR%%/connect.log connect;
     error_log %%TESTDIR%%/connect_error.log error;
@@ -139,6 +143,27 @@ http {
         access_log off;
         return 200 "8081 server";
     }
+
+    # for $proxy_connect_first_byte_time testing
+    server {
+        access_log off;
+        listen 8082;
+        rewrite_by_lua '
+            ngx.sleep(1)
+            ngx.say("8082 server fbt")
+        ';
+
+    }
+    server {
+        access_log off;
+        listen 8083;
+        rewrite_by_lua '
+            ngx.sleep(0.5)
+            ngx.say("8083 server fbt")
+        ';
+
+    }
+
 }
 
 EOF
@@ -197,6 +222,16 @@ like($log, qr/"CONNECT non-existent-domain.com:8081 HTTP\/1.1" 502 .+ resolve:-,
 $errlog = http_get('/connect_error.log');
 like($errlog, qr/proxy_connect: non-existent-domain.com could not be resolved .+Host not found/, 'test error.log for 502 respsone');
 
+# test first byte time
+# fbt:~1s
+http_connect_request('127.0.0.1', '8082', '/');
+$log = http_get('/connect.log');
+like($log, qr/"CONNECT 127.0.0.1:8082 HTTP\/1.1" 200 .+ resolve:0\....,connect:0\....,fbt:1\....,/, 'test first byte time: 1s');
+# fbt:~0.5s
+http_connect_request('127.0.0.1', '8083', '/');
+$log = http_get('/connect.log');
+like($log, qr/"CONNECT 127.0.0.1:8083 HTTP\/1.1" 200 .+ resolve:0\....,connect:0\....,fbt:0\.5..,/, 'test first byte time: 0.5s');
+
 $t->stop();