Adding a bunch of performance markers (#6303)

* Adding a bunch of performance markers

* Update packages/lib/server/perfObserver.ts

Co-authored-by: Peer Richelsen <peeroke@gmail.com>
Co-authored-by: kodiakhq[bot] <49736102+kodiakhq[bot]@users.noreply.github.com>

packages/core/CalendarManager.ts

@@ -124,7 +124,7 @@ const getCachedResults = async (
   const calendarCredentials = withCredentials.filter((credential) => credential.type.endsWith("_calendar"));
   const calendars = calendarCredentials.map((credential) => getCalendar(credential));
 
-  const startGetBusyCalendarTimes = performance.now();
+  performance.mark("getBusyCalendarTimesStart");
   const results = calendars.map(async (c, i) => {
     /** Filter out nulls */
     if (!c) return [];
@@ -148,22 +148,27 @@ const getCachedResults = async (
     }
     log.debug(`Cache MISS: Calendar Availability for key ${cacheKey}`);
     /** If we don't then we actually fetch external calendars (which can be very slow) */
-    const availability = (await c.getAvailability(dateFrom, dateTo, passedSelectedCalendars)).map((a) => ({
-      ...a,
-      source: `${appId}`,
-    }));
+    performance.mark("eventBusyDatesStart");
+    const eventBusyDates = await c.getAvailability(dateFrom, dateTo, passedSelectedCalendars);
+    performance.mark("eventBusyDatesEnd");
+    performance.measure(
+      `[getAvailability for ${selectedCalendarIds.join(", ")}][$1]'`,
+      "eventBusyDatesStart",
+      "eventBusyDatesEnd"
+    );
+    const availability = eventBusyDates.map((a) => ({ ...a, source: `${appId}` }));
+
     /** We save the availability to a few seconds so recurrent calls are nearly instant */
 
     cache.put(cacheHashedKey, availability, CACHING_TIME);
     return availability;
   });
   const awaitedResults = await Promise.all(results);
-  const endGetBusyCalendarTimes = performance.now();
-
-  log.debug(
-    `getBusyCalendarTimes took ${
-      endGetBusyCalendarTimes - startGetBusyCalendarTimes
-    }ms for creds ${calendarCredentials.map((cred) => cred.id)}`
+  performance.mark("getBusyCalendarTimesEnd");
+  performance.measure(
+    `getBusyCalendarTimes took $1 for creds ${calendarCredentials.map((cred) => cred.id)}`,
+    "getBusyCalendarTimesStart",
+    "getBusyCalendarTimesEnd"
   );
   return awaitedResults;
 };

packages/core/getBusyTimes.ts

@@ -34,7 +34,7 @@ export async function getBusyTimes(params: {
       status: BookingStatus.ACCEPTED,
     })}`
   );
-  const startPrismaBookingGet = performance.now();
+  performance.mark("prismaBookingGetStart");
   const busyTimes: EventBusyDetails[] = await prisma.booking
     .findMany({
       where: {
@@ -72,11 +72,10 @@ export async function getBusyTimes(params: {
       }))
     );
   logger.silly(`Busy Time from Cal Bookings ${JSON.stringify(busyTimes)}`);
-  const endPrismaBookingGet = performance.now();
-  logger.debug(`prisma booking get took ${endPrismaBookingGet - startPrismaBookingGet}ms`);
+  performance.mark("prismaBookingGetEnd");
+  performance.measure(`prisma booking get took $1'`, "prismaBookingGetStart", "prismaBookingGetEnd");
   if (credentials?.length > 0) {
     const calendarBusyTimes = await getBusyCalendarTimes(credentials, startTime, endTime, selectedCalendars);
-
     busyTimes.push(
       ...calendarBusyTimes.map((value) => ({
         ...value,

packages/lib/server/perfObserver.ts

@@ -1,5 +1,7 @@
 import { PerformanceObserver } from "perf_hooks";
 
+import logger from "../logger";
+
 declare global {
   // eslint-disable-next-line no-var
   var perfObserver: PerformanceObserver | undefined;
@@ -9,8 +11,7 @@ export const perfObserver =
   new PerformanceObserver((items) => {
     items.getEntries().forEach((entry) => {
       // Log entry duration in seconds with four decimal places.
-      if (!!process.env.NEXT_PUBLIC_DEBUG)
-        console.log(entry.name.replace("$1", `${(entry.duration / 1000.0).toFixed(4)}s`));
+      logger.debug(entry.name.replace("$1", `${(entry.duration / 1000.0).toFixed(4)}s`));
     });
   });