FOUR-20954: Monitor ETag Caching Performance

ProcessMaker/Http/Middleware/Etag/HandleEtag.php

@@ -4,6 +4,8 @@
 
 use Closure;
 use Illuminate\Http\Request;
+use Illuminate\Support\Facades\Cache;
+use Illuminate\Support\Facades\Log;
 use ProcessMaker\Http\Resources\Caching\EtagManager;
 use Symfony\Component\HttpFoundation\Response;
 
@@ -16,6 +18,10 @@ class HandleEtag
      */
     public function handle(Request $request, Closure $next): Response
     {
+        if (!config('etag.enabled')) {
+            return $next($request);
+        }
+
         // Process only GET and HEAD methods.
         if (!$request->isMethod('GET') && !$request->isMethod('HEAD')) {
             return $next($request);
@@ -48,6 +54,9 @@ public function handle(Request $request, Closure $next): Response
             }
         }
 
+        // Detect if the ETag changes frequently for dynamic responses.
+        $this->logEtagChanges($request, $etag);
+
         return $response;
     }
 
@@ -113,4 +122,48 @@ private function stripWeakTags(string $etag): string
     {
         return str_replace('W/', '', $etag);
     }
+
+    /**
+     * Log ETag changes to detect highly dynamic responses.
+     */
+    private function logEtagChanges(Request $request, ?string $etag): void
+    {
+        if (!config('etag.enabled') || !config('etag.log_dynamic_endpoints')) {
+            return;
+        }
+
+        if (!$etag) {
+            return;
+        }
+
+        // Retrieve the history of ETags for this endpoint.
+        $url = $request->fullUrl();
+        $cacheKey = 'etag_history:' . md5($url);
+        $etagHistory = Cache::get($cacheKey, []);
+
+        // If the ETag is already in the history, it is not considered dynamic.
+        if (in_array($etag, $etagHistory, true)) {
+            return;
+        }
+
+        // Add the new ETag to the history.
+        $etagHistory[] = $etag;
+
+        // Keep the history limited to the last n ETags.
+        $etagHistoryLimit = config('etag.history_limit', 10);
+        if (count($etagHistory) > $etagHistoryLimit) {
+            array_shift($etagHistory); // Remove the oldest ETag.
+        }
+
+        // Save the updated history in the cache, valid for 30 minutes.
+        $cacheExpirationMinute = config('etag.history_cache_expiration');
+        Cache::put($cacheKey, $etagHistory, now()->addMinutes($cacheExpirationMinute));
+
+        // If the history is full and all ETags are unique, log this as a highly dynamic endpoint.
+        if (count(array_unique($etagHistory)) === $etagHistoryLimit) {
+            Log::info('ETag Dynamic endpoint detected', [
+                'url' => $url,
+            ]);
+        }
+    }
 }

config/etag.php

@@ -0,0 +1,47 @@
+<?php
+
+return [
+    /*
+    |--------------------------------------------------------------------------
+    | Enable or Disable ETag Logging
+    |--------------------------------------------------------------------------
+    |
+    | This option allows you to enable or disable the ETag change logging
+    | feature.
+    |
+    */
+    'enabled' => env('ETAG_ENABLED', true),
+
+    /*
+    |--------------------------------------------------------------------------
+    | Log Dynamic Endpoints
+    |--------------------------------------------------------------------------
+    |
+    | Enable or disable logging when an endpoint is detected as dynamic.
+    | If set to false, no logs will be recorded for dynamic endpoints.
+    |
+    */
+    'log_dynamic_endpoints' => env('ETAG_LOG_DYNAMIC_ENDPOINTS', false),
+
+    /*
+    |--------------------------------------------------------------------------
+    | ETag History Limit
+    |--------------------------------------------------------------------------
+    |
+    | The maximum number of ETags to track per endpoint. If the number of
+    | unique ETags exceeds this limit, the oldest ETag will be removed.
+    |
+    */
+    'history_limit' => env('ETAG_HISTORY_LIMIT', 10),
+
+    /*
+    |--------------------------------------------------------------------------
+    | History Cache Expiration Time
+    |--------------------------------------------------------------------------
+    |
+    | The duration (in minutes) for which the ETag history should be stored
+    | in the cache. Adjust this based on your caching strategy.
+    |
+    */
+    'history_cache_expiration' => env('ETAG_HISTORY_CACHE_EXPIRATION_MINUTES', 30),
+];

