From 5db762e98735cdb2a8e0061cdd2e816a7b6d5262 Mon Sep 17 00:00:00 2001 From: Hariom Balhara Date: Thu, 7 Jul 2022 20:56:22 +0530 Subject: [PATCH] Add logs (#3256) --- apps/web/server/routers/viewer/slots.tsx | 42 ++++++++++++++++++------ packages/core/CalendarManager.ts | 19 +++++++++-- packages/core/getBusyTimes.ts | 5 ++- packages/core/getUserAvailability.ts | 8 +++-- packages/lib/logger.ts | 1 + 5 files changed, 58 insertions(+), 17 deletions(-) diff --git a/apps/web/server/routers/viewer/slots.tsx b/apps/web/server/routers/viewer/slots.tsx index 88acb51cbe..d80f298580 100644 --- a/apps/web/server/routers/viewer/slots.tsx +++ b/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, }; diff --git a/packages/core/CalendarManager.ts b/packages/core/CalendarManager.ts index 77c6cea95c..eb7f7c2137 100644 --- a/packages/core/CalendarManager.ts +++ b/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 ( diff --git a/packages/core/getBusyTimes.ts b/packages/core/getBusyTimes.ts index d75a1b5922..30397f85ac 100644 --- a/packages/core/getBusyTimes.ts +++ b/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); diff --git a/packages/core/getUserAvailability.ts b/packages/core/getUserAvailability.ts index 8af6ac6a28..3d6b058675 100644 --- a/packages/core/getUserAvailability.ts +++ b/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, diff --git a/packages/lib/logger.ts b/packages/lib/logger.ts index 9cbcc05088..b6ebce421e 100644 --- a/packages/lib/logger.ts +++ b/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",