feat: stats and keyspace notifications about lazy expiration

src/db.c

@@ -101,6 +101,7 @@ void updateLFU(robj *val) {
 robj *lookupKey(serverDb *db, robj *key, int flags) {
     int dict_index = getKVStoreIndexForKey(key->ptr);
     robj *val = dbFindWithDictIndex(db, key->ptr, dict_index);
+    bool is_expired = false;
     if (val) {
         /* Forcing deletion of expired keys on a replica makes the replica
          * inconsistent with the primary. We forbid it on readonly replicas, but
@@ -117,6 +118,7 @@ robj *lookupKey(serverDb *db, robj *key, int flags) {
         if (expireIfNeededWithDictIndex(db, key, val, expire_flags, dict_index) != KEY_VALID) {
             /* The key is no longer valid. */
             val = NULL;
+            is_expired = true;
         }
     }
 
@@ -141,7 +143,12 @@ robj *lookupKey(serverDb *db, robj *key, int flags) {
         /* TODO: Use separate hits stats for WRITE */
     } else {
         if (!(flags & (LOOKUP_NONOTIFY | LOOKUP_WRITE))) notifyKeyspaceEvent(NOTIFY_KEY_MISS, "keymiss", key, db->id);
-        if (!(flags & (LOOKUP_NOSTATS | LOOKUP_WRITE))) server.stat_keyspace_misses++;
+        if (!(flags & (LOOKUP_NOSTATS | LOOKUP_WRITE))) {
+            server.stat_keyspace_misses++;
+            if (is_expired) {
+                server.stat_keyspace_expiration_misses++;
+            }
+        }
         /* TODO: Use separate misses stats and notify event for WRITE */
     }
 
@@ -1822,13 +1829,16 @@ long long getExpire(serverDb *db, robj *key) {
     return getExpireWithDictIndex(db, key, dict_index);
 }
 
-void deleteExpiredKeyAndPropagateWithDictIndex(serverDb *db, robj *keyobj, int dict_index) {
+void deleteExpiredKeyAndPropagateWithDictIndex(serverDb *db, robj *keyobj, int dict_index, bool lazy) {
     mstime_t expire_latency;
     latencyStartMonitor(expire_latency);
     dbGenericDeleteWithDictIndex(db, keyobj, server.lazyfree_lazy_expire, DB_FLAG_KEY_EXPIRED, dict_index);
     latencyEndMonitor(expire_latency);
     latencyAddSampleIfNeeded("expire-del", expire_latency);
     notifyKeyspaceEvent(NOTIFY_EXPIRED, "expired", keyobj, db->id);
+    if (lazy) {
+        notifyKeyspaceEvent(NOTIFY_LAZY_EXPIRED, "lazyexpired", keyobj, db->id);
+    }
     signalModifiedKey(NULL, db, keyobj);
     propagateDeletion(db, keyobj, server.lazyfree_lazy_expire);
     server.stat_expiredkeys++;
@@ -1837,7 +1847,7 @@ void deleteExpiredKeyAndPropagateWithDictIndex(serverDb *db, robj *keyobj, int d
 /* Delete the specified expired key and propagate expire. */
 void deleteExpiredKeyAndPropagate(serverDb *db, robj *keyobj) {
     int dict_index = getKVStoreIndexForKey(keyobj->ptr);
-    deleteExpiredKeyAndPropagateWithDictIndex(db, keyobj, dict_index);
+    deleteExpiredKeyAndPropagateWithDictIndex(db, keyobj, dict_index, false);
 }
 
 /* Delete the specified expired key from overwriting and propagate the DEL or UNLINK. */
@@ -1998,7 +2008,7 @@ static keyStatus expireIfNeededWithDictIndex(serverDb *db, robj *key, robj *val,
         key = createStringObject(key->ptr, sdslen(key->ptr));
     }
     /* Delete the key */
-    deleteExpiredKeyAndPropagateWithDictIndex(db, key, dict_index);
+    deleteExpiredKeyAndPropagateWithDictIndex(db, key, dict_index, true);
     if (static_key) {
         decrRefCount(key);
     }

src/notify.c

@@ -59,6 +59,7 @@ int keyspaceEventsStringToFlags(char *classes) {
         case 'm': flags |= NOTIFY_KEY_MISS; break;
         case 'd': flags |= NOTIFY_MODULE; break;
         case 'n': flags |= NOTIFY_NEW; break;
+        case 'X': flags |= NOTIFY_LAZY_EXPIRED; break;
         default: return -1;
         }
     }
@@ -91,6 +92,7 @@ sds keyspaceEventsFlagsToString(int flags) {
     if (flags & NOTIFY_KEYSPACE) res = sdscatlen(res, "K", 1);
     if (flags & NOTIFY_KEYEVENT) res = sdscatlen(res, "E", 1);
     if (flags & NOTIFY_KEY_MISS) res = sdscatlen(res, "m", 1);
+    if (flags & NOTIFY_LAZY_EXPIRED) res = sdscatlen(res, "X", 1);
     return res;
 }
 

src/server.c

@@ -2649,6 +2649,7 @@ void resetServerStats(void) {
     server.stat_total_eviction_exceeded_time = 0;
     server.stat_last_eviction_exceeded_time = 0;
     server.stat_keyspace_misses = 0;
+    server.stat_keyspace_expiration_misses = 0;
     server.stat_keyspace_hits = 0;
     server.stat_active_defrag_hits = 0;
     server.stat_active_defrag_misses = 0;
@@ -5930,6 +5931,7 @@ sds genValkeyInfoString(dict *section_dict, int all_sections, int everything) {
                 "current_eviction_exceeded_time:%lld\r\n", current_eviction_exceeded_time / 1000,
                 "keyspace_hits:%lld\r\n", server.stat_keyspace_hits,
                 "keyspace_misses:%lld\r\n", server.stat_keyspace_misses,
+                "keyspace_expiration_misses:%lld\r\n", server.stat_keyspace_expiration_misses,
                 "pubsub_channels:%llu\r\n", kvstoreSize(server.pubsub_channels),
                 "pubsub_patterns:%lu\r\n", dictSize(server.pubsub_patterns),
                 "pubsubshard_channels:%llu\r\n", kvstoreSize(server.pubsubshard_channels),

src/server.h

@@ -632,6 +632,7 @@ typedef enum {
 #define NOTIFY_LOADED (1 << 12)   /* module only key space notification, indicate a key loaded from rdb */
 #define NOTIFY_MODULE (1 << 13)   /* d, module key space notification */
 #define NOTIFY_NEW (1 << 14)      /* n, new key notification */
+#define NOTIFY_LAZY_EXPIRED (1 << 15) /* X, lazy expire key notification */
 #define NOTIFY_ALL                                                                                            \
     (NOTIFY_GENERIC | NOTIFY_STRING | NOTIFY_LIST | NOTIFY_SET | NOTIFY_HASH | NOTIFY_ZSET | NOTIFY_EXPIRED | \
      NOTIFY_EVICTED | NOTIFY_STREAM | NOTIFY_MODULE) /* A flag */
@@ -1670,6 +1671,7 @@ struct valkeyServer {
     monotime stat_last_eviction_exceeded_time;     /* Timestamp of current eviction start, unit us */
     long long stat_keyspace_hits;                  /* Number of successful lookups of keys */
     long long stat_keyspace_misses;                /* Number of failed lookups of keys */
+    long long stat_keyspace_expiration_misses;     /* Number of failed lookups of keys due to expiration */
     long long stat_active_defrag_hits;             /* number of allocations moved */
     long long stat_active_defrag_misses;           /* number of allocations scanned but not moved */
     long long stat_active_defrag_key_hits;         /* number of keys with moved allocations */

tests/unit/info.tcl

@@ -504,6 +504,37 @@ start_server {tags {"info" "external:skip" "debug_defrag:skip"}} {
             $r2 close
             wait_for_watched_clients_count 0
         }
+
+        test {stats: keyspace misses} {
+            # disable active expire cycle
+            r debug set-active-expire 0
+
+            # clear stats before test
+            r config resetstat
+
+            # test keyspace misses
+            r set k1 "v1" PX 1
+
+            # before expiration, k1 is in db
+            set before [r info stats]
+
+            # wait for key to expire
+            after 100
+
+            # after expiration, k1 is not in db
+            r get k1
+            r get k2
+            set after [r info stats]
+
+            # check keyspace misses
+            assert_equal [getInfoProperty $before keyspace_misses] 0
+            assert_equal [getInfoProperty $before keyspace_expiration_misses] 0
+            assert_equal [getInfoProperty $after keyspace_misses] 2
+            assert_equal [getInfoProperty $after keyspace_expiration_misses] 1
+
+            # rollback active expire cycle
+            r debug set-active-expire 1
+        }
     }
 }
 

tests/unit/pubsub.tcl

@@ -436,6 +436,48 @@ start_server {tags {"pubsub network"}} {
         $rd1 close
     }
 
+    test "Keyspace notifications: lazy expired events" {
+        # disable active expire
+        r debug set-active-expire 0
+        r config set notify-keyspace-events KEX
+        r del foo
+        set rd1 [valkey_deferring_client]
+        assert_equal {1} [psubscribe $rd1 *]
+        r set foo bar PX 1
+        wait_for_condition 50 100 {
+            [r exists foo] == 0
+        } else {
+            fail "Key does not lazy expire?!"
+        }
+        assert_equal "pmessage * __keyspace@${db}__:foo lazyexpired" [$rd1 read]
+        assert_equal "pmessage * __keyevent@${db}__:lazyexpired foo" [$rd1 read]
+        $rd1 close
+        # enable active expire
+        r debug set-active-expire 1
+    }
+
+    test "Keyspace notifications: expired and lazy expired events" {
+        # disable active expire
+        r debug set-active-expire 0
+        r config set notify-keyspace-events KEXx
+        r del foo
+        set rd1 [valkey_deferring_client]
+        assert_equal {1} [psubscribe $rd1 *]
+        r set foo bar PX 1
+        wait_for_condition 50 100 {
+            [r exists foo] == 0
+        } else {
+            fail "Key does not lazy expire?!"
+        }
+        assert_equal "pmessage * __keyspace@${db}__:foo expired" [$rd1 read]
+        assert_equal "pmessage * __keyevent@${db}__:expired foo" [$rd1 read]
+        assert_equal "pmessage * __keyspace@${db}__:foo lazyexpired" [$rd1 read]
+        assert_equal "pmessage * __keyevent@${db}__:lazyexpired foo" [$rd1 read]
+        $rd1 close
+        # enable active expire
+        r debug set-active-expire 1
+    }
+
     test "Keyspace notifications: evicted events" {
         r config set notify-keyspace-events Ee
         r config set maxmemory-policy allkeys-lru