docs/etag-caching.md

@@ -100,6 +100,35 @@ In this example:
 - Middleware generates the ETag based on the last update of the `processes` table.
 - If the client has the corresponding ETag, the server responds with `304 Not Modified` and does not execute the controller logic.
 
+## Config file
+
+The ETag functionality is managed through the `config/etag.php` file, which centralizes all related settings. This configuration file allows you to enable or disable ETag logging and caching, as well as customize key parameters such as history limits and cache expiration times.
+
+### Key Options
+- **`enabled`**: Determines whether the ETag functionality is active. If set to `false`, all ETag-related processing is skipped.
+- **`log_dynamic_endpoints`**: Controls whether dynamic endpoints are logged. When disabled, no cache processing occurs.
+- **`history_limit`**: Specifies the maximum number of ETags to track per endpoint.
+- **`cache_expiration`**: Sets the duration (in minutes) for which the ETag history is cached.
+
+## Logs
+
+This middleware detects **highly dynamic endpoints** by tracking the history of ETags generated for each endpoint. It helps identify endpoints where ETags are consistently different, indicating dynamic responses that may require further optimization.
+
+1. Tracks the last **N ETags** (default: 10) for each endpoint using Laravel's cache.
+2. Logs endpoints as "highly dynamic" if all tracked ETags are unique.
+3. Efficient caching and memory usage to minimize performance overhead.
+
+### Example Logs
+
+When an endpoint is identified as highly dynamic, the following log is generated:
+
+```
+ETag Dynamic endpoint detected:
+{
+  "url": "https://example.com/api/resource",
+}
+```
+
 ## Testing
 
 ### Unit Tests
@@ -135,9 +164,7 @@ This implementation leverages ETags to optimize `GET` requests in the API, reduc
 1. **ETag Versioning with Cache**:
    - Store ETag versions in cache to avoid database queries.
    - Enable manual invalidation via model events.
-2. **Configuration File**:
-   - Add a `config/etag.php` for global middleware control.
-3. **Metrics Collection**:
+2. **Metrics Collection**:
    - Monitor request duration, `304` response percentage and bandwidth savings.
 
 This solution is well-suited for global optimizations and specific dynamic routes.

tests/k6/etag/config.js

@@ -0,0 +1,11 @@
+export const config = {
+  token: 'FAKE_JWT', // Replace with a valid token.
+  endpoints: {
+    startProcesses: 'https://processmaker.test/api/1.0/start_processes?page=1&per_page=15&filter=&order_by=category.name%2Cname&order_direction=asc%2Casc&include=events%2Ccategories&without_event_definitions=true',
+  },
+};
+
+export const headers = {
+  'Content-Type': 'application/json',
+  Authorization: `Bearer ${config.token}`,
+};

tests/k6/etag/detect-dynamic-endpoints.js

