add notice-log for every request

scripts/gen_msg_type_str.py

@@ -0,0 +1,37 @@
+#!/usr/bin/env python
+#coding: utf-8
+#file   : gen_msg_type_str.py
+#author : ning
+#date   : 2014-05-28 13:45:16
+
+
+import os
+import re
+
+content = file('src/nc_message.h').read()
+
+m = re.search(r'typedef enum msg_type {(.*?)}', content, re.DOTALL)
+body = m.group(1)
+print body
+
+print '''
+inline char *
+nc_msg_type_str(msg_type_t type)
+{
+    switch (type) {
+'''
+
+for line in body.split():
+    if line.find(',') > -1:
+        msg_type = line.split(',')[0].strip()
+        msg_type_str = msg_type.split('_')[-1]
+        print '    case %s: ' % msg_type
+        print '        return "%s"; ' % msg_type_str
+
+print '''
+    default:
++        return "UNKNOWN";
+    }
+}
+'''
+

src/nc_message.c

@@ -212,6 +212,7 @@ _msg_get(void)
 
     STAILQ_INIT(&msg->mhdr);
     msg->mlen = 0;
+    msg->start_usec = 0;
 
     msg->state = 0;
     msg->pos = NULL;
@@ -826,3 +827,253 @@ msg_send(struct context *ctx, struct conn *conn)
 
     return NC_OK;
 }
