Slow Query Logging

queries.ts

// firestoreFetchSingle - This is our logger and timer function which will log if the fetch took more than 60 seconds to return the result

// locations - fetch document by id
public static getById(id): Promise<Location> {
  return new Promise<Location>(async(resolve, reject) => {
    try {
      const snapshot = await firestoreFetchSingle(Location.collectionRef().doc(id), 'location', id)

      if (!snapshot.exists) return reject("location not found");
      const doc = new Location(snapshot);
      resolve(doc);
    } catch (ex) {
      log.error(ex);
      reject(ex);
    }
  });
}

// contacts - fetch document by id
public static getById(id): Promise<Contact> {
  return new Promise(async(resolve, reject) => {
    try {
      log.info(`fetching contact by id ${id}`);
      const snapshot = await firestoreFetchSingle(Contact.collectionRef().doc(id), 'contact', id)

      if (!snapshot.exists) return resolve();
      if (snapshot.data().deleted) {
        log.warn(`Contact ${id} is deleted`);
        return resolve();
      }
      resolve(new Contact(snapshot));
    } catch (ex) {
      log.error(ex);
      reject(ex);
    }
  });
}

slow_fetch_timer.ts

import { firestore } from 'firebase-admin';
import config from '../config';
import { IElasticIndexForDelay, sendElasticLoggingEvent } from '../util/es_logging';
import { log } from '../util/logger';

interface ISlowTimerParams {
  locationId?: string;
  id?: string;
}

const startSlowTimer = (counterObj: any, property: string) => {
  // General function to be used by all Timers.
  if (counterObj && property) {
    if (counterObj[property]) {
      counterObj[property] += 1;
    } else {
      counterObj[property] = 1;
    }
  }
  return Date.now();
};

const endSlowTimer = (counterObj: any, time1: number, property: string, suffix: string, slowTimerParams: ISlowTimerParams, error = false) => {
  // General function to be used by all Timers.
  if (counterObj && property) {
    try {
      if (config.slowFetchLogForSeconds && error === false) {
        const time2 = Date.now();
        const timeTaken = Math.round((time2 - time1) / 1000);
        const slowTimeSec = config.slowFetchLogForSeconds;

        if (timeTaken >= slowTimeSec) {
          log.warn(`#slow - ${property} timer took ${timeTaken} which is more than limit of ${slowTimeSec}. Counter: ${counterObj[property]}`);

          const info = {
            ...slowTimerParams,
            namespace: 'infra_delay',
            type: `${property}_${suffix}`,
            podName: process.env.HOSTNAME,
            processTime: timeTaken,
            documentsBeingFetched: counterObj[property]
          } as IElasticIndexForDelay;
          if (slowTimerParams?.id) {
            info.id = slowTimerParams.id;
          }
          sendElasticLoggingEvent(info);
        }
      }
    } catch (err) {
      log.info(`An error ocurred while saving data to ES in endSlowTimer for ${property}_${suffix}`);
      log.warn(err);
    }

    if (counterObj[property]) {
      counterObj[property] -= 1;
    } else {
      counterObj[property] = 0; // reset
    }
  }
};

const documentsBeingFetched = {};

export const startSlowFetchTimer = (dataType: string) => {
  return startSlowTimer(documentsBeingFetched, dataType);
};

export const endSlowFetchTimer = (time1: number, dataType: string, locationId?: string, id?: string, error = false) => {
  endSlowTimer(documentsBeingFetched, time1, dataType, 'fetch', {
    locationId,
    id
  }, error);
};

const endpointsBeingCalled = {};

export const startSlowRequestTimer = (endpoint: string) => {
  return startSlowTimer(endpointsBeingCalled, endpoint);
};

export const endSlowRequestTimer = (time1: number, endpoint: string, locationId?: string, error = false) => {
  endSlowTimer(endpointsBeingCalled, time1, endpoint, 'endpoint', {
    locationId
  }, error);
};

export async function firestoreFetchSingle(query: firestore.DocumentReference, dataType: string, id: string) {
  let locationId: string;
  const time1 = startSlowFetchTimer(dataType);
  try {
    const snapshot = await query.get();
    if (snapshot.exists) locationId = snapshot.data()?.location_id;
    endSlowFetchTimer(time1, dataType, locationId, id);
    return snapshot;
  } catch (err) {
    log.warn(err);
    endSlowFetchTimer(time1, dataType, locationId, id, true);
    throw err;
  }
}

export async function firestoreFetchMultiple(query: firestore.Query, dataType: string, locationId?: string) {
  const time1 = startSlowFetchTimer(dataType);
  try {
    const snapshot = await query.get();
    endSlowFetchTimer(time1, dataType, locationId);
    return snapshot;
  } catch (err) {
    log.warn(err);
    endSlowFetchTimer(time1, dataType, locationId, undefined, true);
    throw err;
  }
}