Delayed deletion of entries in expirable cache

[akshaynotes]

I was going through the code to understand the expirable cache implemention, where I found time.Ticker is being used (and a separated go routine, which ticks at ttl/100(no of buckets), to delete the expired entries). I was experimenting a scenario where my cache size would be around the 100 (no of buckets). I added a few logs to check addition and deletion timings, I also changed the bucket size to 5. Below is the POC code I used

func main() {
	cache := expirable.NewLRU[string, string](5, nil, time.Second*120)

	time.Sleep(time.Second * 9)
	cache.Add("key1", "val1")

	time.Sleep(time.Second * 9)
	cache.Add("key2", "val2")

	time.Sleep(time.Second * 9)
	cache.Add("key3", "val3")

	time.Sleep(time.Second * 33)

	time.Sleep(time.Second * 9)
	cache.Add("afterkey4", "aftervalue4")

	time.Sleep(time.Second * 9)
	cache.Add("afterkey5", "aftervalue5")

	time.Sleep(time.Second * 9)
	cache.Add("afterkey6", "aftervalue6")

	// wait for cache to expire
	time.Sleep(time.Second * 160)
	
}

Logs -

Added key key1 in Bucketid 4 at 2023-11-05 18:57:39.0832155 +0530 IST m=+9.024316801, This bucket newest entry is 2023-11-05 18:59:39.0832155 +0530 IST m=+129.024316801
Added key key2 in Bucketid 4 at 2023-11-05 18:57:48.1015164 +0530 IST m=+18.042617701, This bucket newest entry is 2023-11-05 18:59:48.1015164 +0530 IST m=+138.042617701
Added key key3 in Bucketid 0 at 2023-11-05 18:57:57.1092536 +0530 IST m=+27.050354901, This bucket newest entry is 2023-11-05 18:59:57.1092536 +0530 IST m=+147.050354901
Added key afterkey4 in Bucketid 1 at 2023-11-05 18:58:39.1157705 +0530 IST m=+69.056871801, This bucket newest entry is 2023-11-05 19:00:39.1157705 +0530 IST m=+189.056871801
Added key afterkey5 in Bucketid 2 at 2023-11-05 18:58:48.129953 +0530 IST m=+78.071054301, This bucket newest entry is 2023-11-05 19:00:48.129953 +0530 IST m=+198.071054301
Added key afterkey6 in Bucketid 2 at 2023-11-05 18:58:57.1432401 +0530 IST m=+87.084341401, This bucket newest entry is 2023-11-05 19:00:57.1432401 +0530 IST m=+207.084341401
Removing key key1 at 2023-11-05 18:58:57.1432401 +0530 IST m=+87.084341401
Deleting expired key at 2023-11-05 18:59:48.1116508 +0530 IST m=+138.052752101, Entry &{next:0xc00005a0c0 prev:0xc00005a2a0 list:0xc00005a0c0 Key:key2 Value:val2 ExpiresAt:2023-11-05 18:59:48.1015164 +0530 IST m=+138.042617701 ExpireBucket:4}, Bucket id 4
Removing key key2 at 2023-11-05 18:59:48.1124826 +0530 IST m=+138.053583901
Deleting expired key at 2023-11-05 18:59:57.1245726 +0530 IST m=+147.065673901, Entry &{next:0xc00005a0c0 prev:0xc000182000 list:0xc00005a0c0 Key:key3 Value:val3 ExpiresAt:2023-11-05 18:59:57.1092536 +0530 IST m=+147.050354901 ExpireBucket:0}, Bucket id 0
Removing key key3 at 2023-11-05 18:59:57.1252004 +0530 IST m=+147.066301701
Deleting expired key at 2023-11-05 19:00:39.1266393 +0530 IST m=+189.067740601, Entry &{next:0xc00005a0c0 prev:0xc00005a300 list:0xc00005a0c0 Key:afterkey4 Value:aftervalue4 ExpiresAt:2023-11-05 19:00:39.1157705 +0530 IST m=+189.056871801 ExpireBucket:1}, Bucket id 1
Removing key afterkey4 at 2023-11-05 19:00:39.1274337 +0530 IST m=+189.068535001
Deleting expired key at 2023-11-05 19:00:57.1442633 +0530 IST m=+207.085364601, Entry &{next:0xc00005a300 prev:0xc00005a0c0 list:0xc00005a0c0 Key:afterkey6 Value:aftervalue6 ExpiresAt:2023-11-05 19:00:57.1432401 +0530 IST m=+207.084341401 ExpireBucket:2}, Bucket id 2
Removing key afterkey6 at 2023-11-05 19:00:57.1451372 +0530 IST m=+207.086238501
Deleting expired key at 2023-11-05 19:00:57.1457121 +0530 IST m=+207.086813401, Entry &{next:0xc00005a0c0 prev:0xc00005a0c0 list:0xc00005a0c0 Key:afterkey5 Value:aftervalue5 ExpiresAt:2023-11-05 19:00:48.129953 +0530 IST m=+198.071054301 ExpireBucket:2}, Bucket id 2
Removing key afterkey5 at 2023-11-05 19:00:57.1457121 +0530 IST m=+207.086813401

Observation-
I observed delayed deletion because in the bucket with id -2 we have two keys <key, expected deletion time> i.e [afterkey5, 19:00:48.129953] and [afterkey6, 19:00:57.1432401]. When I looked at the code golang-lru update the newestEntry (if the bucket id is same) to the furthest (late time) time, which will cause the entries which has earlier expireAt time to delete little bit later. In above case afterkey5 was supposed to delete at 19:00:48 but got deleted at 19:00:57 although delay here 9 seconds. The delay can increase if TTL is in hours.

Not sure about below calcualtion, correct me if I am wrong
multiple entries can be in the same bucket if time.Ticker hasn't been ticked
e.g if TTL is 120 minutes, ticker will tick at every 12 minutes, entry expiring at 19:00 and entry expiring at 19:12 can be in the same bucket and it would cause a max delay of 12 minutes
Also one more question, can it happen - two entries having a difference of expiresAt between them more than 12 minutes to be in the same bucket?

[paskal]

multiple entries can be in the same bucket if time.Ticker hasn't been ticked
Correct, that's the tradeoff I had to make to verify that we expire entries after their expiration time. Initial implementation had a chance to expire entries up to TTL/100 (e.g. 1% of TTL) earlier, but the maintainers of the package told me that it would be unexpected even if documented.

can it happen - two entries having a difference of expiresAt between them more than 12 minutes to be in the same bucket?
It can. Plus/minus a few seconds, I would say.