fix: Heap usage request throttling (#1450)

bmingles · web-flow · commit 5cc2936332a9 · 2023-08-25T11:02:57.000-04:00
fixes #1439 - Heap usage code now guarantees that new requests won't be scheduled until all previous requests are complete. ## Testing I tested by shutting my Mac for ~2 hours and returning. Timings looks something like this: ### Summary <img width="310" alt="image" src="https://github.com/deephaven/web-client-ui/assets/1900643/0ad2d426-2fed-48e8-a255-989ee5d524f3"> It seems that requests still happen occasionally while sleeping. On Wake up, there were a few ticks resulting in "Unable to get heap usage" console errors. Then a prompt showed up indicating credentials had expired at which point requests start succeeding again. ### Full Console Log ``` useAsyncInterval.ts:37 [useAsyncInterval] tick #1. 10068 ms elapsed since last tick. useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 9918 useAsyncInterval.ts:37 [useAsyncInterval] tick #2. 9936 ms elapsed since last tick. useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 10000 useAsyncInterval.ts:37 [useAsyncInterval] tick #3. 10026 ms elapsed since last tick. useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 9958 useAsyncInterval.ts:62 [useAsyncInterval] Setting interval minIntervalMs: 10000 useAsyncInterval.ts:37 [useAsyncInterval] tick #1. 941977 ms elapsed since last tick. useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 0 useAsyncInterval.ts:37 [useAsyncInterval] tick #2. 13 ms elapsed since last tick. useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 10000 useAsyncInterval.ts:37 [useAsyncInterval] tick #3. 2038465 ms elapsed since last tick. HeapUsage.tsx:68 [HeapUsage] Unable to get heap usage Error: Authentication details invalid useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 0 useAsyncInterval.ts:37 [useAsyncInterval] tick #4. 19 ms elapsed since last tick. HeapUsage.tsx:68 [HeapUsage] Unable to get heap usage Error: Authentication details invalid useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 10000 useAsyncInterval.ts:37 [useAsyncInterval] tick #5. 537820 ms elapsed since last tick. HeapUsage.tsx:68 [HeapUsage] Unable to get heap usage Error: Authentication details invalid useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 0 useAsyncInterval.ts:37 [useAsyncInterval] tick #6. 16 ms elapsed since last tick. HeapUsage.tsx:68 [HeapUsage] Unable to get heap usage Error: Authentication details invalid useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 10000 useAsyncInterval.ts:37 [useAsyncInterval] tick #7. 191633 ms elapsed since last tick. HeapUsage.tsx:68 [HeapUsage] Unable to get heap usage Error: Authentication details invalid useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 0 useAsyncInterval.ts:37 [useAsyncInterval] tick #8. 18 ms elapsed since last tick. HeapUsage.tsx:68 [HeapUsage] Unable to get heap usage Error: Authentication details invalid useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 10000 useAsyncInterval.ts:37 [useAsyncInterval] tick #9. 23720 ms elapsed since last tick. HeapUsage.tsx:68 [HeapUsage] Unable to get heap usage Error: Authentication details invalid useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 0 useAsyncInterval.ts:37 [useAsyncInterval] tick #10. 18 ms elapsed since last tick. HeapUsage.tsx:68 [HeapUsage] Unable to get heap usage Error: Authentication details invalid useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 10000 useAsyncInterval.ts:37 [useAsyncInterval] tick #11. 886367 ms elapsed since last tick. HeapUsage.tsx:68 [HeapUsage] Unable to get heap usage Error: Authentication details invalid useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 0 useAsyncInterval.ts:37 [useAsyncInterval] tick #12. 17 ms elapsed since last tick. HeapUsage.tsx:68 [HeapUsage] Unable to get heap usage Error: Authentication details invalid useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 10000 useAsyncInterval.ts:37 [useAsyncInterval] tick #13. 1010951 ms elapsed since last tick. HeapUsage.tsx:68 [HeapUsage] Unable to get heap usage Error: Authentication details invalid useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 0 useAsyncInterval.ts:37 [useAsyncInterval] tick #14. 6 ms elapsed since last tick. HeapUsage.tsx:68 [HeapUsage] Unable to get heap usage Error: Authentication details invalid useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 10000 useAsyncInterval.ts:37 [useAsyncInterval] tick #15. 650011 ms elapsed since last tick. HeapUsage.tsx:68 [HeapUsage] Unable to get heap usage Error: Authentication details invalid useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 0 useAsyncInterval.ts:37 [useAsyncInterval] tick #16. 13 ms elapsed since last tick. HeapUsage.tsx:68 [HeapUsage] Unable to get heap usage Error: Authentication details invalid useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 10000 useAsyncInterval.ts:37 [useAsyncInterval] tick #17. 731687 ms elapsed since last tick. HeapUsage.tsx:68 [HeapUsage] Unable to get heap usage Error: Authentication details invalid useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 0 useAsyncInterval.ts:37 [useAsyncInterval] tick #18. 19 ms elapsed since last tick. HeapUsage.tsx:68 [HeapUsage] Unable to get heap usage Error: Authentication details invalid useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 10000 useAsyncInterval.ts:37 [useAsyncInterval] tick #19. 120545 ms elapsed since last tick. HeapUsage.tsx:68 [HeapUsage] Unable to get heap usage Error: Authentication details invalid useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 0 useAsyncInterval.ts:37 [useAsyncInterval] tick #20. 16 ms elapsed since last tick. HeapUsage.tsx:68 [HeapUsage] Unable to get heap usage Error: Authentication details invalid useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 10000 useAsyncInterval.ts:37 [useAsyncInterval] tick #21. 446345 ms elapsed since last tick. HeapUsage.tsx:68 [HeapUsage] Unable to get heap usage Error: Authentication details invalid useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 0 useAsyncInterval.ts:37 [useAsyncInterval] tick #22. 13 ms elapsed since last tick. HeapUsage.tsx:68 [HeapUsage] Unable to get heap usage Error: Authentication details invalid useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 10000 useAsyncInterval.ts:37 [useAsyncInterval] tick #23. 10999 ms elapsed since last tick. HeapUsage.tsx:68 [HeapUsage] Unable to get heap usage Error: Authentication details invalid useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 8987 useAsyncInterval.ts:37 [useAsyncInterval] tick #24. 9020 ms elapsed since last tick. HeapUsage.tsx:68 [HeapUsage] Unable to get heap usage Error: Authentication details invalid useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 10000 useAsyncInterval.ts:37 [useAsyncInterval] tick #25. 10030 ms elapsed since last tick. HeapUsage.tsx:68 [HeapUsage] Unable to get heap usage Error: Authentication details invalid useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 9955 useAsyncInterval.ts:37 [useAsyncInterval] tick #26. 9979 ms elapsed since last tick. useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 10000 useAsyncInterval.ts:37 [useAsyncInterval] tick #27. 10027 ms elapsed since last tick. useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 9956 useAsyncInterval.ts:62 [useAsyncInterval] Setting interval minIntervalMs: 10000 useAsyncInterval.ts:37 [useAsyncInterval] tick #1. 10695 ms elapsed since last tick. useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 9290 useAsyncInterval.ts:37 [useAsyncInterval] tick #2. 9311 ms elapsed since last tick. useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 10000 useAsyncInterval.ts:37 [useAsyncInterval] tick #3. 10017 ms elapsed since last tick. useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 9969 useAsyncInterval.ts:37 [useAsyncInterval] tick #4. 9992 ms elapsed since last tick. useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 9992 useAsyncInterval.ts:37 [useAsyncInterval] tick #5. 10680 ms elapsed since last tick. useAsyncInterval.ts:56 [useAsyncInterval] adjusted minIntervalMs: 9308 ```
diff --git a/package-lock.json b/package-lock.json
diff --git a/packages/console/package.json b/packages/console/package.json
@@ -31,6 +31,7 @@
     "@deephaven/log": "file:../log",
     "@deephaven/storage": "file:../storage",
     "@deephaven/utils": "file:../utils",
+    "@deephaven/react-hooks": "file:../react-hooks",
     "@fortawesome/react-fontawesome": "^0.2.0",
     "classnames": "^2.3.1",
     "linkifyjs": "^4.1.0",
diff --git a/packages/console/src/HeapUsage.tsx b/packages/console/src/HeapUsage.tsx
@@ -1,9 +1,10 @@
-import React, { useEffect, useState, ReactElement, useRef } from 'react';
+import { useState, ReactElement, useRef, useCallback } from 'react';
 import classNames from 'classnames';
 import { Tooltip } from '@deephaven/components';
 import type { QueryConnectable } from '@deephaven/jsapi-types';
 import { Plot, ChartTheme } from '@deephaven/chart';
 import Log from '@deephaven/log';
+import { useAsyncInterval } from '@deephaven/react-hooks';
 import './HeapUsage.scss';
 
 const log = Log.module('HeapUsage');
@@ -38,55 +39,39 @@ function HeapUsage({
     usages: [],
   });
 
-  useEffect(
-    function setUsageUpdateInterval() {
-      const fetchAndUpdate = async () => {
-        try {
-          const newUsage = await connection.getWorkerHeapInfo();
-          setMemoryUsage(newUsage);
-
-          if (bgMonitoring || isOpen) {
-            const currentUsage =
-              (newUsage.totalHeapSize - newUsage.freeMemory) /
-              newUsage.maximumHeapSize;
-            const currentTime = Date.now();
-
-            const { timestamps, usages } = historyUsage.current;
-            while (
-              timestamps.length !== 0 &&
-              currentTime - timestamps[0] > monitorDuration * 1.5
-            ) {
-              timestamps.shift();
-              usages.shift();
-            }
-
-            timestamps.push(currentTime);
-            usages.push(currentUsage);
-          } else {
-            historyUsage.current = { timestamps: [], usages: [] };
-          }
-        } catch (e) {
-          log.warn('Unable to get heap usage', e);
+  const setUsageUpdateInterval = useCallback(async () => {
+    try {
+      const newUsage = await connection.getWorkerHeapInfo();
+      setMemoryUsage(newUsage);
+
+      if (bgMonitoring || isOpen) {
+        const currentUsage =
+          (newUsage.totalHeapSize - newUsage.freeMemory) /
+          newUsage.maximumHeapSize;
+        const currentTime = Date.now();
+
+        const { timestamps, usages } = historyUsage.current;
+        while (
+          timestamps.length !== 0 &&
+          currentTime - timestamps[0] > monitorDuration * 1.5
+        ) {
+          timestamps.shift();
+          usages.shift();
         }
-      };
-      fetchAndUpdate();
-
-      const updateUsage = setInterval(
-        fetchAndUpdate,
-        isOpen ? hoverUpdateInterval : defaultUpdateInterval
-      );
-      return () => {
-        clearInterval(updateUsage);
-      };
-    },
-    [
-      isOpen,
-      hoverUpdateInterval,
-      connection,
-      defaultUpdateInterval,
-      monitorDuration,
-      bgMonitoring,
-    ]
+
+        timestamps.push(currentTime);
+        usages.push(currentUsage);
+      } else {
+        historyUsage.current = { timestamps: [], usages: [] };
+      }
+    } catch (e) {
+      log.warn('Unable to get heap usage', e);
+    }
+  }, [isOpen, connection, monitorDuration, bgMonitoring]);
+
+  useAsyncInterval(
+    setUsageUpdateInterval,
+    isOpen ? hoverUpdateInterval : defaultUpdateInterval
   );
 
   const toDecimalPlace = (num: number, dec: number) =>
diff --git a/packages/react-hooks/src/index.ts b/packages/react-hooks/src/index.ts
@@ -1,8 +1,10 @@
+export * from './useAsyncInterval';
 export { default as useContextOrThrow } from './useContextOrThrow';
 export { default as usePrevious } from './usePrevious';
 export { default as useForwardedRef } from './useForwardedRef';
 export { default as useCopyToClipboard } from './useCopyToClipboard';
 export { default as useFormWithDetachedSubmitButton } from './useFormWithDetachedSubmitButton';
+export * from './useIsMountedRef';
 export { default as usePromiseFactory } from './usePromiseFactory';
 export type { UseFormWithDetachedSubmitButtonResult } from './useFormWithDetachedSubmitButton';
 export type {
diff --git a/packages/react-hooks/src/useAsyncInterval.test.ts b/packages/react-hooks/src/useAsyncInterval.test.ts
@@ -0,0 +1,135 @@
+import { renderHook, act } from '@testing-library/react-hooks';
+import { TestUtils } from '@deephaven/utils';
+import useAsyncInterval from './useAsyncInterval';
+
+beforeEach(() => {
+  jest.clearAllMocks();
+  expect.hasAssertions();
+  jest.useFakeTimers();
+  jest.spyOn(window, 'setTimeout').mockName('setTimeout');
+});
+
+afterAll(() => {
+  jest.useRealTimers();
+});
+
+describe('useAsyncInterval', () => {
+  function createCallback(ms: number) {
+    return jest.fn(
+      async (): Promise<void> =>
+        new Promise(resolve => {
+          setTimeout(resolve, ms);
+        })
+    );
+  }
+
+  const targetIntervalMs = 1000;
+
+  it('should call the callback function after the target interval', async () => {
+    const callback = createCallback(50);
+
+    renderHook(() => useAsyncInterval(callback, targetIntervalMs));
+
+    // First tick should be scheduled for target interval
+    expect(callback).not.toHaveBeenCalled();
+    expect(window.setTimeout).toHaveBeenCalledWith(
+      expect.any(Function),
+      targetIntervalMs
+    );
+
+    // Callback should be called after target interval
+    act(() => jest.advanceTimersByTime(targetIntervalMs));
+    expect(callback).toHaveBeenCalledTimes(1);
+  });
+
+  it('should adjust the target interval based on how long async call takes', async () => {
+    const callbackDelayMs = 50;
+    const callback = createCallback(callbackDelayMs);
+
+    renderHook(() => useAsyncInterval(callback, targetIntervalMs));
+
+    // Callback should be called after target interval
+    expect(callback).not.toHaveBeenCalled();
+    act(() => jest.advanceTimersByTime(targetIntervalMs));
+    expect(callback).toHaveBeenCalledTimes(1);
+
+    jest.clearAllMocks();
+
+    // Mimick the callback Promise resolving
+    act(() => jest.advanceTimersByTime(callbackDelayMs));
+    await TestUtils.flushPromises();
+
+    // Next target interval should be adjusted based on how long the callback took
+    const nextTargetIntervalMs = targetIntervalMs - callbackDelayMs;
+
+    expect(callback).not.toHaveBeenCalled();
+    expect(window.setTimeout).toHaveBeenCalledTimes(1);
+    expect(window.setTimeout).toHaveBeenCalledWith(
+      expect.any(Function),
+      nextTargetIntervalMs
+    );
+
+    act(() => jest.advanceTimersByTime(nextTargetIntervalMs));
+    expect(callback).toHaveBeenCalledTimes(1);
+  });
+
+  it('should schedule the next callback immediately if the callback takes longer than the target interval', async () => {
+    const callbackDelayMs = targetIntervalMs + 50;
+    const callback = createCallback(callbackDelayMs);
+
+    renderHook(() => useAsyncInterval(callback, targetIntervalMs));
+
+    // Callback should be called after target interval
+    expect(callback).not.toHaveBeenCalled();
+    act(() => jest.advanceTimersByTime(targetIntervalMs));
+    expect(callback).toHaveBeenCalledTimes(1);
+
+    jest.clearAllMocks();
+
+    // Mimick the callback Promise resolving
+    act(() => jest.advanceTimersByTime(callbackDelayMs));
+    await TestUtils.flushPromises();
+
+    expect(callback).not.toHaveBeenCalled();
+    expect(window.setTimeout).toHaveBeenCalledTimes(1);
+    expect(window.setTimeout).toHaveBeenCalledWith(expect.any(Function), 0);
+
+    act(() => jest.advanceTimersByTime(0));
+    expect(callback).toHaveBeenCalledTimes(1);
+  });
+
+  it('should stop calling the callback function after unmounting', async () => {
+    const callback = createCallback(50);
+
+    const { unmount } = renderHook(() =>
+      useAsyncInterval(callback, targetIntervalMs)
+    );
+
+    unmount();
+
+    act(() => jest.advanceTimersByTime(targetIntervalMs));
+
+    expect(callback).not.toHaveBeenCalled();
+  });
+
+  it('should not re-schedule callback if callback resolves after unmounting', async () => {
+    const callbackDelayMs = 50;
+    const callback = createCallback(callbackDelayMs);
+
+    const { unmount } = renderHook(() =>
+      useAsyncInterval(callback, targetIntervalMs)
+    );
+
+    act(() => jest.advanceTimersByTime(targetIntervalMs));
+    expect(callback).toHaveBeenCalledTimes(1);
+    jest.clearAllMocks();
+
+    unmount();
+
+    // Mimick the callback Promise resolving
+    act(() => jest.advanceTimersByTime(callbackDelayMs));
+    await TestUtils.flushPromises();
+
+    expect(window.setTimeout).not.toHaveBeenCalled();
+  });
+});
diff --git a/packages/react-hooks/src/useAsyncInterval.ts b/packages/react-hooks/src/useAsyncInterval.ts
@@ -0,0 +1,78 @@
+import { useCallback, useEffect, useRef } from 'react';
+import Log from '@deephaven/log';
+import { useIsMountedRef } from './useIsMountedRef';
+
+const log = Log.module('useAsyncInterval');
+
+/**
+ * Calls the given async callback at a target interval.
+ *
+ * If the callback takes less time than the target interval, the target interval
+ * for the next tick will be adjusted to target the remaining time in the current
+ * interval.
+ *
+ * e.g. If the target interval is 1000ms, and the callback takes 50ms to resolve,
+ * the next tick will be scheduled for 950ms from now via `setTimeout(callback, 950)`.
+ *
+ * If the callback takes longer than the target interval, the next tick will be
+ * scheduled immediately via `setTimeout(callback, 0)`. In such cases, the time
+ * between ticks may be > than the target interval, but this guarantees that
+ * a callback won't be scheduled until after the previous one has resolved.
+ * @param callback Callback to call at the target interval
+ * @param targetIntervalMs Target interval in milliseconds to call the callback
+ */
+export function useAsyncInterval(
+  callback: () => Promise<void>,
+  targetIntervalMs: number
+) {
+  const isMountedRef = useIsMountedRef();
+  const trackingRef = useRef({ count: 0, started: Date.now() });
+  const setTimeoutRef = useRef(0);
+
+  const tick = useCallback(async () => {
+    const now = Date.now();
+    let elapsedSinceLastTick = now - trackingRef.current.started;
+
+    trackingRef.current.count += 1;
+    trackingRef.current.started = now;
+
+    log.debug(
+      `tick #${trackingRef.current.count}.`,
+      elapsedSinceLastTick,
+      'ms elapsed since last tick.'
+    );
+
+    await callback();
+
+    if (!isMountedRef.current) {
+      return;
+    }
+
+    elapsedSinceLastTick += Date.now() - trackingRef.current.started;
+
+    // If elapsed time is > than the target interval, adjust the next tick interval
+    const nextTickInterval = Math.max(
+      0,
+      Math.min(
+        targetIntervalMs,
+        targetIntervalMs - (elapsedSinceLastTick - targetIntervalMs)
+      )
+    );
+
+    log.debug('adjusted minIntervalMs:', nextTickInterval);
+
+    setTimeoutRef.current = window.setTimeout(tick, nextTickInterval);
+  }, [callback, isMountedRef, targetIntervalMs]);
+
+  useEffect(() => {
+    log.debug('Setting interval minIntervalMs:', targetIntervalMs);
+
+    setTimeoutRef.current = window.setTimeout(tick, targetIntervalMs);
+
+    return () => {
+      window.clearTimeout(setTimeoutRef.current);
+    };
+  }, [targetIntervalMs, tick]);
+}
+
+export default useAsyncInterval;
diff --git a/packages/react-hooks/src/useIsMountedRef.test.ts b/packages/react-hooks/src/useIsMountedRef.test.ts
@@ -0,0 +1,19 @@
+import { renderHook } from '@testing-library/react-hooks';
+import { useIsMountedRef } from './useIsMountedRef';
+
+beforeEach(() => {
+  jest.clearAllMocks();
+  expect.hasAssertions();
+});
+
+describe('useIsMountedRef', () => {
+  it('should return a ref which tracks whether the component is mounted or not', () => {
+    const { result, unmount } = renderHook(() => useIsMountedRef());
+
+    expect(result.current.current).toBe(true);
+
+    unmount();
+
+    expect(result.current.current).toBe(false);
+  });
+});
diff --git a/packages/react-hooks/src/useIsMountedRef.ts b/packages/react-hooks/src/useIsMountedRef.ts
@@ -0,0 +1,20 @@
+import { useEffect, useRef } from 'react';
+
+/**
+ * Returns a ref which tracks whether the component is mounted or not.
+ */
+export function useIsMountedRef() {
+  const isMountedRef = useRef(false);
+
+  useEffect(() => {
+    isMountedRef.current = true;
+
+    return () => {
+      isMountedRef.current = false;
+    };
+  }, []);
+
+  return isMountedRef;
+}
+
+export default useIsMountedRef;
diff --git a/packages/utils/src/TestUtils.ts b/packages/utils/src/TestUtils.ts
