extstore: add evictions-related write logs

"watch evictions" will show a stream of evictions + writes to extstore.
useful for analyzing the remaining ttl or key pattern of stuff being
flushed.

3 files changed, 62 insertions, 3 deletions

diff --git a/logger.c b/logger.c
index 082dceb..7af9917 100644
--- a/logger.c
+++ b/logger.c
@@ -56,6 +56,7 @@ static const entry_details default_entries[] = {
         "type=slab_move src=%d dst=%d"
     },
 #ifdef EXTSTORE
+    [LOGGER_EXTSTORE_WRITE] = {LOGGER_EXT_WRITE_ENTRY, 512, LOG_EVICTIONS, NULL},
     [LOGGER_COMPACT_START] = {LOGGER_TEXT_ENTRY, 512, LOG_SYSEVENTS,
         "type=compact_start id=%lu version=%llu"
     },
@@ -218,7 +219,21 @@ static int _logger_thread_parse_ee(logentry *e, char *scratch) {
 
     return total;
 }
+#ifdef EXTSTORE
+static int _logger_thread_parse_extw(logentry *e, char *scratch) {
+    int total;
+    char keybuf[KEY_MAX_LENGTH * 3 + 1];
+    struct logentry_ext_write *le = (struct logentry_ext_write *) e->data;
+    uriencode(le->key, keybuf, le->nkey, LOGGER_PARSE_SCRATCH);
+    total = snprintf(scratch, LOGGER_PARSE_SCRATCH,
+            "ts=%d.%d gid=%llu type=extwrite key=%s fetch=%s ttl=%lld la=%d clsid=%u bucket=%u\n",
+            (int)e->tv.tv_sec, (int)e->tv.tv_usec, (unsigned long long) e->gid,
+            keybuf, (le->it_flags & ITEM_FETCHED) ? "yes" : "no",
+            (long long int)le->exptime, le->latime, le->clsid, le->bucket);
 
+    return total;
+}
+#endif
 /* Completes rendering of log line. */
 static enum logger_parse_entry_ret logger_thread_parse_entry(logentry *e, struct logger_stats *ls,
         char *scratch, int *scratch_len) {
@@ -233,6 +248,11 @@ static enum logger_parse_entry_ret logger_thread_parse_entry(logentry *e, struct
         case LOGGER_EVICTION_ENTRY:
             total = _logger_thread_parse_ee(e, scratch);
             break;
+#ifdef EXTSTORE
+        case LOGGER_EXT_WRITE_ENTRY:
+            total = _logger_thread_parse_extw(e, scratch);
+            break;
+#endif
         case LOGGER_ITEM_GET_ENTRY:
             total = _logger_thread_parse_ige(e, scratch);
             break;
@@ -608,7 +628,23 @@ static void _logger_log_evictions(logentry *e, item *it) {
     memcpy(le->key, ITEM_key(it), it->nkey);
     e->size = sizeof(struct logentry_eviction) + le->nkey;
 }
-
+#ifdef EXTSTORE
+/* TODO: When more logging endpoints are done and the extstore API has matured
+ * more, this could be merged with above and print different types of
+ * expulsion events.
+ */
+static void _logger_log_ext_write(logentry *e, item *it, uint8_t bucket) {
+    struct logentry_ext_write *le = (struct logentry_ext_write *) e->data;
+    le->exptime = (it->exptime > 0) ? (long long int)(it->exptime - current_time) : (long long int) -1;
+    le->latime = current_time - it->time;
+    le->it_flags = it->it_flags;
+    le->nkey = it->nkey;
+    le->clsid = ITEM_clsid(it);
+    le->bucket = bucket;
+    memcpy(le->key, ITEM_key(it), it->nkey);
+    e->size = sizeof(struct logentry_ext_write) + le->nkey;
+}
+#endif
 /* 0 == nf, 1 == found. 2 == flushed. 3 == expired.
  * might be useful to store/print the flags an item has?
  * could also collapse this and above code into an "item status" struct. wait
@@ -689,6 +725,14 @@ enum logger_ret_type logger_log(logger *l, const enum log_entry_type event, cons
         case LOGGER_EVICTION_ENTRY:
             _logger_log_evictions(e, (item *)entry);
             break;
+#ifdef EXTSTORE
+        case LOGGER_EXT_WRITE_ENTRY:
+            va_start(ap, entry);
+            int ew_bucket = va_arg(ap, int);
+            va_end(ap);
+            _logger_log_ext_write(e, (item *)entry, ew_bucket);
+            break;
+#endif
         case LOGGER_ITEM_GET_ENTRY:
             va_start(ap, entry);
             int was_found = va_arg(ap, int);
diff --git a/logger.h b/logger.h
index f528327..3d4c44c 100644
--- a/logger.h
+++ b/logger.h
@@ -21,6 +21,7 @@ enum log_entry_type {
     LOGGER_CRAWLER_STATUS,
     LOGGER_SLAB_MOVE,
 #ifdef EXTSTORE
+    LOGGER_EXTSTORE_WRITE,
     LOGGER_COMPACT_START,
     LOGGER_COMPACT_ABORT,
     LOGGER_COMPACT_READ_START,
@@ -34,7 +35,10 @@ enum log_entry_subtype {
     LOGGER_TEXT_ENTRY = 0,
     LOGGER_EVICTION_ENTRY,
     LOGGER_ITEM_GET_ENTRY,
-    LOGGER_ITEM_STORE_ENTRY
+    LOGGER_ITEM_STORE_ENTRY,
+#ifdef EXTSTORE
+    LOGGER_EXT_WRITE_ENTRY,
+#endif
 };
 
 enum logger_ret_type {
@@ -65,7 +69,17 @@ struct logentry_eviction {
     uint8_t clsid;
     char key[];
 };
-
+#ifdef EXTSTORE
+struct logentry_ext_write {
+    long long int exptime;
+    uint32_t latime;
+    uint16_t it_flags;
+    uint8_t nkey;
+    uint8_t clsid;
+    uint8_t bucket;
+    char key[];
+};
+#endif
 struct logentry_item_get {
     uint8_t was_found;
     uint8_t nkey;
diff --git a/storage.c b/storage.c
index fbeb121..2f378bf 100644
--- a/storage.c
+++ b/storage.c
@@ -113,6 +113,7 @@ int lru_maintainer_store(void *storage, const int clsid) {
                 ITEM_set_cas(hdr_it, ITEM_get_cas(it));
                 do_item_remove(hdr_it);
                 did_moves = 1;
+                LOGGER_LOG(NULL, LOG_EVICTIONS, LOGGER_EXTSTORE_WRITE, it, bucket);
             } else {
                 /* Failed to write for some reason, can't continue. */
                 slabs_free(hdr_it, ITEM_ntotal(hdr_it), ITEM_clsid(hdr_it));