search

caching-tools / next-shared-cache

Next.js self-hosting simplified
https://caching-tools.github.io/next-shared-cache/
MIT License
333 stars 24 forks source link

Redis handler should memoize keys during same request #785

Open fabn opened 1 month ago

fabn commented 1 month ago

Brief Description of the Bug

Redis client is queried multiple times during same request for the same key.

Severity Major: in some circumstances it does a lot of network calls for a single page render.

Frequency of Occurrence

Always

Steps to Reproduce

I don't know exactly what pattern lead to this situation, I guess is something related to next internals and http request deduplication, but we noticed in some pages that same key is fetched multiple times during the same request. We confirmed this both using Newrelic instrumentation in production, but also locally by adding NEXT_PRIVATE_DEBUG_CACHE=1 to our env file.

If you have a page that perform the same fetch multiple times we see this log messages:

using custom cache handler @neshca/cache-handler with 1 Handler
[CacheHandler] Instance created with provided context.
using custom cache handler @neshca/cache-handler with 1 Handler
[CacheHandler] Instance created with provided context.
using custom cache handler @neshca/cache-handler with 1 Handler
[CacheHandler] Instance created with provided context.
[CacheHandler] Using existing CacheHandler configuration.
[CacheHandler] Using existing CacheHandler configuration.
[CacheHandler] [method: get] [key: 5bc890dc536dbaf76c60b31a135230f2bc32d0024e2091afe6e4b8ee0c9ca84f] Started retrieving value in order.
[CacheHandler] [handler: redis-strings] [method: get] [key: 5bc890dc536dbaf76c60b31a135230f2bc32d0024e2091afe6e4b8ee0c9ca84f] Started retrieving value.
[CacheHandler] [method: get] [key: 062478d0481d927e1f29cdf3afa778a2b4b2e7f1b6819adbe107039b1de016d6] Started retrieving value in order.
[CacheHandler] [handler: redis-strings] [method: get] [key: 062478d0481d927e1f29cdf3afa778a2b4b2e7f1b6819adbe107039b1de016d6] Started retrieving value.
[CacheHandler] Using existing CacheHandler configuration.
[CacheHandler] Using existing CacheHandler configuration.
[CacheHandler] [method: get] [key: 5bc890dc536dbaf76c60b31a135230f2bc32d0024e2091afe6e4b8ee0c9ca84f] Started retrieving value in order.
[CacheHandler] [handler: redis-strings] [method: get] [key: 5bc890dc536dbaf76c60b31a135230f2bc32d0024e2091afe6e4b8ee0c9ca84f] Started retrieving value.
[CacheHandler] [method: get] [key: 062478d0481d927e1f29cdf3afa778a2b4b2e7f1b6819adbe107039b1de016d6] Started retrieving value in order.
[CacheHandler] [handler: redis-strings] [method: get] [key: 062478d0481d927e1f29cdf3afa778a2b4b2e7f1b6819adbe107039b1de016d6] Started retrieving value.
[CacheHandler] [handler: redis-strings] [method: get] [key: 5bc890dc536dbaf76c60b31a135230f2bc32d0024e2091afe6e4b8ee0c9ca84f] Successfully retrieved value.
[CacheHandler] [handler: redis-strings] [method: get] [key: 062478d0481d927e1f29cdf3afa778a2b4b2e7f1b6819adbe107039b1de016d6] Successfully retrieved value.
[CacheHandler] [handler: redis-strings] [method: get] [key: 5bc890dc536dbaf76c60b31a135230f2bc32d0024e2091afe6e4b8ee0c9ca84f] Successfully retrieved value.
[CacheHandler] [handler: redis-strings] [method: get] [key: 062478d0481d927e1f29cdf3afa778a2b4b2e7f1b6819adbe107039b1de016d6] Successfully retrieved value.
[CacheHandler] Using existing CacheHandler configuration.
[CacheHandler] Using existing CacheHandler configuration.
[CacheHandler] [method: get] [key: 5bc890dc536dbaf76c60b31a135230f2bc32d0024e2091afe6e4b8ee0c9ca84f] Started retrieving value in order.
[CacheHandler] [handler: redis-strings] [method: get] [key: 5bc890dc536dbaf76c60b31a135230f2bc32d0024e2091afe6e4b8ee0c9ca84f] Started retrieving value.
[CacheHandler] [method: get] [key: 5bc890dc536dbaf76c60b31a135230f2bc32d0024e2091afe6e4b8ee0c9ca84f] Started retrieving value in order.
[CacheHandler] [handler: redis-strings] [method: get] [key: 5bc890dc536dbaf76c60b31a135230f2bc32d0024e2091afe6e4b8ee0c9ca84f] Started retrieving value.
[CacheHandler] [handler: redis-strings] [method: get] [key: 5bc890dc536dbaf76c60b31a135230f2bc32d0024e2091afe6e4b8ee0c9ca84f] Successfully retrieved value.
[CacheHandler] [handler: redis-strings] [method: get] [key: 5bc890dc536dbaf76c60b31a135230f2bc32d0024e2091afe6e4b8ee0c9ca84f] Successfully retrieved value.

Same pattern can be observed by keeping a redis-cli monitor terminal open (operations performed during the same request)

