chore: add performance logger (#4896)

Add more performance log to debug loading problem

packages/common/debug/src/index.ts

@@ -58,4 +58,9 @@ export class DebugLogger {
     this._debug.log = console[level].bind(console);
     this._debug(`[${level.toUpperCase()}] ${message}`, ...args);
   }
+
+  namespace(extra: string) {
+    const currentNamespace = this._debug.namespace;
+    return new DebugLogger(`${currentNamespace}:${extra}`);
+  }
 }

packages/frontend/core/src/app.tsx

@@ -14,8 +14,10 @@ import { RouterProvider } from 'react-router-dom';
 
 import { CloudSessionProvider } from './providers/session-provider';
 import { router } from './router';
+import { performanceLogger, performanceRenderLogger } from './shared';
 import createEmotionCache from './utils/create-emotion-cache';
 
+const performanceI18nLogger = performanceLogger.namespace('i18n');
 const cache = createEmotionCache();
 
 const DevTools = lazy(() =>
@@ -37,16 +39,23 @@ const future = {
 
 async function loadLanguage() {
   if (environment.isBrowser) {
+    performanceI18nLogger.info('start');
+
     const { createI18n, setUpLanguage } = await import('@affine/i18n');
     const i18n = createI18n();
     document.documentElement.lang = i18n.language;
+
+    performanceI18nLogger.info('set up');
     await setUpLanguage(i18n);
+    performanceI18nLogger.info('done');
   }
 }
 
 const languageLoadingPromise = loadLanguage().catch(console.error);
 
 export const App = memo(function App() {
+  performanceRenderLogger.info('App');
+
   use(languageLoadingPromise);
   return (
     <CacheProvider value={cache}>

packages/frontend/core/src/bootstrap/setup.ts

@@ -23,6 +23,9 @@ import { nanoid } from 'nanoid';
 import { applyUpdate, Doc as YDoc, encodeStateAsUpdate } from 'yjs';
 
 import { WorkspaceAdapters } from '../adapters/workspace';
+import { performanceLogger } from '../shared';
+
+const performanceSetupLogger = performanceLogger.namespace('setup');
 
 async function tryMigration() {
   const value = localStorage.getItem('jotai-workspaces');
@@ -148,6 +151,7 @@ export function createFirstAppData(store: ReturnType<typeof createStore>) {
 }
 
 export async function setup(store: ReturnType<typeof createStore>) {
+  performanceSetupLogger.info('start');
   store.set(
     workspaceAdaptersAtom,
     WorkspaceAdapters as Record<
@@ -156,11 +160,15 @@ export async function setup(store: ReturnType<typeof createStore>) {
     >
   );
 
-  console.log('setup global');
+  performanceSetupLogger.info('setup global');
   setupGlobal();
 
+  performanceSetupLogger.info('try migration');
   await tryMigration();
+
+  performanceSetupLogger.info('get root workspace meta');
   // do not read `rootWorkspacesMetadataAtom` before migration
   await store.get(rootWorkspacesMetadataAtom);
-  console.log('setup done');
+
+  performanceSetupLogger.info('done');
 }

packages/frontend/core/src/index.tsx

@@ -5,18 +5,28 @@ import { StrictMode, Suspense } from 'react';
 import { createRoot } from 'react-dom/client';
 
 import { bootstrapPluginSystem } from './bootstrap/register-plugins';
+import { performanceLogger } from './shared';
 
+const performanceMainLogger = performanceLogger.namespace('main');
 async function main() {
+  performanceMainLogger.info('start');
   const { setup } = await import('./bootstrap/setup');
+
   const rootStore = getCurrentStore();
+  performanceMainLogger.info('setup start');
   await setup(rootStore);
+  performanceMainLogger.info('setup done');
+
   bootstrapPluginSystem(rootStore).catch(err => {
     console.error('Failed to bootstrap plugin system', err);
   });
+
+  performanceMainLogger.info('import app');
   const { App } = await import('./app');
   const root = document.getElementById('app');
   assertExists(root);
 
+  performanceMainLogger.info('render app');
   createRoot(root).render(
     <StrictMode>
       <Suspense fallback={<WorkspaceFallback key="AppLoading" />}>

packages/frontend/core/src/pages/workspace/all-page.tsx

@@ -40,6 +40,7 @@ import { WorkspaceHeader } from '../../components/workspace-header';
 import { useBlockSuiteMetaHelper } from '../../hooks/affine/use-block-suite-meta-helper';
 import { useTrashModalHelper } from '../../hooks/affine/use-trash-modal-helper';
 import { useCurrentWorkspace } from '../../hooks/current/use-current-workspace';
+import { performanceRenderLogger } from '../../shared';
 import * as styles from './all-page.css';
 import { EmptyPageList } from './page-list-empty';
 import { useFilteredPageMetas } from './pages';
@@ -302,5 +303,7 @@ export const AllPage = () => {
 };
 
 export const Component = () => {
+  performanceRenderLogger.info('AllPage');
+
   return <AllPage />;
 };

packages/frontend/core/src/pages/workspace/detail-page.tsx

@@ -29,6 +29,7 @@ import { WorkspaceHeader } from '../../components/workspace-header';
 import { useRegisterBlocksuiteEditorCommands } from '../../hooks/affine/use-register-blocksuite-editor-commands';
 import { useCurrentWorkspace } from '../../hooks/current/use-current-workspace';
 import { useNavigateHelper } from '../../hooks/use-navigate-helper';
+import { performanceRenderLogger } from '../../shared';
 
 const DetailPageImpl = (): ReactElement => {
   const { openPage, jumpToSubPath } = useNavigateHelper();
@@ -145,5 +146,7 @@ export const loader: LoaderFunction = async args => {
 };
 
 export const Component = () => {
+  performanceRenderLogger.info('DetailPage');
+
   return <DetailPage />;
 };

packages/frontend/core/src/pages/workspace/index.tsx

@@ -15,10 +15,17 @@ import {
 } from 'react-router-dom';
 
 import { WorkspaceLayout } from '../../layouts/workspace-layout';
+import { performanceLogger, performanceRenderLogger } from '../../shared';
+
+const workspaceLoaderLogger = performanceLogger.namespace('workspace_loader');
 
 export const loader: LoaderFunction = async args => {
+  workspaceLoaderLogger.info('start');
+
   const rootStore = getCurrentStore();
   const meta = await rootStore.get(rootWorkspacesMetadataAtom);
+  workspaceLoaderLogger.info('meta loaded');
+
   const currentMetadata = meta.find(({ id }) => id === args.params.workspaceId);
   if (!currentMetadata) {
     return redirect('/404');
@@ -32,6 +39,8 @@ export const loader: LoaderFunction = async args => {
   }
   if (currentMetadata.flavour === WorkspaceFlavour.AFFINE_CLOUD) {
     const [workspaceAtom] = getBlockSuiteWorkspaceAtom(currentMetadata.id);
+    workspaceLoaderLogger.info('get cloud workspace atom');
+
     const workspace = await rootStore.get(workspaceAtom);
     return (() => {
       const blockVersions = workspace.meta.blockVersions;
@@ -46,10 +55,14 @@ export const loader: LoaderFunction = async args => {
       return false;
     })();
   }
+
+  workspaceLoaderLogger.info('done');
   return null;
 };
 
 export const Component = (): ReactElement => {
+  performanceRenderLogger.info('WorkspaceLayout');
+
   const incompatible = useLoaderData();
   return (
     <WorkspaceLayout incompatible={!!incompatible}>

packages/frontend/core/src/shared/index.ts

@@ -1,3 +1,4 @@
+import { DebugLogger } from '@affine/debug';
 import type { WorkspaceRegistry } from '@affine/env/workspace';
 import { Workspace as BlockSuiteWorkspace } from '@blocksuite/store';
 
@@ -26,3 +27,6 @@ export const pathGenerator = {
 } satisfies {
   [Path in WorkspaceSubPath]: (workspaceId: string) => string;
 };
+
+export const performanceLogger = new DebugLogger('performance');
+export const performanceRenderLogger = performanceLogger.namespace('render');

packages/frontend/workspace/src/affine/sync.ts

@@ -1,3 +1,4 @@
+import { DebugLogger } from '@affine/debug';
 import { createIndexeddbStorage } from '@blocksuite/store';
 import {
   createIndexedDBDatasource,
@@ -12,6 +13,7 @@ import { createCloudBlobStorage } from '../blob/cloud-blob-storage';
 import { createAffineDataSource } from '.';
 import { CRUD } from './crud';
 
+const performanceLogger = new DebugLogger('performance:sync');
 let abortController: AbortController | undefined;
 
 const downloadRootFromIndexedDB = async (
@@ -29,9 +31,13 @@ const downloadRootFromIndexedDB = async (
 };
 
 export async function startSync() {
+  performanceLogger.info('start');
+
   abortController = new AbortController();
   const signal = abortController.signal;
   const workspaces = await CRUD.list();
+  performanceLogger.info('CRUD list');
+
   const syncDocPromises = workspaces.map(workspace =>
     downloadRootFromIndexedDB(
       workspace.id,
@@ -40,6 +46,8 @@ export async function startSync() {
     )
   );
   await Promise.all(syncDocPromises);
+  performanceLogger.info('all sync promise');
+
   const syncPromises = workspaces.map(workspace => {
     const remoteDataSource = createAffineDataSource(
       workspace.id,
@@ -104,6 +112,7 @@ export async function startSync() {
     });
   });
   await Promise.all([...syncPromises, ...syncBlobPromises]);
+  performanceLogger.info('sync done');
 }
 
 export async function stopSync() {

packages/frontend/workspace/src/atom.ts

@@ -1,3 +1,4 @@
+import { DebugLogger } from '@affine/debug';
 import type { WorkspaceAdapter } from '@affine/env/workspace';
 import { WorkspaceFlavour } from '@affine/env/workspace';
 import type { BlockHub } from '@blocksuite/blocks';
@@ -12,6 +13,8 @@ import { z } from 'zod';
 
 import { getOrCreateWorkspace } from './manager';
 
+const performanceJotaiLogger = new DebugLogger('performance:jotai');
+
 const rootWorkspaceMetadataV1Schema = z.object({
   id: z.string(),
   flavour: z.nativeEnum(WorkspaceFlavour),
@@ -80,6 +83,8 @@ type FetchMetadata = (
  * @internal
  */
 const fetchMetadata: FetchMetadata = async (get, { signal }) => {
+  performanceJotaiLogger.info('fetch metadata start');
+
   const WorkspaceAdapters = get(workspaceAdaptersAtom);
   assertExists(WorkspaceAdapters, 'workspace adapter should be defined');
   const metadata: RootWorkspaceMetadata[] = [];
@@ -120,6 +125,7 @@ const fetchMetadata: FetchMetadata = async (get, { signal }) => {
           once: true,
         });
       });
+      performanceJotaiLogger.info('migration done');
     }
 
     metadata.push(...loadFromLocalStorage());
@@ -131,11 +137,15 @@ const fetchMetadata: FetchMetadata = async (get, { signal }) => {
     );
 
     for (const Adapter of Adapters) {
+      performanceJotaiLogger.info('%s adapter', Adapter.flavour);
+
       const { CRUD, flavour: currentFlavour } = Adapter;
       if (
         Adapter.Events['app:access'] &&
         !(await Adapter.Events['app:access']())
       ) {
+        performanceJotaiLogger.info('%s app:access', Adapter.flavour);
+
         // skip the adapter if the user doesn't have access to it
         const removed = metadata.filter(
           meta => meta.flavour === currentFlavour
@@ -148,6 +158,7 @@ const fetchMetadata: FetchMetadata = async (get, { signal }) => {
       }
       try {
         const item = await CRUD.list();
+        performanceJotaiLogger.info('%s CRUD list', Adapter.flavour);
         // remove the metadata that is not in the list
         //  because we treat the workspace adapter as the source of truth
         {
@@ -179,6 +190,7 @@ const fetchMetadata: FetchMetadata = async (get, { signal }) => {
       } catch (e) {
         console.error('list data error:', e);
       }
+      performanceJotaiLogger.info('%s service:start', Adapter.flavour);
       Adapter.Events['service:start']?.();
     }
   }
@@ -195,7 +207,7 @@ const fetchMetadata: FetchMetadata = async (get, { signal }) => {
     }
   });
   const result = Array.from(metadataMap.values());
-  console.info('metadata', result);
+  performanceJotaiLogger.info('fetch metadata done', result);
   return result;
 };