UBERF-7690: Operation log support + fixes

packages/core/src/measurements/context.ts

@@ -1,7 +1,16 @@
 // Basic performance metrics suite.
 
+import { generateId } from '../utils'
 import { childMetrics, measure, newMetrics } from './metrics'
-import { FullParamsType, MeasureContext, MeasureLogger, Metrics, ParamsType } from './types'
+import {
+  FullParamsType,
+  MeasureContext,
+  MeasureLogger,
+  Metrics,
+  ParamsType,
+  type OperationLog,
+  type OperationLogEntry
+} from './types'
 
 /**
  * @public
@@ -98,21 +107,29 @@ export class MeasureMetricsContext implements MeasureContext {
     )
   }
 
-  async with<T>(
+  with<T>(
     name: string,
     params: ParamsType,
     op: (ctx: MeasureContext) => T | Promise<T>,
     fullParams?: ParamsType | (() => FullParamsType)
   ): Promise<T> {
     const c = this.newChild(name, params, fullParams, this.logger)
+    let needFinally = true
     try {
-      let value = op(c)
-      if (value instanceof Promise) {
-        value = await value
+      const value = op(c)
+      if (value != null && value instanceof Promise) {
+        needFinally = false
+        void value.finally(() => {
+          c.end()
+        })
+        return value
+      } else {
+        return Promise.resolve(value)
       }
-      return value
     } finally {
-      c.end()
+      if (needFinally) {
+        c.end()
+      }
     }
   }
 
@@ -176,3 +193,96 @@ export function withContext (name: string, params: ParamsType = {}): any {
     return descriptor
   }
 }
+
+let operationProfiling = false
+
+export function setOperationLogProfiling (value: boolean): void {
+  operationProfiling = value
+}
+
+export function registerOperationLog (ctx: MeasureContext): { opLogMetrics?: Metrics, op?: OperationLog } {
+  if (!operationProfiling) {
+    return {}
+  }
+  const op: OperationLog = { start: Date.now(), ops: [], end: -1 }
+  let opLogMetrics: Metrics | undefined
+  ctx.id = generateId()
+  if (ctx.metrics !== undefined) {
+    if (ctx.metrics.opLog === undefined) {
+      ctx.metrics.opLog = {}
+    }
+    ctx.metrics.opLog[ctx.id] = op
+    opLogMetrics = ctx.metrics
+  }
+  return { opLogMetrics, op }
+}
+
+export function updateOperationLog (opLogMetrics: Metrics | undefined, op: OperationLog | undefined): void {
+  if (!operationProfiling) {
+    return
+  }
+  if (op !== undefined) {
+    op.end = Date.now()
+  }
+  // We should keep only longest one entry
+  if (opLogMetrics?.opLog !== undefined) {
+    const entries = Object.entries(opLogMetrics.opLog)
+
+    const incomplete = entries.filter((it) => it[1].end === -1)
+    const complete = entries.filter((it) => it[1].end !== -1)
+    complete.sort((a, b) => a[1].start - b[1].start)
+    if (complete.length > 30) {
+      complete.splice(0, complete.length - 30)
+    }
+
+    opLogMetrics.opLog = Object.fromEntries(incomplete.concat(complete))
+  }
+}
+
+export function addOperation<T> (
+  ctx: MeasureContext,
+  name: string,
+  params: ParamsType,
+  op: (ctx: MeasureContext) => Promise<T>,
+  fullParams?: FullParamsType
+): Promise<T> {
+  if (!operationProfiling) {
+    return op(ctx)
+  }
+  let opEntry: OperationLogEntry | undefined
+
+  let p: MeasureContext | undefined = ctx
+  let opLogMetrics: Metrics | undefined
+  let id: string | undefined
+
+  while (p !== undefined) {
+    if (p.metrics?.opLog !== undefined) {
+      opLogMetrics = p.metrics
+    }
+    if (id === undefined && p.id !== undefined) {
+      id = p.id
+    }
+    p = p.parent
+  }
+  const opLog = id !== undefined ? opLogMetrics?.opLog?.[id] : undefined
+
+  if (opLog !== undefined) {
+    opEntry = {
+      op: name,
+      start: Date.now(),
+      params: {},
+      end: -1
+    }
+  }
+  const result = op(ctx)
+  if (opEntry !== undefined && opLog !== undefined) {
+    void result.finally(() => {
+      if (opEntry !== undefined && opLog !== undefined) {
+        opEntry.end = Date.now()
+        opEntry.params = { ...params, ...(typeof fullParams === 'function' ? fullParams() : fullParams) }
+        opLog.ops.push(opEntry)
+      }
+    })
+  }
+  return result
+}

packages/core/src/measurements/metrics.ts

@@ -161,7 +161,8 @@ export function metricsAggregate (m: Metrics, limit: number = -1): Metrics {
     params: m.params,
     value: sumVal,
     topResult: m.topResult,
-    namedParams: m.namedParams
+    namedParams: m.namedParams,
+    opLog: m.opLog
   }
 }
 

packages/core/src/measurements/types.ts

@@ -25,13 +25,27 @@ export interface MetricsData {
   }[]
 }
 
+export interface OperationLogEntry {
+  op: string
+  params: ParamsType
+  start: number
+  end: number
+}
+export interface OperationLog {
+  ops: OperationLogEntry[]
+  start: number
+  end: number
+}
+
 /**
  * @public
  */
 export interface Metrics extends MetricsData {
   namedParams: ParamsType
   params: Record<string, Record<string, MetricsData>>
   measurements: Record<string, Metrics>
+
+  opLog?: Record<string, OperationLog>
 }
 
 /**
@@ -53,9 +67,12 @@ export interface MeasureLogger {
  * @public
  */
 export interface MeasureContext {
+  id?: string
   // Create a child metrics context
   newChild: (name: string, params: ParamsType, fullParams?: FullParamsType, logger?: MeasureLogger) => MeasureContext
 
+  metrics?: Metrics
+
   with: <T>(
     name: string,
     params: ParamsType,

packages/core/src/server.ts

@@ -48,6 +48,9 @@ export interface SessionOperationContext {
     op: (ctx: SessionOperationContext) => T | Promise<T>,
     fullParams?: FullParamsType
   ) => Promise<T>
+
+  contextCache: Map<string, any>
+  removedMap: Map<Ref<Doc>, Doc>
 }
 
 /**

packages/query/src/index.ts

@@ -312,15 +312,22 @@ export class LiveQuery implements WithTx, Client {
     return this.clone(q.result)[0] as WithLookup<T>
   }
 
+  private optionsCompare (opt1?: FindOptions<Doc>, opt2?: FindOptions<Doc>): boolean {
+    const { ctx: _1, ..._opt1 } = (opt1 ?? {}) as any
+    const { ctx: _2, ..._opt2 } = (opt2 ?? {}) as any
+    return deepEqual(_opt1, _opt2)
+  }
+
   private findQuery<T extends Doc>(
     _class: Ref<Class<T>>,
     query: DocumentQuery<T>,
     options?: FindOptions<T>
   ): Query | undefined {
     const queries = this.queries.get(_class)
     if (queries === undefined) return
+
     for (const q of queries) {
-      if (!deepEqual(query, q.query) || !deepEqual(options, q.options)) continue
+      if (!deepEqual(query, q.query) || !this.optionsCompare(options, q.options)) continue
       return q
     }
   }

plugins/workbench-resources/src/components/statistics/MetricsInfo.svelte

@@ -40,7 +40,7 @@
         <Button
           label={getEmbeddedLabel('*')}
           on:click={() => {
-            showPopup(Params, { params: metrics.namedParams ?? {} })
+            showPopup(Params, { params: metrics.namedParams ?? {}, opLog: metrics.opLog }, 'full')
           }}
           kind={'ghost'}
         />

plugins/workbench-resources/src/components/statistics/Params.svelte

@@ -13,27 +13,65 @@
 // limitations under the License.
 -->
 <script lang="ts">
+  import type { OperationLog, OperationLogEntry } from '@hcengineering/core'
   import presentation from '@hcengineering/presentation'
   import { Button, FocusHandler, createFocusManager } from '@hcengineering/ui'
   import { createEventDispatcher } from 'svelte'
 
   export let params: Record<string, any>
+  export let opLog: Record<string, OperationLog> | undefined
 
   const dispatch = createEventDispatcher()
 
   const manager = createFocusManager()
+
+  function toEntries (entries: OperationLogEntry[]): OperationLogEntry[] {
+    entries.sort((a, b) => a.start - b.start)
+    // make relative times
+
+    if (entries.length > 0) {
+      const min = entries[0].start
+      entries.forEach((it) => {
+        it.start -= min
+        it.end -= min
+      })
+    }
+
+    return entries
+  }
+
+  $: entries = toEntries(
+    Object.values(opLog ?? {})
+      .map((it, i) => it.ops.map((q) => ({ ...q, op: `#${i} ${q.op}` })))
+      .flat()
+  )
 </script>
 
 <FocusHandler {manager} />
 
-<div class="msgbox-container">
+<div class="msgbox-container w-full select-text">
   <div class="overflow-label fs-title mb-4"></div>
   <div class="message no-word-wrap" style:overflow={'auto'}>
     {#each Object.entries(params) as kv}
       <div class="flex-row-center">
         {kv[0]}: {typeof kv[1] === 'object' ? JSON.stringify(kv[1]) : kv[1]}
       </div>
     {/each}
+    {#each entries as op, i}
+      {@const hasOverlap = i > 1 && entries.slice(0, i).some((it) => it.end > op.start)}
+      {@const hasOverlapDown = i > 0 && entries.slice(i + 1).some((it) => it.start < op.end)}
+      <div class="flex-row-center select-text" style:background-color={hasOverlap || hasOverlapDown ? 'yellow' : ''}>
+        {op.op}
+        {#if hasOverlap}
+          ⬆️
+        {/if}
+
+        {#if hasOverlapDown}
+          ⬇️
+        {/if}
+        {JSON.stringify(op.params)} - {op.start} - {op.end} - ({op.end - op.start})
+      </div>
+    {/each}
   </div>
   <div class="footer">
     <Button
@@ -54,8 +92,9 @@
     display: flex;
     flex-direction: column;
     padding: 2rem 1.75rem 1.75rem;
-    width: 30rem;
-    max-width: 40rem;
+    width: 100%;
+    max-width: 100%;
+    overflow: auto;
     background: var(--theme-popup-color);
     border-radius: 0.5rem;
     user-select: none;

pods/server/package.json

@@ -8,7 +8,7 @@
   "template": "@hcengineering/node-package",
   "license": "EPL-2.0",
   "scripts": {
-    "start": "rush bundle --to @hcengineering/pod-server && cross-env NODE_ENV=production ELASTIC_INDEX_NAME=local_storage_index MODEL_VERSION=$(node ../../common/scripts/show_version.js) ACCOUNTS_URL=http://localhost:3000 REKONI_URL=http://localhost:4004 MONGO_URL=mongodb://localhost:27017 ELASTIC_URL=http://localhost:9200 FRONT_URL=http://localhost:8087 UPLOAD_URL=/upload MINIO_ENDPOINT=localhost MINIO_ACCESS_KEY=minioadmin MINIO_SECRET_KEY=minioadmin METRICS_CONSOLE=true SERVER_SECRET=secret node --inspect --enable-source-maps bundle/bundle.js",
+    "start": "rush bundle --to @hcengineering/pod-server && cross-env NODE_ENV=production ELASTIC_INDEX_NAME=local_storage_index MODEL_VERSION=$(node ../../common/scripts/show_version.js) ACCOUNTS_URL=http://localhost:3000 REKONI_URL=http://localhost:4004 MONGO_URL=mongodb://localhost:27017 ELASTIC_URL=http://localhost:9200 FRONT_URL=http://localhost:8087 UPLOAD_URL=/upload MINIO_ENDPOINT=localhost MINIO_ACCESS_KEY=minioadmin MINIO_SECRET_KEY=minioadmin METRICS_CONSOLE=true SERVER_SECRET=secret OPERATION_PROFILING=false node --inspect --enable-source-maps bundle/bundle.js",
     "start-u": "rush bundle --to @hcengineering/pod-server && cp ./node_modules/@hcengineering/uws/lib/*.node ./bundle/ && cross-env NODE_ENV=production SERVER_PROVIDER=uweb ELASTIC_INDEX_NAME=local_storage_index MODEL_VERSION=$(node ../../common/scripts/show_version.js) ACCOUNTS_URL=http://localhost:3000 REKONI_URL=http://localhost:4004 MONGO_URL=mongodb://localhost:27017 ELASTIC_URL=http://localhost:9200 FRONT_URL=http://localhost:8087 UPLOAD_URL=/upload MINIO_ENDPOINT=localhost MINIO_ACCESS_KEY=minioadmin MINIO_SECRET_KEY=minioadmin METRICS_CONSOLE=true SERVER_SECRET=secret node --inspect bundle/bundle.js",
     "start-flame": "rush bundle --to @hcengineering/pod-server && cross-env NODE_ENV=production ELASTIC_INDEX_NAME=local_storage_index MODEL_VERSION=$(node ../../common/scripts/show_version.js) ACCOUNTS_URL=http://localhost:3000 REKONI_URL=http://localhost:4004 MONGO_URL=mongodb://localhost:27017 ELASTIC_URL=http://localhost:9200 FRONT_URL=http://localhost:8087 UPLOAD_URL=/upload MINIO_ENDPOINT=localhost MINIO_ACCESS_KEY=minioadmin MINIO_SECRET_KEY=minioadmin METRICS_CONSOLE=true SERVER_SECRET=secret clinic flame --dest ./out -- node --nolazy -r ts-node/register --enable-source-maps src/__start.ts",
     "build": "compile",

pods/server/src/__start.ts

@@ -5,7 +5,7 @@
 // Add this to the VERY top of the first file loaded in your app
 import { Analytics } from '@hcengineering/analytics'
 import contactPlugin from '@hcengineering/contact'
-import { MeasureMetricsContext, newMetrics } from '@hcengineering/core'
+import { MeasureMetricsContext, newMetrics, setOperationLogProfiling } from '@hcengineering/core'
 import notification from '@hcengineering/notification'
 import { setMetadata } from '@hcengineering/platform'
 import { getMetricsContext, serverConfigFromEnv } from '@hcengineering/server'
@@ -39,6 +39,8 @@ getMetricsContext(
     )
 )
 
+setOperationLogProfiling(process.env.OPERATION_PROFILING === 'true')
+
 const config = serverConfigFromEnv()
 const storageConfig: StorageConfiguration = storageConfigFromEnv()
 

server-plugins/love-resources/src/index.ts

@@ -150,7 +150,7 @@ export async function OnUserStatus (tx: Tx, control: TriggerControl): Promise<Tx
 }
 
 async function roomJoinHandler (info: ParticipantInfo, control: TriggerControl): Promise<Tx[]> {
-  const roomInfos = await control.queryFind(love.class.RoomInfo, {})
+  const roomInfos = await control.queryFind(control.ctx, love.class.RoomInfo, {})
   const roomInfo = roomInfos.find((ri) => ri.room === info.room)
   if (roomInfo !== undefined) {
     roomInfo.persons.push(info.person)
@@ -174,7 +174,7 @@ async function roomJoinHandler (info: ParticipantInfo, control: TriggerControl):
 
 async function rejectJoinRequests (info: ParticipantInfo, control: TriggerControl): Promise<Tx[]> {
   const res: Tx[] = []
-  const roomInfos = await control.queryFind(love.class.RoomInfo, {})
+  const roomInfos = await control.queryFind(control.ctx, love.class.RoomInfo, {})
   const oldRoomInfo = roomInfos.find((ri) => ri.persons.includes(info.person))
   if (oldRoomInfo !== undefined) {
     const restPersons = oldRoomInfo.persons.filter((p) => p !== info.person)
@@ -197,7 +197,7 @@ async function rejectJoinRequests (info: ParticipantInfo, control: TriggerContro
 
 async function setDefaultRoomAccess (info: ParticipantInfo, control: TriggerControl): Promise<Tx[]> {
   const res: Tx[] = []
-  const roomInfos = await control.queryFind(love.class.RoomInfo, {})
+  const roomInfos = await control.queryFind(control.ctx, love.class.RoomInfo, {})
   const oldRoomInfo = roomInfos.find((ri) => ri.persons.includes(info.person))
   if (oldRoomInfo !== undefined) {
     oldRoomInfo.persons = oldRoomInfo.persons.filter((p) => p !== info.person)

server-plugins/notification-resources/src/utils.ts

@@ -146,7 +146,7 @@ export async function isAllowed (
   type: BaseNotificationType,
   provider: NotificationProvider
 ): Promise<boolean> {
-  const providersSettings = await control.queryFind(notification.class.NotificationProviderSetting, {
+  const providersSettings = await control.queryFind(control.ctx, notification.class.NotificationProviderSetting, {
     space: core.space.Workspace
   })
   const providerSetting = providersSettings.find(
@@ -167,7 +167,7 @@ export async function isAllowed (
     return false
   }
 
-  const typesSettings = await control.queryFind(notification.class.NotificationTypeSetting, {
+  const typesSettings = await control.queryFind(control.ctx, notification.class.NotificationTypeSetting, {
     space: core.space.Workspace
   })
   const setting = typesSettings.find(