+
+/*
+ * this is auto generate by scripts/gen_msg_type_str.py
+ */
+inline char *
+msg_type_str(msg_type_t type)
+{
+    switch (type) {
+    case MSG_UNKNOWN:
+        return "UNKNOWN";
+    case MSG_REQ_MC_GET:
+        return "GET";
+    case MSG_REQ_MC_GETS:
+        return "GETS";
+    case MSG_REQ_MC_DELETE:
+        return "DELETE";
+    case MSG_REQ_MC_CAS:
+        return "CAS";
+    case MSG_REQ_MC_SET:
+        return "SET";
+    case MSG_REQ_MC_ADD:
+        return "ADD";
+    case MSG_REQ_MC_REPLACE:
+        return "REPLACE";
+    case MSG_REQ_MC_APPEND:
+        return "APPEND";
+    case MSG_REQ_MC_PREPEND:
+        return "PREPEND";
+    case MSG_REQ_MC_INCR:
+        return "INCR";
+    case MSG_REQ_MC_DECR:
+        return "DECR";
+    case MSG_REQ_MC_QUIT:
+        return "QUIT";
+    case MSG_RSP_MC_NUM:
+        return "NUM";
+    case MSG_RSP_MC_STORED:
+        return "STORED";
+    case MSG_RSP_MC_NOT_STORED:
+        return "STORED";
+    case MSG_RSP_MC_EXISTS:
+        return "EXISTS";
+    case MSG_RSP_MC_NOT_FOUND:
+        return "FOUND";
+    case MSG_RSP_MC_END:
+        return "END";
+    case MSG_RSP_MC_VALUE:
+        return "VALUE";
+    case MSG_RSP_MC_DELETED:
+        return "DELETED";
+    case MSG_RSP_MC_ERROR:
+        return "ERROR";
+    case MSG_RSP_MC_CLIENT_ERROR:
+        return "ERROR";
+    case MSG_RSP_MC_SERVER_ERROR:
+        return "ERROR";
+    case MSG_REQ_REDIS_DEL:
+        return "DEL";
+    case MSG_REQ_REDIS_EXISTS:
+        return "EXISTS";
+    case MSG_REQ_REDIS_EXPIRE:
+        return "EXPIRE";
+    case MSG_REQ_REDIS_EXPIREAT:
+        return "EXPIREAT";
+    case MSG_REQ_REDIS_PEXPIRE:
+        return "PEXPIRE";
+    case MSG_REQ_REDIS_PEXPIREAT:
+        return "PEXPIREAT";
+    case MSG_REQ_REDIS_PERSIST:
+        return "PERSIST";
+    case MSG_REQ_REDIS_PTTL:
+        return "PTTL";
+    case MSG_REQ_REDIS_TTL:
+        return "TTL";
+    case MSG_REQ_REDIS_TYPE:
+        return "TYPE";
+    case MSG_REQ_REDIS_APPEND:
+        return "APPEND";
+    case MSG_REQ_REDIS_BITCOUNT:
+        return "BITCOUNT";
+    case MSG_REQ_REDIS_DECR:
+        return "DECR";
+    case MSG_REQ_REDIS_DECRBY:
+        return "DECRBY";
+    case MSG_REQ_REDIS_DUMP:
+        return "DUMP";
+    case MSG_REQ_REDIS_GET:
+        return "GET";
+    case MSG_REQ_REDIS_GETBIT:
+        return "GETBIT";
+    case MSG_REQ_REDIS_GETRANGE:
+        return "GETRANGE";
+    case MSG_REQ_REDIS_GETSET:
+        return "GETSET";
+    case MSG_REQ_REDIS_INCR:
+        return "INCR";
+    case MSG_REQ_REDIS_INCRBY:
+        return "INCRBY";
+    case MSG_REQ_REDIS_INCRBYFLOAT:
+        return "INCRBYFLOAT";
+    case MSG_REQ_REDIS_MGET:
+        return "MGET";
+    case MSG_REQ_REDIS_PSETEX:
+        return "PSETEX";
+    case MSG_REQ_REDIS_RESTORE:
+        return "RESTORE";
+    case MSG_REQ_REDIS_SET:
+        return "SET";
+    case MSG_REQ_REDIS_SETBIT:
+        return "SETBIT";
+    case MSG_REQ_REDIS_SETEX:
+        return "SETEX";
+    case MSG_REQ_REDIS_SETNX:
+        return "SETNX";
+    case MSG_REQ_REDIS_SETRANGE:
+        return "SETRANGE";
+    case MSG_REQ_REDIS_STRLEN:
+        return "STRLEN";
+    case MSG_REQ_REDIS_HDEL:
+        return "HDEL";
+    case MSG_REQ_REDIS_HEXISTS:
+        return "HEXISTS";
+    case MSG_REQ_REDIS_HGET:
+        return "HGET";
+    case MSG_REQ_REDIS_HGETALL:
+        return "HGETALL";
+    case MSG_REQ_REDIS_HINCRBY:
+        return "HINCRBY";
+    case MSG_REQ_REDIS_HINCRBYFLOAT:
+        return "HINCRBYFLOAT";
+    case MSG_REQ_REDIS_HKEYS:
+        return "HKEYS";
+    case MSG_REQ_REDIS_HLEN:
+        return "HLEN";
+    case MSG_REQ_REDIS_HMGET:
+        return "HMGET";
+    case MSG_REQ_REDIS_HMSET:
+        return "HMSET";
+    case MSG_REQ_REDIS_HSET:
+        return "HSET";
+    case MSG_REQ_REDIS_HSETNX:
+        return "HSETNX";
+    case MSG_REQ_REDIS_HVALS:
+        return "HVALS";
+    case MSG_REQ_REDIS_LINDEX:
+        return "LINDEX";
+    case MSG_REQ_REDIS_LINSERT:
+        return "LINSERT";
+    case MSG_REQ_REDIS_LLEN:
+        return "LLEN";
+    case MSG_REQ_REDIS_LPOP:
+        return "LPOP";
+    case MSG_REQ_REDIS_LPUSH:
+        return "LPUSH";
+    case MSG_REQ_REDIS_LPUSHX:
+        return "LPUSHX";
+    case MSG_REQ_REDIS_LRANGE:
+        return "LRANGE";
+    case MSG_REQ_REDIS_LREM:
+        return "LREM";
+    case MSG_REQ_REDIS_LSET:
+        return "LSET";
+    case MSG_REQ_REDIS_LTRIM:
+        return "LTRIM";
+    case MSG_REQ_REDIS_RPOP:
+        return "RPOP";
+    case MSG_REQ_REDIS_RPOPLPUSH:
+        return "RPOPLPUSH";
+    case MSG_REQ_REDIS_RPUSH:
+        return "RPUSH";
+    case MSG_REQ_REDIS_RPUSHX:
+        return "RPUSHX";
+    case MSG_REQ_REDIS_SADD:
+        return "SADD";
+    case MSG_REQ_REDIS_SCARD:
+        return "SCARD";
+    case MSG_REQ_REDIS_SDIFF:
+        return "SDIFF";
+    case MSG_REQ_REDIS_SDIFFSTORE:
+        return "SDIFFSTORE";
+    case MSG_REQ_REDIS_SINTER:
+        return "SINTER";
+    case MSG_REQ_REDIS_SINTERSTORE:
+        return "SINTERSTORE";
+    case MSG_REQ_REDIS_SISMEMBER:
+        return "SISMEMBER";
+    case MSG_REQ_REDIS_SMEMBERS:
+        return "SMEMBERS";
+    case MSG_REQ_REDIS_SMOVE:
+        return "SMOVE";
+    case MSG_REQ_REDIS_SPOP:
+        return "SPOP";
+    case MSG_REQ_REDIS_SRANDMEMBER:
+        return "SRANDMEMBER";
+    case MSG_REQ_REDIS_SREM:
+        return "SREM";
+    case MSG_REQ_REDIS_SUNION:
+        return "SUNION";
+    case MSG_REQ_REDIS_SUNIONSTORE:
+        return "SUNIONSTORE";
+    case MSG_REQ_REDIS_ZADD:
+        return "ZADD";
+    case MSG_REQ_REDIS_ZCARD:
+        return "ZCARD";
+    case MSG_REQ_REDIS_ZCOUNT:
+        return "ZCOUNT";
+    case MSG_REQ_REDIS_ZINCRBY:
+        return "ZINCRBY";
+    case MSG_REQ_REDIS_ZINTERSTORE:
+        return "ZINTERSTORE";
+    case MSG_REQ_REDIS_ZRANGE:
+        return "ZRANGE";
+    case MSG_REQ_REDIS_ZRANGEBYSCORE:
+        return "ZRANGEBYSCORE";
+    case MSG_REQ_REDIS_ZRANK:
+        return "ZRANK";
+    case MSG_REQ_REDIS_ZREM:
+        return "ZREM";
+    case MSG_REQ_REDIS_ZREMRANGEBYRANK:
+        return "ZREMRANGEBYRANK";
+    case MSG_REQ_REDIS_ZREMRANGEBYSCORE:
+        return "ZREMRANGEBYSCORE";
+    case MSG_REQ_REDIS_ZREVRANGE:
+        return "ZREVRANGE";
+    case MSG_REQ_REDIS_ZREVRANGEBYSCORE:
+        return "ZREVRANGEBYSCORE";
+    case MSG_REQ_REDIS_ZREVRANK:
+        return "ZREVRANK";
+    case MSG_REQ_REDIS_ZSCORE:
+        return "ZSCORE";
+    case MSG_REQ_REDIS_ZUNIONSTORE:
+        return "ZUNIONSTORE";
+    case MSG_REQ_REDIS_EVAL:
+        return "EVAL";
+    case MSG_REQ_REDIS_EVALSHA:
+        return "EVALSHA";
+    case MSG_RSP_REDIS_STATUS:
+        return "STATUS";
+    case MSG_RSP_REDIS_ERROR:
+        return "ERROR";
+    case MSG_RSP_REDIS_INTEGER:
+        return "INTEGER";
+    case MSG_RSP_REDIS_BULK:
+        return "BULK";
+    case MSG_RSP_REDIS_MULTIBULK:
+        return "MULTIBULK";
+    default:
+        return "UNKNOWN";
+    }
+}

