Add logs (#3256)

apps/web/server/routers/viewer/slots.tsx

@@ -4,6 +4,7 @@ import { z } from "zod";
 import type { CurrentSeats } from "@calcom/core/getUserAvailability";
 import { getUserAvailability } from "@calcom/core/getUserAvailability";
 import dayjs, { Dayjs } from "@calcom/dayjs";
+import logger from "@calcom/lib/logger";
 import { availabilityUserSelect } from "@calcom/prisma";
 import { TimeRange } from "@calcom/types/schedule";
 
@@ -25,6 +26,7 @@ const getScheduleSchema = z
     timeZone: z.string().optional(),
     // or list of users (for dynamic events)
     usernameList: z.array(z.string()).optional(),
+    debug: z.boolean().optional(),
   })
   .refine(
     (data) => !!data.eventTypeId || !!data.usernameList,
@@ -103,6 +105,10 @@ const checkForAvailability = ({
 export const slotsRouter = createRouter().query("getSchedule", {
   input: getScheduleSchema,
   async resolve({ input, ctx }) {
+    if (input.debug === true) {
+      logger.setSettings({ minLevel: "debug" });
+    }
+    const startPrismaEventTypeGet = performance.now();
     const eventType = await ctx.prisma.eventType.findUnique({
       where: {
         id: input.eventTypeId,
@@ -143,7 +149,8 @@ export const slotsRouter = createRouter().query("getSchedule", {
         },
       },
     });
-
+    const endPrismaEventTypeGet = performance.now();
+    logger.debug(`Prisma eventType get took ${endPrismaEventTypeGet - startPrismaEventTypeGet}ms`);
     if (!eventType) {
       throw new TRPCError({ code: "NOT_FOUND" });
     }
@@ -203,8 +210,12 @@ export const slotsRouter = createRouter().query("getSchedule", {
       });
 
     let time = startTime;
-
+    let getSlotsTime = 0;
+    let checkForAvailabilityTime = 0;
+    let getSlotsCount = 0;
+    let checkForAvailabilityCount = 0;
     do {
+      const startGetSlots = performance.now();
       // get slots retrieves the available times for a given day
       const times = getSlots({
         inviteeDate: time,
@@ -213,19 +224,24 @@ export const slotsRouter = createRouter().query("getSchedule", {
         minimumBookingNotice: eventType.minimumBookingNotice,
         frequency: eventType.slotInterval || eventType.length,
       });
-
+      const endGetSlots = performance.now();
+      getSlotsTime += endGetSlots - startGetSlots;
+      getSlotsCount++;
       // if ROUND_ROBIN - slots stay available on some() - if normal / COLLECTIVE - slots only stay available on every()
       const filterStrategy =
         !eventType.schedulingType || eventType.schedulingType === SchedulingType.COLLECTIVE
           ? ("every" as const)
           : ("some" as const);
-      const filteredTimes = times
-        .filter(isWithinBounds)
-        .filter((time) =>
-          userSchedules[filterStrategy]((schedule) =>
-            checkForAvailability({ time, ...schedule, ...availabilityCheckProps })
-          )
-        );
+      const filteredTimes = times.filter(isWithinBounds).filter((time) =>
+        userSchedules[filterStrategy]((schedule) => {
+          const startCheckForAvailability = performance.now();
+          const result = checkForAvailability({ time, ...schedule, ...availabilityCheckProps });
+          const endCheckForAvailability = performance.now();
+          checkForAvailabilityCount++;
+          checkForAvailabilityTime += endCheckForAvailability - startCheckForAvailability;
+          return result;
+        })
+      );
 
       slots[time.format("YYYY-MM-DD")] = filteredTimes.map((time) => ({
         time: time.toISOString(),
@@ -245,6 +261,12 @@ export const slotsRouter = createRouter().query("getSchedule", {
       time = time.add(1, "day");
     } while (time.isBefore(endTime));
 
+    logger.debug(`getSlots took ${getSlotsTime}ms and executed ${getSlotsCount} times`);
+
+    logger.debug(
+      `checkForAvailability took ${checkForAvailabilityTime}ms and executed ${checkForAvailabilityCount} times`
+    );
+
     return {
       slots,
     };

packages/core/CalendarManager.ts

@@ -78,7 +78,7 @@ export const getConnectedCalendars = async (
 
 const CACHING_TIME = 30_000; // 30 seconds
 
-const getCachedResults = (
+const getCachedResults = async (
   withCredentials: Credential[],
   dateFrom: string,
   dateTo: string,
@@ -86,6 +86,8 @@ const getCachedResults = (
 ) => {
   const calendarCredentials = withCredentials.filter((credential) => credential.type.endsWith("_calendar"));
   const calendars = calendarCredentials.map((credential) => getCalendar(credential));
+
+  const startGetBusyCalendarTimes = performance.now();
   const results = calendars.map(async (c, i) => {
     /** Filter out nulls */
     if (!c) return [];
@@ -103,15 +105,26 @@ const getCachedResults = (
       .digest("hex");
     /** Check if we already have cached data and return */
     const cachedAvailability = cache.get(cacheKey);
-    if (cachedAvailability) return cachedAvailability;
+    if (cachedAvailability) {
+      log.debug(`Cache HIT: Calendar Availability for key`, { id, selectedCalendarIds, dateFrom, dateTo });
+      return cachedAvailability;
+    }
+    log.debug(`Cache MISS: Calendar Availability for key`, { id, selectedCalendarIds, dateFrom, dateTo });
     /** If we don't then we actually fetch external calendars (which can be very slow) */
     const availability = await c.getAvailability(dateFrom, dateTo, passedSelectedCalendars);
     /** We save the availability to a few seconds so recurrent calls are nearly instant */
     cache.put(cacheKey, availability, CACHING_TIME);
     return availability;
   });
+  const awaitedResults = await Promise.all(results);
+  const endGetBusyCalendarTimes = performance.now();
 
-  return Promise.all(results);
+  log.debug(
+    `getBusyCalendarTimes took ${
+      endGetBusyCalendarTimes - startGetBusyCalendarTimes
+    }ms for creds ${calendarCredentials.map((cred) => cred.id)}`
+  );
+  return awaitedResults;
 };
 
 export const getBusyCalendarTimes = async (

packages/core/getBusyTimes.ts

@@ -1,6 +1,7 @@
 import { BookingStatus, Credential, SelectedCalendar } from "@prisma/client";
 
 import { getBusyCalendarTimes } from "@calcom/core/CalendarManager";
+import logger from "@calcom/lib/logger";
 // import { getBusyVideoTimes } from "@calcom/core/videoClient";
 // import notEmpty from "@calcom/lib/notEmpty";
 import prisma from "@calcom/prisma";
@@ -15,6 +16,7 @@ export async function getBusyTimes(params: {
   selectedCalendars: SelectedCalendar[];
 }) {
   const { credentials, userId, eventTypeId, startTime, endTime, selectedCalendars } = params;
+  const startPrismaBookingGet = performance.now();
   const busyTimes: EventBusyDate[] = await prisma.booking
     .findMany({
       where: {
@@ -32,7 +34,8 @@ export async function getBusyTimes(params: {
       },
     })
     .then((bookings) => bookings.map(({ startTime, endTime }) => ({ end: endTime, start: startTime })));
-
+  const endPrismaBookingGet = performance.now();
+  logger.debug(`prisma booking get took ${endPrismaBookingGet - startPrismaBookingGet}ms`);
   if (credentials.length > 0) {
     const calendarBusyTimes = await getBusyCalendarTimes(credentials, startTime, endTime, selectedCalendars);
     // console.log("calendarBusyTimes", calendarBusyTimes);

packages/core/getUserAvailability.ts

@@ -1,9 +1,10 @@
 import { Prisma } from "@prisma/client";
-import dayjs, { Dayjs } from "@calcom/dayjs";
 import { z } from "zod";
 
+import dayjs, { Dayjs } from "@calcom/dayjs";
 import { getWorkingHours } from "@calcom/lib/availability";
 import { HttpError } from "@calcom/lib/http-error";
+import logger from "@calcom/lib/logger";
 import prisma, { availabilityUserSelect } from "@calcom/prisma";
 import { stringToDayjs } from "@calcom/prisma/zod-utils";
 
@@ -137,13 +138,14 @@ export async function getUserAvailability(
       };
 
   const timeZone = timezone || schedule?.timeZone || eventType?.timeZone || currentUser.timeZone;
-
+  const startGetWorkingHours = performance.now();
   const workingHours = getWorkingHours(
     { timeZone },
     schedule.availability ||
       (eventType?.availability.length ? eventType.availability : currentUser.availability)
   );
-
+  const endGetWorkingHours = performance.now();
+  logger.debug(`getWorkingHours took ${endGetWorkingHours - startGetWorkingHours}ms for userId ${userId}`);
   return {
     busy: bufferedBusyTimes,
     timeZone,

packages/lib/logger.ts

@@ -3,6 +3,7 @@ import { Logger } from "tslog";
 import { IS_PRODUCTION } from "./constants";
 
 const logger = new Logger({
+  minLevel: "info",
   dateTimePattern: "hour:minute:second.millisecond timeZoneName",
   displayFunctionName: false,
   displayFilePath: "hidden",