shockbot/utils/timer.test.ts

import * as cli from "./cli.ts";
import { ThinkingTimer, Timer } from "./timer.ts";

describe("Timer", () => {
  beforeEach(() => {
    vi.spyOn(cli.log, "debug");
    // Mock Date.now to have predictable timestamps
    vi.useFakeTimers();
  });

  afterEach(() => {
    vi.restoreAllMocks();
    vi.useRealTimers();
  });

  describe("constructor", () => {
    it("should initialize with current timestamp", () => {
      const mockTime = 1000000;
      vi.setSystemTime(mockTime);

      const timer = new Timer();
      timer.checkpoint("test");

      expect(cli.log.debug).toHaveBeenCalledWith(expect.stringContaining("test"));
    });
  });

  describe("checkpoint", () => {
    it("should log duration from initial timestamp on first checkpoint", () => {
      const startTime = 1000000;
      vi.setSystemTime(startTime);
      const timer = new Timer();

      const checkpointTime = startTime + 100;
      vi.setSystemTime(checkpointTime);
      timer.checkpoint("first");

      expect(cli.log.debug).toHaveBeenCalledWith("» first: 100ms");
    });

    it("should log duration from last checkpoint on subsequent checkpoints", () => {
      const startTime = 1000000;
      vi.setSystemTime(startTime);
      const timer = new Timer();

      // First checkpoint
      const firstCheckpointTime = startTime + 50;
      vi.setSystemTime(firstCheckpointTime);
      timer.checkpoint("first");

      // Second checkpoint
      const secondCheckpointTime = firstCheckpointTime + 75;
      vi.setSystemTime(secondCheckpointTime);
      timer.checkpoint("second");

      expect(cli.log.debug).toHaveBeenCalledTimes(2);
      expect(cli.log.debug).toHaveBeenNthCalledWith(1, "» first: 50ms");
      expect(cli.log.debug).toHaveBeenNthCalledWith(2, "» second: 75ms");
    });

    it("should handle multiple checkpoints correctly", () => {
      const startTime = 1000000;
      vi.setSystemTime(startTime);
      const timer = new Timer();

      // First checkpoint
      vi.setSystemTime(startTime + 10);
      timer.checkpoint("step1");

      // Second checkpoint
      vi.setSystemTime(startTime + 25);
      timer.checkpoint("step2");

      // Third checkpoint
      vi.setSystemTime(startTime + 45);
      timer.checkpoint("step3");

      expect(cli.log.debug).toHaveBeenCalledTimes(3);
      expect(cli.log.debug).toHaveBeenNthCalledWith(1, "» step1: 10ms");
      expect(cli.log.debug).toHaveBeenNthCalledWith(2, "» step2: 15ms");
      expect(cli.log.debug).toHaveBeenNthCalledWith(3, "» step3: 20ms");
    });

    it("should handle zero duration correctly", () => {
      const startTime = 1000000;
      vi.setSystemTime(startTime);
      const timer = new Timer();

      // Checkpoint immediately
      timer.checkpoint("immediate");

      expect(cli.log.debug).toHaveBeenCalledWith("» immediate: 0ms");
    });

    it("should handle custom checkpoint names", () => {
      const startTime = 1000000;
      vi.setSystemTime(startTime);
      const timer = new Timer();

      vi.setSystemTime(startTime + 200);
      timer.checkpoint("Custom Checkpoint Name");

      expect(cli.log.debug).toHaveBeenCalledWith("» Custom Checkpoint Name: 200ms");
    });
  });
});

describe("ThinkingTimer", () => {
  beforeEach(() => {
    vi.spyOn(cli.log, "info");
    vi.useFakeTimers();
  });

  afterEach(() => {
    vi.restoreAllMocks();
    vi.useRealTimers();
  });

  describe("markToolResult", () => {
    it("should store the current timestamp", () => {
      const startTime = 1000000;
      vi.setSystemTime(startTime);

      const timer = new ThinkingTimer();
      timer.markToolResult();

      vi.setSystemTime(startTime + 5000);
      timer.markToolCall();

      expect(cli.log.info).toHaveBeenCalled();
    });
  });

  describe("markToolCall", () => {
    it("should not log if markToolResult was never called", () => {
      const timer = new ThinkingTimer();
      timer.markToolCall();

      expect(cli.log.info).not.toHaveBeenCalled();
    });

    it("should not log if elapsed time is below threshold (3000ms)", () => {
      const startTime = 1000000;
      vi.setSystemTime(startTime);

      const timer = new ThinkingTimer();
      timer.markToolResult();

      vi.setSystemTime(startTime + 2999);
      timer.markToolCall();

      expect(cli.log.info).not.toHaveBeenCalled();
    });

    it("should log if elapsed time equals threshold (3000ms)", () => {
      const startTime = 1000000;
      vi.setSystemTime(startTime);

      const timer = new ThinkingTimer();
      timer.markToolResult();

      vi.setSystemTime(startTime + 3000);
      timer.markToolCall();

      expect(cli.log.info).toHaveBeenCalledWith("» thought for 3 seconds");
    });

    it("should log if elapsed time exceeds threshold", () => {
      const startTime = 1000000;
      vi.setSystemTime(startTime);

      const timer = new ThinkingTimer();
      timer.markToolResult();

      vi.setSystemTime(startTime + 5500);
      timer.markToolCall();

      expect(cli.log.info).toHaveBeenCalledWith("» thought for 5.5 seconds");
    });

    it("should format large durations correctly", () => {
      const startTime = 1000000;
      vi.setSystemTime(startTime);

      const timer = new ThinkingTimer();
      timer.markToolResult();

      vi.setSystemTime(startTime + 15000);
      timer.markToolCall();

      expect(cli.log.info).toHaveBeenCalledWith("» thought for 15 seconds");
    });

    it("should handle multiple markToolCall invocations", () => {
      const startTime = 1000000;
      vi.setSystemTime(startTime);

      const timer = new ThinkingTimer();
      timer.markToolResult();

      vi.setSystemTime(startTime + 4000);
      timer.markToolCall();

      vi.setSystemTime(startTime + 5000);
      timer.markToolCall();

      expect(cli.log.info).toHaveBeenCalledTimes(2);
      expect(cli.log.info).toHaveBeenNthCalledWith(1, "» thought for 4 seconds");
      expect(cli.log.info).toHaveBeenNthCalledWith(2, "» thought for 5 seconds");
    });
  });
});