@@ -0,0 +1,57 @@
+import http from 'k6/http';
+import { config, headers } from './config.js';
+
+export let options = {
+  vus: 1,
+  iterations: 5, // n iterations per URL.
+};
+
+const endpoints = [
+  config.endpoints.startProcesses,
+];
+
+// Object to track ETag history for each endpoint.
+const etagHistory = {};
+
+// Limit to determine when an endpoint is considered dynamic.
+const ETAG_HISTORY_LIMIT = 5;
+
+export default function () {
+  endpoints.forEach((url) => {
+    const res1 = http.get(url, { headers });
+    const etag = res1.headers['Etag'];
+
+    // If no ETag is present, log a warning and skip further processing.
+    if (!etag) {
+      console.log(`No ETag found for ${url}`);
+      return;
+    }
+
+    // Log the ETag value for debugging.
+    console.log(`ETag: ${etag}`);
+
+    // Initialize the ETag history for this endpoint if not already present.
+    if (!etagHistory[url]) {
+      etagHistory[url] = [];
+    }
+
+    // Add the ETag to the history if it is unique.
+    if (!etagHistory[url].includes(etag)) {
+      etagHistory[url].push(etag);
+    }
+
+    // Keep the history limited to the last N ETags.
+    if (etagHistory[url].length > ETAG_HISTORY_LIMIT) {
+      etagHistory[url].shift(); // Remove the oldest ETag
+    }
+
+    // Check if the endpoint is dynamic.
+    // If the history is full and all ETags are unique, the endpoint is considered dynamic.
+    if (
+      etagHistory[url].length === ETAG_HISTORY_LIMIT &&
+      new Set(etagHistory[url]).size === ETAG_HISTORY_LIMIT
+    ) {
+      console.log(`Dynamic endpoint detected: ${url}`);
+    }
+  });
+}

tests/k6/etag/long-duration-test.js

@@ -0,0 +1,43 @@
+import http from 'k6/http';
+import { check, sleep } from 'k6';
+import { Trend } from 'k6/metrics';
+import { config, headers } from './config.js';
+
+// Metrics to track response durations.
+let duration200 = new Trend('duration_200');
+let duration304 = new Trend('duration_304');
+
+export let options = {
+  stages: [
+    { duration: '5m', target: 50 }, // Hold 50 VUs for 5 minutes.
+  ],
+  thresholds: {
+    http_req_duration: ['p(95)<1000'], // 95% of requests should respond in < 1s.
+    duration_200: ['avg<800'], // Ensure 200 OK average duration is < 800ms.
+    duration_304: ['avg<400'], // Ensure 304 Not Modified avg duration is < 400ms.
+  },
+};
+
+export default function () {
+  const url = config.endpoints.startProcesses;
+  let res = http.get(url, { headers });
+  duration200.add(res.timings.duration);
+  check(res, {
+    'status is 200': (r) => r.status === 200,
+    'ETag exists': (r) => !!r.headers.Etag,
+  });
+
+  const etag = res.headers.Etag;
+  if (etag) {
+    const conditionalHeaders = { ...headers, 'If-None-Match': etag };
+
+    let conditionalRes = http.get(url, { headers: conditionalHeaders });
+    duration304.add(conditionalRes.timings.duration);
+
+    check(conditionalRes, {
+      'status is 304': (r) => r.status === 304,
+    });
+  }
+
+  sleep(1);
+}

tests/k6/etag/performance-test.js

@@ -0,0 +1,46 @@
+import http from 'k6/http';
+import { check, sleep, group } from 'k6';
+import { Trend } from 'k6/metrics';
+import { config, headers } from './config.js';
+
+// Custom metrics to track request durations.
+let duration200 = new Trend('duration_200');
+let duration304 = new Trend('duration_304');
+
+export let options = {
+  stages: [
+    { duration: '10s', target: 10 },
+    { duration: '20s', target: 50 },
+    { duration: '10s', target: 0 },
+  ],
+};
+
+export default function () {
+  const baseUrl = config.endpoints.startProcesses;
+  group('ETag Performance', () => {
+    // Add the duration of the 200 response to the custom metric.
+    let res = http.get(baseUrl, { headers });
+    duration200.add(res.timings.duration);
+    check(res, {
+      'status is 200': (r) => r.status === 200,
+    });
+
+    // Use ETag with If-None-Match header to validate 304 response.
+    const etag = res.headers.Etag;
+    if (etag) {
+      const conditionalHeaders = {
+        ...headers,
+        'If-None-Match': etag,
+      };
+
+      // Add the duration of the 304 response to the custom metric
+      let conditionalRes = http.get(baseUrl, { headers: conditionalHeaders });
+      duration304.add(conditionalRes.timings.duration);
+      check(conditionalRes, {
+        'status is 304': (r) => r.status === 304,
+      });
+    }
+
+    sleep(1);
+  });
+}