add notice-log for every request

[idning]

we need a NOTICE log for every request, fields::

type, key, req_len, rsp_len, request_time (like access_log for nginx) 

so we can stat req/s, average srv time, key frequency with awk/grep, this is very useful for Tracing.

here is the format:

[Fri May 30 16:43:03 2014] nc_request.c:102 notice req 3 done on c 11 req_time: 0.265 type: SET narg: 3 req_len: 35 rsp_len: 5 key0: kkk-3, done: 1, error:0
[Fri May 30 16:43:03 2014] nc_request.c:102 notice req 23 done on c 11 req_time: 0.159 type: MGET narg: 11 req_len: 11 rsp_len: 16 key0: kkk-3, done: 1, error:0
[Fri May 30 16:43:03 2014] nc_request.c:102 notice req 43 done on c 11 req_time: 0.121 type: DEL narg: 11 req_len: 11 rsp_len: 5 key0: kkk-3, done: 1, error:0
[Fri May 30 16:43:03 2014] nc_request.c:102 notice req 63 done on c 11 req_time: 0.108 type: MGET narg: 11 req_len: 11 rsp_len: 10 key0: kkk-3, done: 1, error:0

maybe add:

• client/backend addr
• log timestamp should ms/us. [Wed May 28 15:06:12.xxx 2014]

[idning]

this patch will miss some request in pipeline, the newest code can be found here(and we use ms in log):

idning@8e08544
idning@28b1710

@manjuraj : it's hard to maintain 2+ branches, if this can be merged, I will create a new pull request for the newest code.

current notice-log example:

[2014-06-14 17:57:42.295] nc_request.c:109 [notice] req 305097 done on c 47 req_time: 1.085 type: GET narg: 2 req_len: 36 rsp_len: 5 key0: key:__rand_int__ peer: 127.0.0.5:41949 127.0.0.5:2003:1 done: 1 error: 0

[manjuraj]

No need for a py script. You can generate the strings using macro magic called strigificaion :) This way your code never gets outdate

See this for reference --

• https://github.com/twitter/twemproxy/blob/master/src%2Fnc_stats.h#L23-L49
• https://github.com/twitter/twemproxy/blob/master/src%2Fnc_stats.h#L117-L122
• http://gcc.gnu.org/onlinedocs/cpp/Stringification.html

[idning]

macro create clean code but break cscope/ctags :(

clean code is more important, I will have a try.

[manjuraj]

Looks great. Added few comments on the commit

Instead of the format:

request.c:109 [notice] req 305097 done on c 47 req_time: 1.085 type: GET narg: 2 req_len: 36 rsp_len: 5 key0: key:__rand_int__ peer: 127.0.0.5:41949 127.0.0.5:2003:1 done: 1 error: 0

can we do this:

request.c:109 [notice] req 305097 done on c 47 latency 1.085 usec type GET narg 2 req_len 36 rsp_len 5 key0: key __rand_int__ peer 127.0.0.5:41949 127.0.0.5:2003:1 done 1 error 0

The reason I stay away from ":" is because throughout the nutcracker code base ":" is used the separate the logline from the error message like this - https://github.com/twitter/twemproxy/blob/master/src%2Fnc_client.c#L184

[manjuraj]

Great job @idning