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

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;
@@ -284,6 +285,8 @@ export default async function init({
     element.addEventListener(EVENTS.CAMERA_RESET, resetCrosshairs);
 
     eventTarget.addEventListener(EVENTS.STACK_VIEWPORT_NEW_STACK, toolbarEventListener);
+
+    initViewTiming({ element, eventTarget });
   }
 
   function elementDisabledHandler(evt) {
@@ -305,8 +308,8 @@ export default async function init({
   viewportGridService.subscribe(
     viewportGridService.EVENTS.ACTIVE_VIEWPORT_ID_CHANGED,
     activeViewportEventListener
-  );
-}
+      );
+    }
 
 function CPUModal() {
   return (

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);
+  }
+}

extensions/default/src/getDisplaySetMessages.ts

@@ -13,22 +13,23 @@ export default function getDisplaySetMessages(
   isReconstructable: boolean
 ): DisplaySetMessageList {
   const messages = new DisplaySetMessageList();
-  if (!instances.length) {
+  const firstInstance = instances[0];
+  if (!instances.length || firstInstance) {
     messages.addMessage(DisplaySetMessage.CODES.NO_VALID_INSTANCES);
+    return;
   }
 
-  const firstInstance = instances[0];
+  const { Modality, ImageType, NumberOfFrames } = firstInstance;
   // Due to current requirements, LOCALIZER series doesn't have any messages
-  if (firstInstance?.ImageType?.includes('LOCALIZER')) {
+  if (ImageType?.includes('LOCALIZER')) {
     return messages;
   }
 
-  const Modality = firstInstance.Modality;
   if (!constructableModalities.includes(Modality)) {
     return messages;
   }
 
-  const isMultiframe = firstInstance.NumberOfFrames > 1;
+  const isMultiframe = NumberOfFrames > 1;
   // Can't reconstruct if all instances don't have the ImagePositionPatient.
   if (!isMultiframe && !instances.every(instance => instance.ImagePositionPatient)) {
     messages.addMessage(DisplaySetMessage.CODES.NO_POSITION_INFORMATION);

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) {

platform/core/src/log.js

@@ -4,8 +4,25 @@ 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 during the index.html initial load,
+    // before log (this file) is loaded, and the log
+    // can't depend on the enums, so for this case recreate the string.
+    // See TimingEnum for details
+    scriptToView: true,
+  },
 };
 
 export default log;

platform/core/src/types/TimingEnum.ts

@@ -0,0 +1,24 @@
+export enum TimingEnum {
+  // The time from when the users selects a study until the study metadata
+  // is loaded (and the display sets are ready)
+  STUDY_TO_DISPLAY_SETS = 'studyToDisplaySetsLoaded',
+
+  // The time from when the user selects a study until any viewport renders
+  STUDY_TO_FIRST_IMAGE = 'studyToFirstImage',
+
+  // The time from when display sets are loaded until any viewport renders
+  // an image.
+  DISPLAY_SETS_TO_FIRST_IMAGE = 'displaySetsToFirstImage',
+
+  // The time from when display sets are loaded until all viewports have images
+  DISPLAY_SETS_TO_ALL_IMAGES = 'displaySetsToAllImages',
+
+  // The time from when the user hits search until the worklist is displayed
+  SEARCH_TO_LIST = 'searchToList',
+
+  // The time from when the html script first starts being evaluated (before
+  // any other scripts or CSS is loaded), until the time that the first image
+  // is viewed for viewer endpoints, or the time that the first search for studies
+  // completes.
+  SCRIPT_TO_VIEW = 'scriptToView',
+}

platform/core/src/types/index.ts

@@ -19,6 +19,9 @@ export type * from './PanelModule';
 export type * from './IPubSub';
 export type * 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.

platform/core/src/utils/metadataProvider/getPixelSpacingInformation.js

@@ -78,9 +78,12 @@ export default function getPixelSpacingInformation(instance) {
         pixelSpacing => pixelSpacing / EstimatedRadiographicMagnificationFactor
       );
     } else {
-      log.info(
-        'EstimatedRadiographicMagnificationFactor was not present. Unable to correct ImagerPixelSpacing.'
-      );
+      if (!instance._loggedSpacingMessage) {
+        log.info(
+          'EstimatedRadiographicMagnificationFactor was not present. Unable to correct ImagerPixelSpacing.'
+        );
+        instance._loggedSpacingMessage = true;
+      }
     }
 
     return {