feat: increase entitiesUpdateSince performance, closes #236 (#237)

- detailed logging for entitiesUpdatedSince
- rewrote parts of the fetching procedure to handle pristine fetches more explicitly
- populate users on pristine entitiesUpdateSince fetch
  by populating the user field deliberately many lookups down the road
can be saved
- better leveraging of cached user data

server/lib/cache/methods/cacheDiff.ts

@@ -1,12 +1,24 @@
 import { BaseType } from '../../util/baseObject'
+import { timerEnd, timerStart } from '../../util/logging'
 import { cacheGetPatch } from './cacheGetPatch'
 
 export const cacheDiff = <T extends BaseType>(
   entities: Array<T>,
   cachedIds: Array<string>,
   { cacheUpdatedAt }: { cacheUpdatedAt: Date },
 ) => {
+  if (cacheUpdatedAt.getTime() === 0) {
+    return {
+      added: entities,
+      removedIds: [],
+      updated: [],
+      patch: { type: 'add', newPos: 0, oldPos: 0, items: entities }
+    }
+  }
+
+  timerStart('cacheDiff: cacheGetPatch')
   const entitiesPatch = cacheGetPatch(entities, cachedIds)
+  timerEnd('cacheDiff: cacheGetPatch')
   const cachePatch = {
     added: [],
     removedIds: [],

server/lib/cache/methods/entitiesUpdatedSince.ts

@@ -2,7 +2,7 @@ import { baseNotesQuery, leanTypeEnumFixer } from '../../notes/notesMethods'
 import { Note } from '../../notes/notesModels'
 import { Tag } from '../../tags/tagModel'
 import { baseTagsQuery } from '../../tags/tagsMethods'
-import { timerEnd, timerStart } from '../../util/logging'
+import { logger, timerEnd, timerStart } from '../../util/logging'
 import { Cache } from '../cacheModel'
 import { cacheDiff } from './cacheDiff'
 import { updateCacheFromDiff } from './updateCacheFromDiff'
@@ -14,6 +14,7 @@ export const entitiesUpdatedSince = async (cacheId, user) => {
 
   timerStart('entitiesUpdatedSince')
 
+  timerStart('entitesUpdatedSince: cache read')
   let cache = (await Cache.findOne({ _id: cacheId, user }).lean()) || {
     _id: undefined,
     value: {
@@ -23,47 +24,74 @@ export const entitiesUpdatedSince = async (cacheId, user) => {
     updatedAt: new Date(0),
   }
   const cacheUpdatedAt = cache.updatedAt
+  timerEnd('entitesUpdatedSince: cache read')
 
   const entityQueryProjection = cache._id
-    ? { _id: 1, updatedAt: 1, createdAt: 1 }
+    ? { _id: 1, updatedAt: 1, createdAt: 1, type: 1 }
     : {}
 
   const fetchNotes = async (transformFilters = (filter) => filter) => {
+    if (cache._id) {
+      logger.trace('Cache exists, read notes directly from collection')
+      return Note.collection
+        .find(
+          transformFilters({
+            ...(await baseNotesQuery(user, 'read')),
+            deletedAt: null,
+          }),
+        )
+        .project(entityQueryProjection)
+        .sort({ createdAt: -1 })
+        .toArray()
+        .then(leanTypeEnumFixer)
+    }
+
+    // we're fetching notes with full population because we don't have any data cached and can save lookups down the road
     let notesLookup = Note.find(
       transformFilters({
         ...(await baseNotesQuery(user, 'read')),
         deletedAt: null,
       }),
-      entityQueryProjection,
     )
       .sort({ createdAt: -1 })
+      .populate('tags')
+      .populate('user')
       .lean()
 
-    if (!cache._id) {
-      notesLookup = notesLookup.populate('tags')
-    }
-
     return notesLookup.exec().then(leanTypeEnumFixer)
   }
+  timerStart('entitesUpdatedSince: load notes from DB')
   const notes = await fetchNotes()
+  timerEnd('entitesUpdatedSince: load notes from DB')
 
+  timerStart('entitesUpdatedSince: load tags from DB')
   const tags = await Tag.find(
     {
       ...baseTagsQuery(user, 'read'),
     },
     entityQueryProjection,
   )
+    // maybe only populate user on pristine reads?
+    .populate('user')
     .lean()
     .exec()
+  timerEnd('entitesUpdatedSince: load tags from DB')
+
+  // gets lost somewhere around here?
 
+  timerStart('entitesUpdatedSince: notes diff')
   const notesDiff = cacheDiff(notes, cache.value.noteIds, {
     cacheUpdatedAt,
   })
+  timerEnd('entitesUpdatedSince: notes diff')
+  timerStart('entitesUpdatedSince: tags diff')
   const tagsDiff = cacheDiff(tags, cache.value.tagIds, {
     cacheUpdatedAt,
   })
+  timerEnd('entitesUpdatedSince: tags diff')
 
   if (cache._id) {
+    timerStart('entitesUpdatedSince: cache pre-processing (update)')
     if (tagsDiff.added.length) {
       tagsDiff.added = await Tag.find({
         _id: tagsDiff.added.map(({ _id }) => _id),
@@ -112,10 +140,12 @@ export const entitiesUpdatedSince = async (cacheId, user) => {
         .populate('tags')
         .lean()
     }
+    timerEnd('entitesUpdatedSince: cache pre-processing (update)')
   }
 
   let cacheIdWritten
   if (cache._id) {
+    timerStart('entitesUpdatedSince: cache (update)')
     await updateCacheFromDiff(user, cache._id, 'noteIds', notesDiff)
     await updateCacheFromDiff(user, cache._id, 'tagIds', tagsDiff)
 
@@ -128,13 +158,17 @@ export const entitiesUpdatedSince = async (cacheId, user) => {
       },
     )
     cacheIdWritten = cache._id
+    timerEnd('entitesUpdatedSince: cache (update)')
   } else {
+    timerStart('entitesUpdatedSince: cache (pristine)')
     const cacheWriteValue = {
       noteIds: notesDiff.added.map(({ _id }) => _id),
       tagIds: tagsDiff.added.map(({ _id }) => _id),
     }
+    const t_cache = new Date().getTime()
     cacheIdWritten = (await new Cache({ value: cacheWriteValue, user }).save())
       ._id
+    timerEnd('entitesUpdatedSince: cache (pristine)')
   }
 
   timerEnd('entitiesUpdatedSince', "Complete Method 'Entities Updated Since'")

server/lib/notes/notesMethods.ts

@@ -1,10 +1,13 @@
 import { decode } from 'html-entities'
 import { JSDOM } from 'jsdom'
+import { Types } from 'mongoose'
 import fetch from 'node-fetch'
 import { Tag } from '../tags/tagModel'
 import { basePermissionsQueryOnTags } from '../tags/tagsMethods'
 import { Link } from './notesModels'
 
+const { ObjectId } = Types
+
 export function submitLink(user, { url, title, description }) {
   return new Link({
     url,
@@ -66,8 +69,8 @@ export const baseNotesQuery = async (user, mode = 'read') => {
   return {
     tags: {
       $in: [
-        user.internal.ownershipTagId,
-        ...tagIdsWithNoteReadPermissionAndSharing,
+        new ObjectId(user.internal.ownershipTagId),
+        ...tagIdsWithNoteReadPermissionAndSharing.map(({ _id }) => _id),
       ],
     },
   }

server/lib/notes/notesResolvers.ts

@@ -16,12 +16,20 @@ import { logger } from '../util/logging'
 
 const INoteResolvers = {
   async tags(note, args, context) {
+    if (note.tags) {
+      return note.tags.filter(tag => tag.permissions[context.user._id].tag.read)
+    }
+
     return Tag.find({
       ...baseTagsQuery(context.user, 'read'),
       _id: { $in: note.tags },
     }).lean()
   },
   async user(note, args, context) {
+    if (note.user && note.user._id) {
+      return note.user
+    }
+
     return getCachedUser(note.user, context.user)
   },
 }

server/lib/tags/tagsResolvers.ts

@@ -28,8 +28,11 @@ export const tagsResolvers = {
       const notes = await Note.find({ tags: tag, deletedAt: null }).lean()
       return leanTypeEnumFixer(notes)
     },
-    async user(note, args, context) {
-      return getCachedUser(note.user, context.user)
+    async user(tag, args, context) {
+      if (tag.user && tag.user._id) {
+        return tag.user
+      }
+      return getCachedUser(tag.user, context.user)
     },
     permissions(tag, { onlyMine }: TagPermissionsArgs, { user }, info) {
       // todo: investigate