Adding stats logging to pelikan_twemcache (#213)

* make stats log related changes in twemcache

* Squashed 'deps/ccommon/' changes from f5efe29..4acc53a

4acc53a Stats to file (#186)
2168fec minimize osx build config (#185)
42b24de Simplify rust options, specify fewer output targets (#183)
c9fa905 update CMakeRust used to latest version, tweaks to make build work (#184)
2ef0163 Reorder dependency includes in cmake, don't parallel build (#182)
a6a54d9 remove endian-specific logic from str*cmp (#177)
4c0668b epoll_create* ignores size hint in newer kernels, switch to new API (#179)
c9c5ee5 improve cc_bstring string literal and cstring names (#176)
0184d73 Add unit tests for buffer, fix buf/dbuf bugs and refactor (#174)
d7dab43 create a .cargo/config so intellij uses the same target dir as cmake (#173)
e710712 use accept4 for tcp_accept when available (#171)
21ba10e Remove cargo lock for shared lib, closes #169 (#172)
24660f1 update style guide (#170)
17baf1e Per thread logging (#168)

git-subtree-dir: deps/ccommon
git-subtree-split: 4acc53a

* fix compile

* Squashed 'deps/ccommon/' changes from 4acc53a..05eb03e

05eb03e fix inconsistent naming and bump version (#187)

git-subtree-dir: deps/ccommon
git-subtree-split: 05eb03e

* Squashed 'deps/ccommon/' changes from 05eb03e..a4c0334

a4c0334 add linebreak to stats_log() (#188)

git-subtree-dir: deps/ccommon
git-subtree-split: a4c0334

* use finer grain proc time

* update metric description

deps/ccommon/CMakeLists.txt

@@ -40,7 +40,7 @@ endif()
 
 # version info
 set(${PROJECT_NAME}_VERSION_MAJOR 2)
-set(${PROJECT_NAME}_VERSION_MINOR 0)
+set(${PROJECT_NAME}_VERSION_MINOR 1)
 set(${PROJECT_NAME}_VERSION_PATCH 0)
 set(${PROJECT_NAME}_VERSION
    ${${PROJECT_NAME}_VERSION_MAJOR}.${${PROJECT_NAME}_VERSION_MINOR}.${${PROJECT_NAME}_VERSION_PATCH}

deps/ccommon/ci/before-install.sh

@@ -9,7 +9,7 @@ TEMP="$(mktemp -d -t TEMP.XXXXXXX)" || die "failed to make tmpdir"
 cleanup() { [[ -n "${TEMP:-}" ]] && rm -rf "${TEMP}"; }
 trap cleanup EXIT
 
-TOPLEVEL="$(cd "$(dirname "$(realpath "$0" >/dev/null || exit 1)")" && git rev-parse --show-toplevel)" || die 'failed to find TOPLEVEL'
+TOPLEVEL="$(git -C "$(cd "$(dirname "$0")" >/dev/null || exit 1; pwd)" rev-parse --show-toplevel)" || die 'failed to find TOPLEVEL'
 
 if [[ -n "${RUST_ENABLED:-}" ]]; then
   curl https://sh.rustup.rs -sSf | sh -s -- -y

deps/ccommon/include/cc_stats_log.h

@@ -0,0 +1,38 @@
+#pragma once
+
+#ifdef __cplusplus
+extern "C" {
+#endif
+
+#include <cc_metric.h>
+#include <cc_option.h>
+
+
+#define STATS_LOG_FILE  NULL    /* default log file */
+#define STATS_LOG_NBUF  0       /* default log buf size */
+
+/*          name            type              default           description */
+#define STATS_LOG_OPTION(ACTION)                                                         \
+    ACTION( stats_log_file, OPTION_TYPE_STR,  NULL,             "file storing stats"   )\
+    ACTION( stats_log_nbuf, OPTION_TYPE_UINT, STATS_LOG_NBUF,   "stats log buf size"   )
+
+typedef struct {
+    STATS_LOG_OPTION(OPTION_DECLARE)
+} stats_log_options_st;
+
+
+/* dump stats as CSV records into a log file, this allows metrics to be captured
+ * locally without setting up an observability infrastructure
+ */
+void stats_log_setup(stats_log_options_st *options);
+void stats_log_teardown(void);
+
+void stats_log(struct metric metrics[], unsigned int nmetric);
+
+void stats_log_flush(void);
+
+
+#ifdef __cplusplus
+}
+#endif
+

deps/ccommon/rust/cc_binding/build.rs

@@ -57,7 +57,7 @@ for (k, v) in kvs {
 }
 
 fn main() {
-    println!("cargo:rustc-link-lib=static=ccommon-2.0.0");
+    println!("cargo:rustc-link-lib=static=ccommon-2.1.0");
     if cfg!(target_os = "macos") {
         println!("cargo:rustc-link-lib=framework=Security");
     }

deps/ccommon/src/cc_debug.c

@@ -20,7 +20,6 @@
 #include <cc_log.h>
 #include <cc_mm.h>
 #include <cc_print.h>
-#include <time/cc_wheel.h>
 
 #include <ctype.h>
 #include <errno.h>

deps/ccommon/src/stats/CMakeLists.txt

@@ -1,4 +1,5 @@
 set(SOURCE
     ${SOURCE}
     stats/cc_metric.c
+    stats/cc_stats_log.c
     PARENT_SCOPE)

deps/ccommon/src/stats/cc_stats_log.c

@@ -0,0 +1,89 @@
+#include <cc_stats_log.h>
+
+#include <cc_debug.h>
+#include <cc_log.h>
+#include <cc_metric.h>
+
+#define STATS_LOG_MODULE_NAME "util::stats_log"
+#define STATS_LOG_FMT "%s: %s, "
+#define PRINT_BUF_LEN 64
+
+static struct logger *slog = NULL;
+static bool stats_log_init = false;
+
+static char buf[PRINT_BUF_LEN];
+
+
+void
+stats_log_setup(stats_log_options_st *options)
+{
+    size_t log_nbuf = STATS_LOG_NBUF;
+    char *filename = STATS_LOG_FILE;
+
+    log_info("set up the %s module", STATS_LOG_MODULE_NAME);
+
+    if (stats_log_init) {
+        log_warn("%s has already been setup, overwrite", STATS_LOG_MODULE_NAME);
+        if (slog != NULL) {
+            log_destroy(&slog);
+        }
+    }
+
+    if (options != NULL) {
+        filename = option_str(&options->stats_log_file);
+        log_nbuf = option_uint(&options->stats_log_nbuf);
+    }
+
+    if (filename != NULL) {
+        slog = log_create(filename, log_nbuf);
+        if (slog == NULL) {
+            log_warn("Could not create logger");
+        }
+    }
+
+    stats_log_init = true;
+}
+
+void
+stats_log_teardown(void)
+{
+    log_info("tear down the %s module", STATS_LOG_MODULE_NAME);
+
+    if (!stats_log_init) {
+        log_warn("%s has never been setup", STATS_LOG_MODULE_NAME);
+    }
+
+    if (slog != NULL) {
+        log_destroy(&slog);
+    }
+
+    stats_log_init = false;
+}
+
+void
+stats_log(struct metric metrics[], unsigned int nmetric)
+{
+    unsigned int i;
+
+    if (slog == NULL) {
+        return;
+    }
+
+    for (i = 0; i < nmetric; i++, metrics++) {
+        int len = 0;
+
+        len = metric_print(buf, PRINT_BUF_LEN, STATS_LOG_FMT, metrics);
+        log_write(slog, buf, len);
+    }
+    log_write(slog, CRLF, CRLF_LEN);
+}
+
+void
+stats_log_flush(void)
+{
+    if (slog == NULL) {
+        return;
+    }
+    log_flush(slog);
+}
+

src/server/twemcache/admin/process.c

@@ -6,6 +6,7 @@
 
 #include <cc_mm.h>
 #include <cc_print.h>
+#include <cc_stats_log.h>
 
 #define TWEMCACHE_ADMIN_MODULE_NAME "twemcache::admin"
 
@@ -112,3 +113,11 @@ admin_process_request(struct response *rsp, struct request *req)
         break;
     }
 }
+
+void
+stats_dump(void *arg)
+{
+    procinfo_update();
+    stats_log((struct metric *)&stats, nmetric);
+    stats_log_flush();
+}

src/server/twemcache/admin/process.h

@@ -2,3 +2,5 @@
 
 void admin_process_setup(void);
 void admin_process_teardown(void);
+
+void stats_dump(void *arg); /* compatible type: timeout_cb_fn */

src/server/twemcache/main.c

@@ -70,6 +70,7 @@ teardown(void)
     event_teardown();
     dbuf_teardown();
     buf_teardown();
+    stats_log_teardown();
 
     debug_teardown();
     log_teardown();
@@ -104,6 +105,7 @@ setup(void)
     }
 
     /* setup library modules */
+    stats_log_setup(&setting.stats_log);
     buf_setup(&setting.buf, &stats.buf);
     dbuf_setup(&setting.dbuf, &stats.dbuf);
     event_setup(&stats.event);
@@ -139,6 +141,12 @@ setup(void)
         goto error;
     }
 
+    intvl = option_uint(&setting.twemcache.stats_intvl);
+    if (core_admin_register(intvl, stats_dump, NULL) == NULL) {
+        log_error("Could not register timed event to dump stats");
+        goto error;
+    }
+
     return;
 
 error:

src/server/twemcache/setting.c

@@ -15,6 +15,7 @@ struct setting setting = {
     { BUF_OPTION(OPTION_INIT)       },
     { DBUF_OPTION(OPTION_INIT)      },
     { DEBUG_OPTION(OPTION_INIT)     },
+    { STATS_LOG_OPTION(OPTION_INIT) },
     { SOCKIO_OPTION(OPTION_INIT)    },
     { TCP_OPTION(OPTION_INIT)       },
 };

src/server/twemcache/setting.h

@@ -13,6 +13,7 @@
 #include <cc_debug.h>
 #include <cc_option.h>
 #include <cc_ring_array.h>
+#include <cc_stats_log.h>
 #include <channel/cc_tcp.h>
 #include <stream/cc_sockio.h>
 
@@ -22,7 +23,8 @@
     ACTION( daemonize,      OPTION_TYPE_BOOL,   false,  "daemonize the process"        )\
     ACTION( pid_filename,   OPTION_TYPE_STR,    NULL,   "file storing the pid"         )\
     ACTION( dlog_intvl,     OPTION_TYPE_UINT,   500,    "debug log flush interval(ms)" )\
-    ACTION( klog_intvl,     OPTION_TYPE_UINT,   100,    "cmd log flush interval(ms)"   )
+    ACTION( klog_intvl,     OPTION_TYPE_UINT,   100,    "cmd log flush interval(ms)"   )\
+    ACTION( stats_intvl,    OPTION_TYPE_UINT,   100,    "stats dump interval(ms)"      )
 
 typedef struct {
     TWEMCACHE_OPTION(OPTION_DECLARE)
@@ -46,6 +48,7 @@ struct setting {
     buf_options_st          buf;
     dbuf_options_st         dbuf;
     debug_options_st        debug;
+    stats_log_options_st    stats_log;
     sockio_options_st       sockio;
     tcp_options_st          tcp;
 };

src/util/procinfo.c

@@ -49,7 +49,7 @@ procinfo_update(void)
 
     UPDATE_VAL(procinfo_metrics, pid, getpid());
     UPDATE_VAL(procinfo_metrics, time, time_unix_sec());
-    UPDATE_VAL(procinfo_metrics, uptime, time_proc_sec());
+    UPDATE_VAL(procinfo_metrics, uptime, time_proc_ms());
 
     /* "%02d%02d%02d" % (major, minor, patch) */
     UPDATE_VAL(procinfo_metrics, version, VERSION_MAJOR * 10000 +

src/util/procinfo.h

@@ -7,7 +7,7 @@
 #define PROCINFO_METRIC(ACTION)                                         \
     ACTION( pid,            METRIC_GAUGE,   "pid of current process"   )\
     ACTION( time,           METRIC_COUNTER, "unix time in seconds"     )\
-    ACTION( uptime,         METRIC_COUNTER, "process uptime in seconds")\
+    ACTION( uptime,         METRIC_COUNTER, "process uptime in ms"     )\
     ACTION( version,        METRIC_COUNTER, "version as an int"        )\
     ACTION( ru_stime,       METRIC_FPN,     "system CPU time"          )\
     ACTION( ru_utime,       METRIC_FPN,     "user CPU time"            )\