src/nc_message.h

@@ -168,6 +168,7 @@ struct msg {
 
     struct mhdr          mhdr;            /* message mbuf header */
     uint32_t             mlen;            /* message length */
+    int64_t              start_usec;      /* request start usec*/
 
     int                  state;           /* current parser state */
     uint8_t              *pos;            /* parser position marker */
@@ -229,6 +230,7 @@ void msg_dump(struct msg *msg);
 bool msg_empty(struct msg *msg);
 rstatus_t msg_recv(struct context *ctx, struct conn *conn);
 rstatus_t msg_send(struct context *ctx, struct conn *conn);
+char * msg_type_str(msg_type_t type);
 
 struct msg *req_get(struct conn *conn);
 void req_put(struct msg *msg);

src/nc_request.c

@@ -18,6 +18,8 @@
 #include <nc_core.h>
 #include <nc_server.h>
 
+void req_notice_log(struct msg * req);
+
 struct msg *
 req_get(struct conn *conn)
 {
@@ -29,6 +31,9 @@ req_get(struct conn *conn)
     if (msg == NULL) {
         conn->err = errno;
     }
+    if (log_loggable(LOG_NOTICE) != 0){
+        msg->start_usec = nc_usec_now();
+    }
 
     return msg;
 }
@@ -40,6 +45,8 @@ req_put(struct msg *msg)
 
     ASSERT(msg->request);
 
+    req_notice_log(msg);
+
     pmsg = msg->peer;
     if (pmsg != NULL) {
         ASSERT(!pmsg->request && pmsg->peer == msg);
@@ -53,6 +60,48 @@ req_put(struct msg *msg)
     msg_put(msg);
 }
 
+void
+req_notice_log(struct msg * req){
+    struct msg *rsp;                /* peer message (response) */
+    int64_t request_time;           /*time cost for this request*/
+
+    uint32_t req_len = 0;           /* message length */
+    uint32_t rsp_len = 0;           /* message length */
+
+
+    if (log_loggable(LOG_NOTICE) == 0){
+        return;
+    }
+
+    if (req->start_usec == 0){      /*a fragment*/
+        return;
+    }
+
+    if (req->mlen == 0){            /*conn close normally*/
+        return;
+    }
+
+    rsp = req->peer;
+
+    req_len = req->mlen;
+    if(rsp){
+        rsp_len = rsp->mlen;
+    }
+
+    if (req->key_end){
+        *(req->key_end) = '\0';
+    }
+
+    request_time = nc_usec_now() - req->start_usec;
+
+    log_debug(LOG_NOTICE, "notice req %"PRIu64" done on c %d req_time: %"PRIi64".%03"PRIi64" type: %s "
+            "narg: %"PRIu32" req_len: %"PRIu32" rsp_len: %"PRIu32" "
+            "key0: %s, done: %d, error:%d",
+            req->id, req->owner->sd, request_time/1000, request_time%1000, msg_type_str(req->type),
+            req->narg, req_len, rsp_len,
+            req->key_start, req->done, req->error);
+}
+
 /*
  * Return true if request is done, false otherwise
  *