Merge pull request #972 from Aukevanoost/fix/performance-metrics

fix(nf): Added debug timers

Author: Aukevanoost

libs/native-federation-core/src/lib/core/build-for-federation.ts

@@ -36,13 +36,16 @@ export async function buildForFederation(
   let artefactInfo: ArtefactInfo | undefined;
 
   if (!buildParams.skipMappingsAndExposed) {
-    var start = process.hrtime();
+    let start = process.hrtime();
     artefactInfo = await bundleExposedAndMappings(
       config,
       fedOptions,
       externals
     );
-    logDuration(start, 'To bundle all mappings and exposed.');
+    logger.measure(
+      start,
+      '[build artifacts] - To bundle all mappings and exposed.'
+    );
   }
 
   const exposedInfo = !artefactInfo
@@ -53,41 +56,57 @@ export async function buildForFederation(
     const { sharedBrowser, sharedServer, separateBrowser, separateServer } =
       splitShared(config.shared);
 
-    var start = process.hrtime();
-
+    let start = process.hrtime();
     const sharedPackageInfoBrowser = await bundleShared(
       sharedBrowser,
       config,
       fedOptions,
       externals,
       'browser'
     );
+    logger.measure(
+      start,
+      '[build artifacts] - To bundle all shared browser externals'
+    );
 
+    start = process.hrtime();
     const sharedPackageInfoServer = await bundleShared(
       sharedServer,
       config,
       fedOptions,
       externals,
       'node'
     );
+    logger.measure(
+      start,
+      '[build artifacts] - To bundle all shared node externals'
+    );
 
+    start = process.hrtime();
     const separatePackageInfoBrowser = await bundleSeparate(
       separateBrowser,
       externals,
       config,
       fedOptions,
       'browser'
     );
+    logger.measure(
+      start,
+      '[build artifacts] - To bundle all separate browser externals'
+    );
 
+    start = process.hrtime();
     const separatePackageInfoServer = await bundleSeparate(
       separateServer,
       externals,
       config,
       fedOptions,
       'node'
     );
-
-    logDuration(start, 'To bundle all dependencies');
+    logger.measure(
+      start,
+      '[build artifacts] - To bundle all separate node externals'
+    );
 
     sharedPackageInfoCache = [
       ...sharedPackageInfoBrowser,
@@ -126,11 +145,6 @@ type SplitSharedResult = {
   separateServer: Record<string, NormalizedSharedConfig>;
 };
 
-function logDuration(start: [number, number], msg: string) {
-  var [seconds, milliseconds] = process.hrtime(start);
-  logger.debug(`${seconds}s:${milliseconds.toFixed(3)}ms - ${msg}`);
-}
-
 function inferPackageFromSecondary(secondary: string): string {
   const parts = secondary.split('/');
   if (secondary.startsWith('@') && parts.length >= 2) {

libs/native-federation-core/src/lib/utils/logger.ts

@@ -13,6 +13,24 @@ export const logger = {
     verbose && console.log(chalk.bgGreen.ansi256(15)(' DBG! '), msg),
   debug: (msg: any) =>
     verbose && console.log(chalk.bgGreen.ansi256(15)(' DBG! '), msg),
+  measure: (start: [number, number], milestone: string) => {
+    if (!verbose) return;
+
+    const [totalSeconds, nanoseconds] = process.hrtime(start);
+    const minutes = Math.floor(totalSeconds / 60);
+    const seconds = totalSeconds % 60;
+    const milliseconds = nanoseconds / 1000000;
+
+    const msFormatted = milliseconds.toFixed(3);
+    const timeStr = `${minutes.toString().padStart(2, '0')}:${seconds
+      .toString()
+      .padStart(2, '0')}:${msFormatted.padStart(7, '0')}ms`;
+
+    console.log(
+      chalk.bgGreen.ansi256(15)(' DBG! '),
+      `${timeStr} - ${milestone}`
+    );
+  },
 };
 
 export const setLogLevel = (level: string) => {

libs/native-federation/src/builders/build/builder.ts

@@ -228,7 +228,10 @@ export async function* runBuilder(
 
   const activateSsr = nfOptions.ssr && !nfOptions.dev;
 
+  let start = process.hrtime();
   const config = await loadFederationConfig(fedOptions);
+  logger.measure(start, 'To load the federation config.');
+
   const externals = getExternals(config);
   const plugins = [
     createSharedMappingsPlugin(config.sharedMappings),
@@ -322,8 +325,11 @@ export async function* runBuilder(
 
   let federationResult: FederationInfo;
   try {
+    let start = process.hrtime();
     federationResult = await buildForFederation(config, fedOptions, externals);
+    logger.measure(start, 'To build the artifacts.');
   } catch (e) {
+    logger.error(e?.message ?? 'Building the artifacts failed');
     process.exit(1);
   }
 
@@ -333,12 +339,15 @@ export async function* runBuilder(
 
   const hasLocales = i18n?.locales && Object.keys(i18n.locales).length > 0;
   if (hasLocales && localeFilter) {
+    let start = process.hrtime();
+
     translateFederationArtefacts(
       i18n,
       localeFilter,
       outputOptions.base,
       federationResult
     );
+    logger.measure(start, 'To translate the artifacts.');
   }
 
   options.deleteOutputPath = false;
@@ -392,6 +401,7 @@ export async function* runBuilder(
       if (!first && (nfOptions.dev || watch)) {
         setTimeout(async () => {
           try {
+            let start = process.hrtime();
             federationResult = await buildForFederation(
               config,
               fedOptions,
@@ -417,6 +427,7 @@ export async function* runBuilder(
             if (isLocalDevelopment) {
               federationBuildNotifier.broadcastBuildCompletion();
             }
+            logger.measure(start, 'To rebuild nf.');
           } catch (error) {
             logger.error('Federation rebuild failed!');