1727775826.330784 [0 [::1]:62136] "GET" "development:5bc890dc536dbaf76c60b31a135230f2bc32d0024e2091afe6e4b8ee0c9ca84f"
1727775826.330886 [0 [::1]:62136] "GET" "development:062478d0481d927e1f29cdf3afa778a2b4b2e7f1b6819adbe107039b1de016d6"
1727775826.330933 [0 [::1]:62136] "GET" "development:5bc890dc536dbaf76c60b31a135230f2bc32d0024e2091afe6e4b8ee0c9ca84f"
1727775826.330967 [0 [::1]:62136] "GET" "development:062478d0481d927e1f29cdf3afa778a2b4b2e7f1b6819adbe107039b1de016d6"
1727775826.333293 [0 [::1]:62136] "HMGET" "development:__revalidated_tags__" "_N_T_/layout" "_N_T_/_not-found/layout" "_N_T_/blog/wp-json/wp/v2/posts"
1727775826.333327 [0 [::1]:62136] "HMGET" "development:__revalidated_tags__" "_N_T_/layout" "_N_T_/_not-found/layout" "_N_T_/blog/wp-json/wp/v2/posts"
1727775826.333344 [0 [::1]:62136] "HMGET" "development:__revalidated_tags__" "_N_T_/layout" "_N_T_/_not-found/layout" "_N_T_/blog/wp-json/wp/v2/categories"
1727775826.333367 [0 [::1]:62136] "HMGET" "development:__revalidated_tags__" "_N_T_/layout" "_N_T_/_not-found/layout" "_N_T_/blog/wp-json/wp/v2/categories"
1727775826.337012 [0 [::1]:62136] "GET" "development:5bc890dc536dbaf76c60b31a135230f2bc32d0024e2091afe6e4b8ee0c9ca84f"
1727775826.337133 [0 [::1]:62136] "GET" "development:5bc890dc536dbaf76c60b31a135230f2bc32d0024e2091afe6e4b8ee0c9ca84f"
1727775826.361671 [0 [::1]:62136] "HMGET" "development:__revalidated_tags__" "_N_T_/layout" "_N_T_/_not-found/layout" "_N_T_/blog/wp-json/wp/v2/posts"
1727775826.361689 [0 [::1]:62136] "HMGET" "development:__revalidated_tags__" "_N_T_/layout" "_N_T_/_not-found/layout" "_N_T_/blog/wp-json/wp/v2/categories"

Expected vs. Actual Behavior

I expect a single GET in redis for each involved key during same request. In this transcript we have 2 different keys:

Screenshots/Logs

Already attached.

Environment:

Attempted Solutions or Workarounds

I guess an easy solution could be to store a const map = {} within the client instance and whenever a key is retrieved from redis store it also there, on subsequent requests check in the map before redis, but is just an idea.

Impact of the Bug

According to newrelic for some pages (that reuses same fetch in various parts) we're spending ~60ms in redis GET calls, while a single one (~4ms) should be enough to render the page.

Additional context

I also see that redis handler is instantiated multiple times, so we're paying the connect time lot of times, but I guess this is Next.js fault, and you cannot avoid it. It would be super nice to have redis client as singleton instance but I don't know if it's possible.

tilman commented 2 weeks ago

I have also observed this in our setup and could reproduce it locally with a single node-server instance of our nextjs app. For some pages I even observed 50times requesting of the same key. Here an example:

➜ redis-cli -h localhost monitor | grep 79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502
1730893951.510511 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893951.521628 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893951.522081 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893951.522512 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893951.588988 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893951.599978 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893951.640880 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893951.657484 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893951.681665 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893951.778738 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893951.785540 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893951.785641 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893951.786208 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893951.788751 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893951.795035 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893951.844404 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893951.844590 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893951.844776 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893951.845118 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893951.845535 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893951.902778 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893951.902932 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893951.903294 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893951.903629 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893951.983431 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893951.983546 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893951.983626 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893952.043903 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893952.128533 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893952.128629 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893952.128721 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893952.282175 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893952.311405 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893952.311464 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"
1730893952.311510 [0 192.168.65.1:32033] "GET" "UNDEFINED_URL_79a20c85aca8284a05a64d8d6b57e9e4845407c22e4e65c9ae290bb07e2ac502"

Seems like nextjs request deduplication is not working all the time.

tilman commented 2 weeks ago

As a workaround I have wrapped my fetch calls in a custom dedupe function. May it helps you as well:

type AnyFunction = (...args: any[]) => Promise<any>;

export function deduplicateRequests<T extends AnyFunction>(fn: T): T {
  // Map to store the currently pending promises by their argument stringified key
  const pendingRequests = new Map<string, Promise<any>>();
  const pendingRequestsCounter = new Map<string, number>();

  return async function (...args: Parameters<T>): Promise<ReturnType<T>> {
    const key = JSON.stringify(args); // Stringify arguments to use as a cache key

    // If there's already a pending request with the same key, return it
    if (pendingRequests.has(key)) {
      const c = pendingRequestsCounter.get(key)! + 1;
      pendingRequestsCounter.set(key, c);

      console.debug(args?.[3], "dedupe position " + c);
      return pendingRequests.get(key)!.then(structuredClone);
    }

    // If no pending request, call the original function and store the promise
    const promise = fn(...args);
    pendingRequests.set(key, promise);
    pendingRequestsCounter.set(key, 1);

    console.debug(args?.[3], "deduping request");

    try {
      // Await the promise and return the result
      const result = await promise;
      return structuredClone(result);
    } finally {
      // Once the promise is resolved/rejected, remove it from the map
      pendingRequests.delete(key);
      pendingRequestsCounter.delete(key);
    }
  } as T;
}

To use it create a deduped instance of any function. For example fetch: export const fetchDeduped = deduplicateRequests(fetch);