perf(theme): add debug log (#245)

plugins/plugin-md-power/src/node/enhance/imageSize.ts

@@ -6,7 +6,7 @@ import http from 'node:https'
 import { URL } from 'node:url'
 import { isLinkExternal, isLinkHttp } from '@vuepress/helper'
 import imageSize from 'image-size'
-import { fs, path } from 'vuepress/utils'
+import { fs, logger, path } from 'vuepress/utils'
 import { resolveAttrs } from '../utils/resolveAttrs.js'
 
 interface ImgSize {
@@ -36,10 +36,14 @@ export async function imageSizePlugin(
     return
 
   if (type === 'all') {
+    const start = performance.now()
     try {
       await scanRemoteImageSize(app)
     }
     catch {}
+    if (app.env.isDebug) {
+      logger.info(`[vuepress-plugin-md-power] imageSizePlugin: scan all images time spent: ${performance.now() - start}ms`)
+    }
   }
 
   const imageRule = md.renderer.rules.image!

theme/src/node/autoFrontmatter/generator.ts

@@ -13,6 +13,7 @@ import grayMatter from 'gray-matter'
 import jsonToYaml from 'json2yaml'
 import { fs, hash, path } from 'vuepress/utils'
 import { getThemeConfig } from '../loadConfig/index.js'
+import { logger } from '../utils/index.js'
 import { readMarkdown, readMarkdownList } from './readFile.js'
 import { resolveOptions } from './resolveOptions.js'
 
@@ -87,6 +88,7 @@ export function initAutoFrontmatter(
 }
 
 export async function generateAutoFrontmatter(app: App) {
+  const start = performance.now()
   if (!generate)
     return
 
@@ -106,6 +108,10 @@ export async function generateAutoFrontmatter(app: App) {
   )
 
   await generate.updateCache(app)
+
+  if (app.env.isDebug) {
+    logger.info(`Generate auto frontmatter: ${(performance.now() - start).toFixed(2)}ms`)
+  }
 }
 
 export async function watchAutoFrontmatter(app: App, watchers: any[]) {

theme/src/node/loadConfig/loader.ts

@@ -5,6 +5,7 @@ import { deepMerge } from '@pengzhanbo/utils'
 import { watch } from 'chokidar'
 import { path } from 'vuepress/utils'
 import { resolveLocaleOptions } from '../config/resolveLocaleOptions.js'
+import { logger } from '../utils/index.js'
 import { compiler } from './compiler.js'
 import { findConfigPath } from './findConfigPath.js'
 
@@ -39,6 +40,7 @@ export async function initConfigLoader(
   defaultConfig: ThemeConfig,
   { configFile, onChange }: InitConfigLoaderOptions = {},
 ) {
+  const start = performance.now()
   const { encrypt, autoFrontmatter, ...localeOptions } = defaultConfig
   loader = {
     configFile,
@@ -55,19 +57,31 @@ export async function initConfigLoader(
     },
   }
 
+  const findStart = performance.now()
   loader.configFile = await findConfigPath(app, configFile)
+  if (app.env.isDebug) {
+    logger.info(`Find config path: ${(performance.now() - findStart).toFixed(2)}ms`)
+  }
 
   if (onChange) {
     loader.changeEvents.push(onChange)
   }
 
+  const loadStart = performance.now()
   const { config, dependencies = [] } = await loader.load()
+  if (app.env.isDebug) {
+    logger.info(`theme config call load: ${(performance.now() - loadStart).toFixed(2)}ms`)
+  }
   loader.loaded = true
   loader.dependencies = [...dependencies]
   updateResolvedConfig(app, config)
 
   loader.whenLoaded.forEach(fn => fn(loader!.resolvedConfig))
   loader.whenLoaded = []
+
+  if (app.env.isDebug) {
+    logger.info(`Load config: ${(performance.now() - start).toFixed(2)}ms`)
+  }
 }
 
 export function watchConfigFile(app: App, watchers: any[], onChange: ChangeEvent) {

theme/src/node/prepare/index.ts

@@ -1,6 +1,7 @@
 import type { App } from 'vuepress'
 import { watch } from 'chokidar'
 import { getThemeConfig } from '../loadConfig/index.js'
+import { logger } from '../utils/index.js'
 import { prepareArticleTagColors } from './prepareArticleTagColor.js'
 import { preparedBlogData } from './prepareBlogData.js'
 import { prepareEncrypt } from './prepareEncrypt.js'
@@ -10,6 +11,7 @@ import { prepareSidebar } from './prepareSidebar.js'
 export async function prepareData(
   app: App,
 ): Promise<void> {
+  const start = performance.now()
   const { localeOptions, encrypt } = getThemeConfig()
   await Promise.all([
     prepareArticleTagColors(app),
@@ -18,6 +20,10 @@ export async function prepareData(
     prepareEncrypt(app, encrypt),
     prepareIcons(app, localeOptions),
   ])
+
+  if (app.env.isDebug) {
+    logger.info(`Prepare data: ${(performance.now() - start).toFixed(2)}ms`)
+  }
 }
 
 export function watchPrepare(

theme/src/node/prepare/prepareArticleTagColor.ts

@@ -1,6 +1,6 @@
 import type { App } from 'vuepress'
 import { toArray } from '@pengzhanbo/utils'
-import { nanoid, resolveContent, writeTemp } from '../utils/index.js'
+import { logger, nanoid, resolveContent, writeTemp } from '../utils/index.js'
 
 export type TagsColorsItem = readonly [
   string, // normal color
@@ -33,9 +33,15 @@ export const PRESET: TagsColorsItem[] = [
 const cache: Record<number, string> = {}
 
 export async function prepareArticleTagColors(app: App): Promise<void> {
+  const start = performance.now()
   const { js, css } = genCode(app)
   await writeTemp(app, 'internal/articleTagColors.css', css)
   await writeTemp(app, 'internal/articleTagColors.js', js)
+  if (app.env.isDebug) {
+    logger.info(
+      `Generate article tag colors: ${(performance.now() - start).toFixed(2)}ms`,
+    )
+  }
 }
 
 export function genCode(app: App): { js: string, css: string } {

theme/src/node/prepare/prepareEncrypt.ts

@@ -3,7 +3,7 @@ import type { Page } from 'vuepress/core'
 import type { PlumeThemeEncrypt, PlumeThemePageData } from '../../shared/index.js'
 import { isNumber, isString, random, toArray } from '@pengzhanbo/utils'
 import { genSaltSync, hashSync } from 'bcrypt-ts'
-import { hash, resolveContent, writeTemp } from '../utils/index.js'
+import { hash, logger, resolveContent, writeTemp } from '../utils/index.js'
 
 export type EncryptConfig = readonly [
   boolean, // global
@@ -18,6 +18,7 @@ const separator = ':'
 let contentHash = ''
 
 export async function prepareEncrypt(app: App, encrypt?: PlumeThemeEncrypt) {
+  const start = performance.now()
   const currentHash = encrypt ? hash(JSON.stringify(encrypt)) : ''
 
   if (!contentHash || contentHash !== currentHash) {
@@ -28,6 +29,9 @@ export async function prepareEncrypt(app: App, encrypt?: PlumeThemeEncrypt) {
     })
     await writeTemp(app, 'internal/encrypt.js', content)
   }
+  if (app.env.isDebug) {
+    logger.info(`Generate encrypt: ${(performance.now() - start).toFixed(2)}ms`)
+  }
 }
 
 const salt = () => genSaltSync(random(8, 16))

theme/src/node/prepare/prepareIcons.ts

@@ -36,6 +36,7 @@ function isIconify(icon: any): icon is string {
 }
 
 export async function prepareIcons(app: App, localeOptions: PlumeThemeLocaleOptions) {
+  const start = performance.now()
   if (!isInstalled) {
     await writeTemp(app, JS_FILENAME, resolveContent(app, { name: 'icons', content: '{}' }))
     return
@@ -54,6 +55,12 @@ export async function prepareIcons(app: App, localeOptions: PlumeThemeLocaleOpti
     collectMap[collect].push(name)
   })
 
+  if (app.env.isDebug) {
+    logger.info(`Generate icons with pages and theme config: ${(performance.now() - start).toFixed(2)}ms`)
+  }
+
+  const collectStart = performance.now()
+
   if (!locate) {
     const mod = await interopDefault(import('@iconify/json'))
     locate = mod.locate
@@ -67,6 +74,10 @@ export async function prepareIcons(app: App, localeOptions: PlumeThemeLocaleOpti
     logger.warn(`[iconify] Unknown icons: ${unknownList.join(', ')}`)
   }
 
+  if (app.env.isDebug) {
+    logger.info(`Generate icons with iconify collect: ${(performance.now() - collectStart).toFixed(2)}ms`)
+  }
+
   let cssCode = ''
   const map: Record<string, string> = {}
   for (const [iconName, { className, content, background }] of entries(cache)) {
@@ -82,6 +93,10 @@ export async function prepareIcons(app: App, localeOptions: PlumeThemeLocaleOpti
       before: `import './iconify.css'`,
     })),
   ])
+
+  if (app.env.isDebug) {
+    logger.info(`Generate icons total time: ${(performance.now() - start).toFixed(2)}ms`)
+  }
 }
 
 function getIconsWithPage(page: Page): string[] {

theme/src/node/prepare/prepareSidebar.ts

@@ -13,12 +13,17 @@ import {
   isPlainObject,
   removeLeadingSlash,
 } from '@vuepress/helper'
-import { normalizeLink, resolveContent, writeTemp } from '../utils/index.js'
+import { logger, normalizeLink, resolveContent, writeTemp } from '../utils/index.js'
 
 export async function prepareSidebar(app: App, localeOptions: PlumeThemeLocaleOptions) {
+  const start = performance.now()
   const sidebar = getAllSidebar(localeOptions)
   sidebar.__auto__ = getSidebarData(app, sidebar)
   await writeTemp(app, 'internal/sidebar.js', resolveContent(app, { name: 'sidebar', content: sidebar }))
+
+  if (app.env.isDebug) {
+    logger.info(`Generate sidebar: ${(performance.now() - start).toFixed(2)}ms`)
+  }
 }
 
 function getSidebarData(

theme/src/node/prepare/prepareThemeData.ts

@@ -2,19 +2,24 @@ import type { App } from 'vuepress'
 import type { PlumeThemeData, PlumeThemeLocaleOptions, PlumeThemePluginOptions } from '../../shared/index.js'
 import { resolveImageSize } from 'vuepress-plugin-md-power'
 import { resolveThemeData } from '../config/resolveThemeData.js'
-import { resolveContent, writeTemp } from '../utils/index.js'
+import { logger, resolveContent, writeTemp } from '../utils/index.js'
 
 export async function prepareThemeData(
   app: App,
   localeOptions: PlumeThemeLocaleOptions,
   pluginOptions: PlumeThemePluginOptions,
 ): Promise<void> {
+  const start = performance.now()
   const resolvedThemeData = resolveThemeData(app, localeOptions)
 
   await resolveProfileImage(app, resolvedThemeData, pluginOptions)
 
   const content = resolveContent(app, { name: 'themeData', content: resolvedThemeData })
   await writeTemp(app, 'internal/themePlumeData.js', content)
+
+  if (app.env.isDebug) {
+    logger.info(`Generate theme data: ${(performance.now() - start).toFixed(2)}ms`)
+  }
 }
 
 async function resolveProfileImage(