Expirable LRU cache example is wrong

[Harris-H]

package main

import (
	"fmt"
	"time"

	"github.com/hashicorp/golang-lru/v2/expirable"
)

func main() {
	// make cache with 10ms TTL and 5 max keys
	cache := expirable.NewLRU[string, string](5, nil, time.Millisecond*10)

	// set value under key1.
	cache.Add("key1", "val1")

	// get value under key1
	r, ok := cache.Get("key1")

	// check for OK value
	if ok {
		fmt.Printf("value before expiration is found: %v, value: %q\n", ok, r)
	}

	// wait for cache to expire
	time.Sleep(time.Millisecond * 10)

	// get value under key1 after key expiration
	r, ok = cache.Get("key1")
	fmt.Printf("value after expiration is found: %v, value: %q\n", ok, r)

	// set value under key2, would evict old entry because it is already expired.
	cache.Add("key2", "val2")

	fmt.Printf("Cache len: %d\n", cache.Len())
	// Output:
	// value before expiration is found: true, value: "val1"
	// value after expiration is found: false, value: ""
	// Cache len: 1
}

The above output is:

value before expiration is found: true, value: "val1"
value after expiration is found: false, value: ""
Cache len: 2

The size of the cache is not 1, but 2, and the expired key is not deleted.

[guerinoni]

I tested and it returns

value before expiration is found: true, value: "val1"
value after expiration is found: false, value: ""
Cache len: 1

[Harris-H]

my environment is go version go1.22.10 windows/amd64. golang-lru version is v2.0.7.I just ran it again, and the output is still wrong. Is this a bug? @guerinoni

[guerinoni]

I tested on windows with latest Go version the example func ExampleLRU() { (yes example are runnable if put in test file)
Everything is work for me, can you do same test? I mean using the example function in test, not very used with windows but maybe in the recent versions something is changed about the GC for W

[Harris-H]

@guerinoni Strangely enough, when I used ExampleLRU to test it, it also didn’t work (as shown in Figure 1). When I increased time.Sleep(time.Millisecond * 1000), it also didn’t work (as shown in Figure 2). However, it worked when I increased it to time.Millisecond * 10000 (as shown in Figure 3).

[guerinoni]

Unfortunately, I don’t have access to a Windows 11 machine to investigate this further. On Linux and macOS, the behavior works as expected.
If you are open to discuss this on discord or other platform we can pair together

[chengxilo]

The problem was caused by Windows. Or you can also treat it as a problem of golang.

This link would be helpful golang/go#8687. The group of Golang are still trying to fix this problem and it is really hardcore.😵

I edit the source code(only one single line) to print the millisecond information in the ticker which delete expired cache over and over again.

My test code, the only thing I changed is that I add a time.Sleep(100 * time.Millisecond), in order to get more output.

package main

import (
   "fmt"
   "github.com/hashicorp/golang-lru/v2/expirable"
   "time"
)

func main() {
   // make cache with 10ms TTL and 5 max keys
   cache := expirable.NewLRU[string, string](5, nil, time.Millisecond*10)

   // set value under key1.
   cache.Add("key1", "val1")

   // get value under key1
   r, ok := cache.Get("key1")

   // check for OK value
   if ok {
       fmt.Printf("value before expiration is found: %v, value: %q\n", ok, r)
   }

   // wait for cache to expire
   time.Sleep(time.Millisecond * 10)

   // get value under key1 after key expiration
   r, ok = cache.Get("key1")
   fmt.Printf("value after expiration is found: %v, value: %q\n", ok, r)

   // set value under key2, would evict old entry because it is already expired.
   cache.Add("key2", "val2")

   fmt.Printf("Cache len: %d\n", cache.Len())
   // Output:
   // value before expiration is found: true, value: "val1"
   // value after expiration is found: false, value: ""
   // Cache len: 1
   time.Sleep(100 * time.Millisecond) // I add one sentence here
}

And here is the output:

If you try it too, the output might be different, but you should realized that many of the UnixMilliSecond timestamp have a difference of about 15ms or 16ms.

Hope it would be helpful.