Skip to content

Instantly share code, notes, and snippets.

@rkbodenner
Created March 1, 2010 19:08
Show Gist options
  • Save rkbodenner/318681 to your computer and use it in GitHub Desktop.
Save rkbodenner/318681 to your computer and use it in GitHub Desktop.
Add a 'start_time' variable to nginx 0.8.33 to support an X-REQUEST-START header. This header is used by New Relic RPM to record queue time.
--- src/http/ngx_http_variables.c.orig 2010-01-11 03:21:46.000000000 -0800
+++ src/http/ngx_http_variables.c 2010-02-18 10:01:32.000000000 -0800
@@ -93,6 +93,9 @@
static ngx_int_t ngx_http_variable_pid(ngx_http_request_t *r,
ngx_http_variable_value_t *v, uintptr_t data);
+static ngx_int_t ngx_http_variable_start_time(ngx_http_request_t *r,
+ ngx_http_variable_value_t *v, uintptr_t data);
+
/*
* TODO:
* Apache CGI: AUTH_TYPE, PATH_INFO (null), PATH_TRANSLATED
@@ -253,6 +256,9 @@
{ ngx_string("pid"), NULL, ngx_http_variable_pid,
0, 0, 0 },
+ { ngx_string("start_time"), NULL, ngx_http_variable_start_time,
+ 0, 0, 0 },
+
{ ngx_null_string, NULL, NULL, 0, 0, 0 }
};
@@ -1749,6 +1755,27 @@
return re;
}
+static ngx_int_t
+ngx_http_variable_start_time(ngx_http_request_t *r,
+ ngx_http_variable_value_t *v, uintptr_t data)
+{
+ u_char *p;
+
+ p = ngx_pnalloc(r->pool, NGX_INT64_LEN);
+ if (p == NULL) {
+ return NGX_ERROR;
+ }
+
+ uint64_t usec = (((uint64_t)r->start_sec * 1000 * 1000) + ((uint64_t)r->start_msec * 1000));
+
+ v->len = ngx_sprintf(p, "%L", usec) - p;
+ v->valid = 1;
+ v->no_cacheable = 0;
+ v->not_found = 0;
+ v->data = p;
+
+ return NGX_OK;
+}
ngx_int_t
ngx_http_regex_exec(ngx_http_request_t *r, ngx_http_regex_t *re, ngx_str_t *s)
@mfischer-zd
Copy link

More questions:

  • Does the timestamp indicate when the request was fully received, when the connection was accept()ed, or when the first byte was received?
  • Are you aware of a way to apply a similar timestamp to a backposted request to an upstream (right before the connect())?

@rkbodenner
Copy link
Author

rkbodenner commented Mar 29, 2012 via email

@ttilley
Copy link

ttilley commented Oct 7, 2012

If you are unable to patch nginx or unwilling, yet have the lua engine available to you, you can use the much simpler:

set_by_lua $start_time 'ngx.now() * 1000 * 1000';

The lua API for nginx makes available the cached timestamp via ngx.time() and ngx.now(), where time is an int in seconds and now is a float in seconds (I am not sure to what point the fractional portion is accurate). If you absolutely need to have the current timestamp, you can update the cached version by force with ngx.update_time(), but this is potentially expensive. Rather, instead, it is suggested that you set timer_resolution in your config to the maximum latency you can tolerate in your recorded numbers.

If you are using CloudFoundry, which uses nginx and lua alongside a sinatra app to dynamically handle routing requests to the currently correct location or load balance across multiple instances, then you should also set the X-Queue-Start header after the subrequest to the router. Despite using a cached timestamp, you will get a fresh one as it's updated after every event in the event loop, and a subrequest is performed non-blocking if performed via the nginx lua api (which it will be).

@ttilley
Copy link

ttilley commented Oct 7, 2012

I stand corrected. Using the above, the result appears to always use scientific notation: X-Request-Start:t=1.349622085668e+15. The correct way to get the desired result is the following:

set_by_lua $start_time '
  local seconds = ngx.now()
  local microseconds = seconds * 1000 * 1000
  return string.format("%d", microseconds);
';

@valo
Copy link

valo commented Nov 15, 2012

OMG, this question is so important:

"Does the timestamp indicate when the request was fully received, when the connection was accept()ed, or when the first byte was received?"

Please clarify this, because this patch is linked from authoritative sources like the NewRelic docs and not knowing this information looks really unprofessional. At the very least the guys from NewRelic should clarify this issue!

@lawrencepit
Copy link

NewRelic writes: "To collect request queuing time, you need to mark the HTTP request with a timestamp when queuing starts." -- Given that they are linking to this patch they seem to think this patch does just that. Seems clear enough to me.

Whether this patch really does that....? I wouldn't trust any clarification from an "authoritative source" ;-) Better test for yourself, apply this patch, upload a large file, and see which timestamp you receive in your backend.

Perhaps you could look at it this way: it's the timestamp of the moment nginx adds the proxy header. Nginx probably won't do that when the connection is accept()ed or when the first byte is received, as there's nothing to add the header to yet. Given you probably use proxy_pass, nginx documents: "the entire client request will be buffered in nginx before being passed on to the backend proxied servers". My guess is the timestamp is close to the time the request is passed into the queue for delivery to a backend proxy server.

@lawrencepit
Copy link

... but then... ;) if I look at this patch, it appears to me it's sending the recorded start time of the nginx request, i.e. the time when the connection was accept()ed.

@lawrencepit
Copy link

The patch below applies to the nginx stable-1.2 branch. It supports two http variables: $usec and $start_usec. In your nginx.conf file you could add:

  proxy_set_header X-Request-Start 't=$start_usec';
  proxy_set_header X-Queue-Start 't=$usec';

Request-Start has the time with a microseconds resolution that indicates when the first bytes were read from the client.

Queue-Start has the time with a microseconds resolution that indicates when the request is sent to the backend server.

I chose the name usec as it seems to be in line with the variable msec as used by the nginx log format variables.

Note that at the New Relic site they indicate they support these two variables, see the paragraph "Implementation Notes" at https://newrelic.com/docs/features/tracking-front-end-time.

Subject: [PATCH] Feature: $usec and $start_usec variables, useful for setting
 in proxy headers before sending request to backend servers
 so queue times can be measured.


---
 src/http/ngx_http_variables.c | 60 +++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 60 insertions(+)

diff --git a/src/http/ngx_http_variables.c b/src/http/ngx_http_variables.c
index b0949c7..b9a630a 100644
--- a/src/http/ngx_http_variables.c
+++ b/src/http/ngx_http_variables.c
@@ -108,6 +108,10 @@ static ngx_int_t ngx_http_variable_hostname(ngx_http_request_t *r,
     ngx_http_variable_value_t *v, uintptr_t data);
 static ngx_int_t ngx_http_variable_pid(ngx_http_request_t *r,
     ngx_http_variable_value_t *v, uintptr_t data);
+static ngx_int_t ngx_http_variable_usec(ngx_http_request_t *r,
+    ngx_http_variable_value_t *v, uintptr_t data);
+static ngx_int_t ngx_http_variable_start_usec(ngx_http_request_t *r,
+    ngx_http_variable_value_t *v, uintptr_t data);

 /*
  * TODO:
@@ -285,6 +289,12 @@ static ngx_http_variable_t  ngx_http_core_variables[] = {
     { ngx_string("pid"), NULL, ngx_http_variable_pid,
       0, 0, 0 },

+    { ngx_string("usec"), NULL, ngx_http_variable_usec,
+      0, 0, 0 },
+
+    { ngx_string("start_usec"), NULL, ngx_http_variable_start_usec,
+      0, 0, 0 },
+
 #if (NGX_HAVE_TCP_INFO)
     { ngx_string("tcpinfo_rtt"), NULL, ngx_http_variable_tcpinfo,
       0, NGX_HTTP_VAR_NOCACHEABLE, 0 },
@@ -1915,6 +1925,56 @@ ngx_http_variable_pid(ngx_http_request_t *r,
 }


+static ngx_int_t
+ngx_http_variable_usec(ngx_http_request_t *r,
+    ngx_http_variable_value_t *v, uintptr_t data)
+{
+    u_char     *p;
+    ngx_time_t *tp;
+    uint64_t   usec;
+
+    p = ngx_pnalloc(r->pool, NGX_INT64_LEN);
+    if (p == NULL) {
+        return NGX_ERROR;
+    }
+
+    tp = ngx_timeofday();
+    usec = (uint64_t) (tp->sec * 1000 * 1000 + tp->msec * 1000);
+
+    v->len = ngx_sprintf(p, "%L", usec) - p;
+    v->valid = 1;
+    v->no_cacheable = 0;
+    v->not_found = 0;
+    v->data = p;
+
+    return NGX_OK;
+}
+
+
+static ngx_int_t
+ngx_http_variable_start_usec(ngx_http_request_t *r,
+    ngx_http_variable_value_t *v, uintptr_t data)
+{
+    u_char   *p;
+    uint64_t start_usec;
+
+    p = ngx_pnalloc(r->pool, NGX_INT64_LEN);
+    if (p == NULL) {
+        return NGX_ERROR;
+    }
+
+    start_usec = (uint64_t) (r->start_sec * 1000 * 1000 + r->start_msec * 1000);
+
+    v->len = ngx_sprintf(p, "%L", start_usec) - p;
+    v->valid = 1;
+    v->no_cacheable = 0;
+    v->not_found = 0;
+    v->data = p;
+
+    return NGX_OK;
+}
+
+
 void *
 ngx_http_map_find(ngx_http_request_t *r, ngx_http_map_t *map, ngx_str_t *match)
 {
-- 
1.7.11.1

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment