feat(debug): Add timing information about time to first image/all images, and query time

extensions/cornerstone/src/init.tsx

@@ -28,6 +28,7 @@ import interleaveTopToBottom from './utils/interleaveTopToBottom';
 import initContextMenu from './initContextMenu';
 import initDoubleClick from './initDoubleClick';
 import { CornerstoneServices } from './types';
+import initViewTiming from './utils/initViewTiming';
 
 // TODO: Cypress tests are currently grabbing this from the window?
 window.cornerstone = cornerstone;
@@ -235,6 +236,8 @@ export default async function init({
     element.addEventListener(EVENTS.CAMERA_RESET, resetCrosshairs);
 
     eventTarget.addEventListener(EVENTS.STACK_VIEWPORT_NEW_STACK, newStackCallback);
+
+    initViewTiming({ element, eventTarget });
   }
 
   function elementDisabledHandler(evt) {

extensions/cornerstone/src/utils/initViewTiming.ts

@@ -0,0 +1,45 @@
+import { log, Types } from '@ohif/core';
+import { EVENTS } from '@cornerstonejs/core';
+
+const { TimingEnum } = Types;
+
+const IMAGE_TIMING_KEYS = [
+  TimingEnum.DISPLAY_SETS_TO_ALL_IMAGES,
+  TimingEnum.DISPLAY_SETS_TO_FIRST_IMAGE,
+  TimingEnum.STUDY_TO_FIRST_IMAGE,
+];
+
+const imageTiming = {
+  viewportsWaiting: 0,
+};
+
+/**
+ * Defines the initial view timing reporting.
+ * This allows knowing how many viewports are waiting for initial views and
+ * when the IMAGE_RENDERED gets sent out.
+ * The first image rendered will fire the FIRST_IMAGE timeEnd logs, while
+ * the last of the enabled viewport will fire the ALL_IMAGES timeEnd logs.
+ *
+ */
+
+export default function initViewTiming({ element }) {
+  if (!IMAGE_TIMING_KEYS.find(key => log.timingKeys[key])) {
+    return;
+  }
+  imageTiming.viewportsWaiting += 1;
+  element.addEventListener(EVENTS.IMAGE_RENDERED, imageRenderedListener);
+}
+
+function imageRenderedListener(evt) {
+  if (evt.detail.viewportStatus === 'preRender') {
+    return;
+  }
+  log.timeEnd(TimingEnum.DISPLAY_SETS_TO_FIRST_IMAGE);
+  log.timeEnd(TimingEnum.STUDY_TO_FIRST_IMAGE);
+  log.timeEnd(TimingEnum.SCRIPT_TO_VIEW);
+  imageTiming.viewportsWaiting -= 1;
+  evt.detail.element.removeEventListener(EVENTS.IMAGE_RENDERED, imageRenderedListener);
+  if (!imageTiming.viewportsWaiting) {
+    log.timeEnd(TimingEnum.DISPLAY_SETS_TO_ALL_IMAGES);
+  }
+}

platform/app/public/html-templates/index.html

@@ -42,6 +42,10 @@
       name="msapplication-config"
       content="<%= PUBLIC_URL %>assets/browserconfig.xml"
     />
+    <script type="text/javascript">
+      console.time('scriptToView');
+      window.PUBLIC_URL = '<%= PUBLIC_URL %>';
+    </script>
     <link
       rel="manifest"
       href="<%= PUBLIC_URL %>manifest.json"
@@ -183,9 +187,6 @@
     <!-- Targets IE11 -->
     <!-- <script
     src="https://polyfill.io/v3/polyfill.min.js?flags=gated&features=default%2CObject.values%2CArray.prototype.flat%2CObject.entries%2CSymbol%2CArray.prototype.includes%2CString.prototype.repeat%2CArray.prototype.find"></script>!-->
-    <script type="text/javascript">
-      window.PUBLIC_URL = '<%= PUBLIC_URL %>';
-    </script>
     <script
       rel="preload"
       as="script"

platform/app/src/routes/DataSourceWrapper.tsx

@@ -1,13 +1,15 @@
 /* eslint-disable react/jsx-props-no-spreading */
 import React, { useCallback, useEffect, useState } from 'react';
 import PropTypes from 'prop-types';
-import { ExtensionManager, MODULE_TYPES } from '@ohif/core';
+import { ExtensionManager, MODULE_TYPES, Types, log } from '@ohif/core';
 //
 import { extensionManager } from '../App.tsx';
 import { useParams, useLocation } from 'react-router';
 import { useNavigate } from 'react-router-dom';
 import useSearchParams from '../hooks/useSearchParams.ts';
 
+const { TimingEnum } = Types;
+
 /**
  * Determines if two React Router location objects are the same.
  */
@@ -149,7 +151,7 @@ function DataSourceWrapper(props) {
     // 204: no content
     async function getData() {
       setIsLoading(true);
-
+      log.time(TimingEnum.SEARCH_TO_LIST);
       const studies = await dataSource.query.studies.search(queryFilterValues);
 
       setData({
@@ -159,6 +161,8 @@ function DataSourceWrapper(props) {
         pageNumber: queryFilterValues.pageNumber,
         location,
       });
+      log.timeEnd(TimingEnum.SCRIPT_TO_VIEW);
+      log.timeEnd(TimingEnum.SEARCH_TO_LIST);
 
       setIsLoading(false);
     }

platform/app/src/routes/Mode/Mode.tsx

@@ -2,7 +2,7 @@ import React, { useEffect, useState, useRef } from 'react';
 import { useParams, useLocation, useNavigate } from 'react-router';
 import PropTypes from 'prop-types';
 // TODO: DicomMetadataStore should be injected?
-import { DicomMetadataStore, ServicesManager, utils } from '@ohif/core';
+import { DicomMetadataStore, ServicesManager, utils, Types, log } from '@ohif/core';
 import { DragAndDropProvider, ImageViewerProvider } from '@ohif/ui';
 import { useSearchParams } from '@hooks';
 import { useAppConfig } from '@state';
@@ -14,6 +14,7 @@ import loadModules from '../../pluginImports';
 import isSeriesFilterUsed from '../../utils/isSeriesFilterUsed';
 
 const { getSplitParam } = utils;
+const { TimingEnum } = Types;
 
 /**
  * Initialize the route.
@@ -60,6 +61,8 @@ function defaultRouteInit(
 
   unsubscriptions.push(instanceAddedUnsubscribe);
 
+  log.time(TimingEnum.STUDY_TO_DISPLAY_SETS);
+  log.time(TimingEnum.STUDY_TO_FIRST_IMAGE);
   const allRetrieves = studyInstanceUIDs.map(StudyInstanceUID =>
     dataSource.retrieve.series.metadata({
       StudyInstanceUID,
@@ -81,6 +84,9 @@ function defaultRouteInit(
   // until we run the hanging protocol matching service.
 
   Promise.allSettled(allRetrieves).then(() => {
+    log.timeEnd(TimingEnum.STUDY_TO_DISPLAY_SETS);
+    log.time(TimingEnum.DISPLAY_SETS_TO_FIRST_IMAGE);
+    log.time(TimingEnum.DISPLAY_SETS_TO_ALL_IMAGES);
     const displaySets = displaySetService.getActiveDisplaySets();
 
     if (!displaySets || !displaySets.length) {
@@ -443,7 +449,7 @@ export default function ModeRoute({
     <ImageViewerProvider
       // initialState={{ StudyInstanceUIDs: StudyInstanceUIDs }}
       StudyInstanceUIDs={studyInstanceUIDs}
-    // reducer={reducer}
+      // reducer={reducer}
     >
       <CombinedContextProvider>
         <DragAndDropProvider>

platform/core/src/log.js

@@ -4,8 +4,23 @@ const log = {
   info: console.log,
   trace: console.trace,
   debug: console.debug,
-  time: console.time,
-  timeEnd: console.timeEnd,
+  time: key => {
+    log.timingKeys[key] = true;
+    console.time(key);
+  },
+  timeEnd: key => {
+    if (!log.timingKeys[key]) {
+      return;
+    }
+    log.timingKeys[key] = false;
+    console.timeEnd(key);
+  },
+  // Store the timing keys to allow knowing whether or not to log events
+  timingKeys: {
+    // script time values are added before log is loaded, and the log
+    // shouldn't depend on the enums, so for this case recreate the string.
+    scriptToView: true,
+  },
 };
 
 export default log;

platform/core/src/types/TimingEnum.ts

@@ -0,0 +1,8 @@
+export enum TimingEnum {
+  STUDY_TO_DISPLAY_SETS = 'studyToDisplaySetsLoaded',
+  STUDY_TO_FIRST_IMAGE = 'studyToFirstImage',
+  DISPLAY_SETS_TO_FIRST_IMAGE = 'displaySetsToFirstImage',
+  DISPLAY_SETS_TO_ALL_IMAGES = 'displaySetsToAllImages',
+  SCRIPT_TO_VIEW = 'scriptToView',
+  SEARCH_TO_LIST = 'searchToList',
+}

platform/core/src/types/index.ts

@@ -19,6 +19,9 @@ export * from './PanelModule';
 export * from './IPubSub';
 export * from './Color';
 
+// Enum exports
+export * from './TimingEnum';
+
 /**
  * Export the types used within the various services and managers, but
  * not the services/managers themselves, which are exported at the top level.