From 0ecd72ec97eadc0a5746a5e6dff510716cf8bda4 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Nacho=20Codo=C3=B1er?= Date: Mon, 10 Feb 2025 17:44:29 +0100 Subject: [PATCH 01/11] ensure some stage profiling are considered async to keep track of them --- tools/project-context.js | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/tools/project-context.js b/tools/project-context.js index 60f5ae794a..192b3558db 100644 --- a/tools/project-context.js +++ b/tools/project-context.js @@ -318,7 +318,7 @@ Object.assign(ProjectContext.prototype, { * * @return {Promise<*|undefined>} */ - readProjectMetadata: function () { + readProjectMetadata: async function () { // don't generate a profiling report for this stage (Profile.run), // because all we do here is read a handful of files. return this._completeStagesThrough(STAGE.READ_PROJECT_METADATA); @@ -328,7 +328,7 @@ Object.assign(ProjectContext.prototype, { * @return {Promise<*|undefined>} */ initializeCatalog: function () { - return Profile.run('ProjectContext initializeCatalog', () => { + return Profile.run('ProjectContext initializeCatalog', async () => { return this._completeStagesThrough(STAGE.INITIALIZE_CATALOG); }); }, @@ -337,7 +337,7 @@ Object.assign(ProjectContext.prototype, { * @return {Promise<*|undefined>} */ resolveConstraints: function () { - return Profile.run('ProjectContext resolveConstraints', () => { + return Profile.run('ProjectContext resolveConstraints', async () => { return this._completeStagesThrough(STAGE.RESOLVE_CONSTRAINTS); }); }, @@ -347,7 +347,7 @@ Object.assign(ProjectContext.prototype, { * @return {Promise<*|undefined>} */ downloadMissingPackages: function () { - return Profile.run('ProjectContext downloadMissingPackages', () => { + return Profile.run('ProjectContext downloadMissingPackages', async () => { return this._completeStagesThrough(STAGE.DOWNLOAD_MISSING_PACKAGES); }); }, @@ -356,7 +356,7 @@ Object.assign(ProjectContext.prototype, { * @return {Promise<*|undefined>} */ buildLocalPackages: function () { - return Profile.run('ProjectContext buildLocalPackages', () => { + return Profile.run('ProjectContext buildLocalPackages', async () => { return this._completeStagesThrough(STAGE.BUILD_LOCAL_PACKAGES); }); }, @@ -365,7 +365,7 @@ Object.assign(ProjectContext.prototype, { * @return {Promise<*|undefined>} */ saveChangedMetadata: function () { - return Profile.run('ProjectContext saveChangedMetadata', () => { + return Profile.run('ProjectContext saveChangedMetadata', async () => { return this._completeStagesThrough(STAGE.SAVE_CHANGED_METADATA); }); }, @@ -376,7 +376,7 @@ Object.assign(ProjectContext.prototype, { prepareProjectForBuild: function () { // This is the same as saveChangedMetadata, but if we insert stages after // that one it will continue to mean "fully finished". - return Profile.run('ProjectContext prepareProjectForBuild', () => { + return Profile.run('ProjectContext prepareProjectForBuild', async () => { return this._completeStagesThrough(STAGE.SAVE_CHANGED_METADATA); }); }, From ec80e8d746c45ded6fc5b8581ba50d2ca73707f5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Nacho=20Codo=C3=B1er?= Date: Tue, 18 Feb 2025 15:27:21 +0100 Subject: [PATCH 02/11] support async context on profiler async actions --- tools/tool-env/profile.ts | 79 +++++++++++++++++++++++++-------------- 1 file changed, 50 insertions(+), 29 deletions(-) diff --git a/tools/tool-env/profile.ts b/tools/tool-env/profile.ts index 9bbef2cbe4..28cd3183d8 100644 --- a/tools/tool-env/profile.ts +++ b/tools/tool-env/profile.ts @@ -160,7 +160,9 @@ // B: 250.0 // // In both reports the grand total is 600ms. +import { AsyncLocalStorage } from 'async_hooks'; +const asyncLocalStorage = new AsyncLocalStorage(); const filter = parseFloat(process.env.METEOR_PROFILE || "100"); // ms @@ -230,7 +232,6 @@ function decodeEntryKey(key: string) { return key.split('\t'); } -const globalEntry: string[] = []; let running = false; export function Profile< @@ -238,47 +239,67 @@ export function Profile< TResult, >( bucketName: string | ((...args: TArgs) => string), - f: (...args: TArgs) => TResult, + f: (...args: TArgs) => TResult | Promise, ): typeof f { if (! Profile.enabled) { return f; } return Object.assign(function profileWrapper(this: any) { - if (! running) { - return f.apply(this, arguments as any); + const args = arguments as unknown as TArgs; // Capture the arguments passed to the function + + if (!running) { + return f.apply(this, args); } - const name = typeof bucketName === "function" - ? bucketName.apply(this, arguments as any) - : bucketName; + const existingStore = asyncLocalStorage.getStore(); - // TODO Test with Profile / use __METEOR_ASYNC_LOCAL_STORAGE - //const currentStore = asyncLo - // const currentEntry = Fiber.current - // ? Fiber.current.profilerEntry || (Fiber.current.profilerEntry = []) - // : globalEntry; - const currentEntry = globalEntry; - - currentEntry.push(name); - const key = encodeEntryKey(currentEntry); - const start = process.hrtime(); - try { - return f.apply(this, arguments as any); - } finally { - const elapsed = process.hrtime(start); - const stats = (bucketStats[key] || (bucketStats[key] = { - time: 0.0, - count: 0, - isOther: false, - })); - stats.time += (elapsed[0] * 1000 + elapsed[1] / 1000000); - stats.count++; - currentEntry.pop(); + // If a context already exists, reuse it, otherwise, create a new one. + if (existingStore) { + return runWithContext(bucketName, existingStore, f, this, args); } + + return asyncLocalStorage.run([], () => runWithContext(bucketName, [], f, this, args)); }, f) as typeof f; } +async function runWithContext( + bucketName: string | ((...args: TArgs) => string), + currentEntry: string[], + f: (...args: TArgs) => TResult | Promise, + context: any, + args: IArguments, // Using `arguments` type here +): Promise { + const name = typeof bucketName === "function" ? bucketName.apply(context, args) : bucketName; + currentEntry.push(name); + const key = encodeEntryKey(currentEntry); + const start = process.hrtime(); + + try { + const result = f.apply(context, args); + console.log("=>(profile.ts:280) result", result, result instanceof Promise); + + if (result instanceof Promise) { + return result.finally(() => finalizeProfiling(key, start, currentEntry)); + } + return result; + } finally { + finalizeProfiling(key, start, currentEntry); + } +} + +function finalizeProfiling(key: string, start: [number, number], currentEntry: string[]) { + const elapsed = process.hrtime(start); + const stats = (bucketStats[key] || (bucketStats[key] = { + time: 0.0, + count: 0, + isOther: false, + })); + stats.time += elapsed[0] * 1000 + elapsed[1] / 1_000_000; + stats.count++; + currentEntry.pop(); +} + export namespace Profile { export let enabled = !! process.env.METEOR_PROFILE; From b16c8cb6d6802d72795bd2d2b6592ad1523bf5c5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Nacho=20Codo=C3=B1er?= Date: Tue, 18 Feb 2025 15:51:00 +0100 Subject: [PATCH 03/11] correct async support on profiler --- tools/tool-env/profile.ts | 18 +++++++++++------- 1 file changed, 11 insertions(+), 7 deletions(-) diff --git a/tools/tool-env/profile.ts b/tools/tool-env/profile.ts index 28cd3183d8..a946321f36 100644 --- a/tools/tool-env/profile.ts +++ b/tools/tool-env/profile.ts @@ -246,7 +246,7 @@ export function Profile< } return Object.assign(function profileWrapper(this: any) { - const args = arguments as unknown as TArgs; // Capture the arguments passed to the function + const args = arguments as unknown as TArgs; if (!running) { return f.apply(this, args); @@ -254,7 +254,7 @@ export function Profile< const existingStore = asyncLocalStorage.getStore(); - // If a context already exists, reuse it, otherwise, create a new one. + // If a context already exists, reuse it; otherwise, create a new one. if (existingStore) { return runWithContext(bucketName, existingStore, f, this, args); } @@ -263,13 +263,13 @@ export function Profile< }, f) as typeof f; } -async function runWithContext( +function runWithContext( bucketName: string | ((...args: TArgs) => string), currentEntry: string[], f: (...args: TArgs) => TResult | Promise, context: any, - args: IArguments, // Using `arguments` type here -): Promise { + args: IArguments, +): TResult | Promise { const name = typeof bucketName === "function" ? bucketName.apply(context, args) : bucketName; currentEntry.push(name); const key = encodeEntryKey(currentEntry); @@ -277,14 +277,18 @@ async function runWithContext( try { const result = f.apply(context, args); - console.log("=>(profile.ts:280) result", result, result instanceof Promise); if (result instanceof Promise) { + // Return a promise if async return result.finally(() => finalizeProfiling(key, start, currentEntry)); } + + // Return directly if sync return result; } finally { - finalizeProfiling(key, start, currentEntry); + if (!(f.apply(context, args) instanceof Promise)) { + finalizeProfiling(key, start, currentEntry); + } } } From b0426df46d65c72ad24ac84bd4a069045b33ea9b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Nacho=20Codo=C3=B1er?= Date: Tue, 18 Feb 2025 16:01:03 +0100 Subject: [PATCH 04/11] reuse meteor tool als context --- tools/tool-env/profile.ts | 31 ++++++++++++++++++------------- 1 file changed, 18 insertions(+), 13 deletions(-) diff --git a/tools/tool-env/profile.ts b/tools/tool-env/profile.ts index a946321f36..d5605e3733 100644 --- a/tools/tool-env/profile.ts +++ b/tools/tool-env/profile.ts @@ -160,9 +160,7 @@ // B: 250.0 // // In both reports the grand total is 600ms. -import { AsyncLocalStorage } from 'async_hooks'; - -const asyncLocalStorage = new AsyncLocalStorage(); +const { makeGlobalAsyncLocalStorage } = require("../utils/fiber-helpers"); const filter = parseFloat(process.env.METEOR_PROFILE || "100"); // ms @@ -252,27 +250,34 @@ export function Profile< return f.apply(this, args); } - const existingStore = asyncLocalStorage.getStore(); + const asyncLocalStorage = makeGlobalAsyncLocalStorage(); + let existingStore = asyncLocalStorage.getStore(); - // If a context already exists, reuse it; otherwise, create a new one. - if (existingStore) { - return runWithContext(bucketName, existingStore, f, this, args); + // Ensure `existingStore` is an object, initialize it if not present + if (!existingStore) { + existingStore = { currentEntry: [] }; + return asyncLocalStorage.run(existingStore, () => runWithContext(bucketName, existingStore, f, this, args)); } - return asyncLocalStorage.run([], () => runWithContext(bucketName, [], f, this, args)); + // Ensure `existingStore.currentEntry` exists + if (!existingStore.currentEntry) { + existingStore.currentEntry = []; + } + + return runWithContext(bucketName, existingStore, f, this, args); }, f) as typeof f; } function runWithContext( bucketName: string | ((...args: TArgs) => string), - currentEntry: string[], + store: { currentEntry: string[]; [key: string]: any }, // Keep other properties intact f: (...args: TArgs) => TResult | Promise, context: any, args: IArguments, ): TResult | Promise { const name = typeof bucketName === "function" ? bucketName.apply(context, args) : bucketName; - currentEntry.push(name); - const key = encodeEntryKey(currentEntry); + store.currentEntry.push(name); + const key = encodeEntryKey(store.currentEntry); const start = process.hrtime(); try { @@ -280,14 +285,14 @@ function runWithContext( if (result instanceof Promise) { // Return a promise if async - return result.finally(() => finalizeProfiling(key, start, currentEntry)); + return result.finally(() => finalizeProfiling(key, start, store.currentEntry)); } // Return directly if sync return result; } finally { if (!(f.apply(context, args) instanceof Promise)) { - finalizeProfiling(key, start, currentEntry); + finalizeProfiling(key, start, store.currentEntry); } } } From 1de4c5e19033a7cfa3d80863ee267dc54efb2f8c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Nacho=20Codo=C3=B1er?= Date: Tue, 18 Feb 2025 17:23:46 +0100 Subject: [PATCH 05/11] avoid issue that runs the profiler function twice --- tools/tool-env/profile.ts | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/tools/tool-env/profile.ts b/tools/tool-env/profile.ts index d5605e3733..407f66b496 100644 --- a/tools/tool-env/profile.ts +++ b/tools/tool-env/profile.ts @@ -280,8 +280,9 @@ function runWithContext( const key = encodeEntryKey(store.currentEntry); const start = process.hrtime(); + let result: TResult | Promise; try { - const result = f.apply(context, args); + result = f.apply(context, args); if (result instanceof Promise) { // Return a promise if async @@ -291,9 +292,7 @@ function runWithContext( // Return directly if sync return result; } finally { - if (!(f.apply(context, args) instanceof Promise)) { - finalizeProfiling(key, start, store.currentEntry); - } + finalizeProfiling(key, start, store.currentEntry); } } From 7ab17e6de3e93523a782d95157856a12966785fe Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Nacho=20Codo=C3=B1er?= Date: Tue, 18 Feb 2025 17:28:29 +0100 Subject: [PATCH 06/11] avoid issue to properly finish on sync and async cases --- tools/tool-env/profile.ts | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/tools/tool-env/profile.ts b/tools/tool-env/profile.ts index 407f66b496..151294fcf6 100644 --- a/tools/tool-env/profile.ts +++ b/tools/tool-env/profile.ts @@ -292,7 +292,9 @@ function runWithContext( // Return directly if sync return result; } finally { - finalizeProfiling(key, start, store.currentEntry); + if (!(result instanceof Promise)) { + finalizeProfiling(key, start, store.currentEntry); + } } } From 47104bf9f240d91a8a7089dc547ff93b53285855 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Nacho=20Codo=C3=B1er?= Date: Tue, 18 Feb 2025 18:17:34 +0100 Subject: [PATCH 07/11] fix require error --- tools/tool-env/profile.ts | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/tools/tool-env/profile.ts b/tools/tool-env/profile.ts index 151294fcf6..efde9463ae 100644 --- a/tools/tool-env/profile.ts +++ b/tools/tool-env/profile.ts @@ -160,7 +160,6 @@ // B: 250.0 // // In both reports the grand total is 600ms. -const { makeGlobalAsyncLocalStorage } = require("../utils/fiber-helpers"); const filter = parseFloat(process.env.METEOR_PROFILE || "100"); // ms @@ -250,7 +249,7 @@ export function Profile< return f.apply(this, args); } - const asyncLocalStorage = makeGlobalAsyncLocalStorage(); + const asyncLocalStorage = global.__METEOR_ASYNC_LOCAL_STORAGE; let existingStore = asyncLocalStorage.getStore(); // Ensure `existingStore` is an object, initialize it if not present From d87f47345041013b299ed494fc071d94ed2f3ba5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Nacho=20Codo=C3=B1er?= Date: Wed, 19 Feb 2025 16:32:13 +0100 Subject: [PATCH 08/11] dont mutate current entry --- tools/tool-env/profile.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tools/tool-env/profile.ts b/tools/tool-env/profile.ts index efde9463ae..10328e067f 100644 --- a/tools/tool-env/profile.ts +++ b/tools/tool-env/profile.ts @@ -275,7 +275,7 @@ function runWithContext( args: IArguments, ): TResult | Promise { const name = typeof bucketName === "function" ? bucketName.apply(context, args) : bucketName; - store.currentEntry.push(name); + store.currentEntry = [...store.currentEntry || [], name]; const key = encodeEntryKey(store.currentEntry); const start = process.hrtime(); From 7b5702d2f788dd7fbf51b2f8503fc3e3602810b7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Nacho=20Codo=C3=B1er?= Date: Wed, 19 Feb 2025 16:40:14 +0100 Subject: [PATCH 09/11] reuse existing async local storage context --- tools/static-assets/server/boot.js | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/tools/static-assets/server/boot.js b/tools/static-assets/server/boot.js index e6d0a7eb89..11d1d001b0 100644 --- a/tools/static-assets/server/boot.js +++ b/tools/static-assets/server/boot.js @@ -498,8 +498,10 @@ var runMain = Profile("Run main()", async function () { global.__METEOR_ASYNC_LOCAL_STORAGE = new AsyncLocalStorage(); } - await Profile.run('Server startup', function() { - return global.__METEOR_ASYNC_LOCAL_STORAGE.run({}, async () => { + await Profile.run('Server startup', async function() { + const asyncLocalStorage = global.__METEOR_ASYNC_LOCAL_STORAGE; + let existingStore = asyncLocalStorage.getStore(); + return global.__METEOR_ASYNC_LOCAL_STORAGE.run(existingStore || {}, async () => { await loadServerBundles(); await callStartupHooks(); await runMain(); From e8f64f0cb613401d1d3e5c3fc09d3a156eddf25f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Nacho=20Codo=C3=B1er?= Date: Wed, 19 Feb 2025 16:40:54 +0100 Subject: [PATCH 10/11] use const --- tools/static-assets/server/boot.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tools/static-assets/server/boot.js b/tools/static-assets/server/boot.js index 11d1d001b0..1cee390bee 100644 --- a/tools/static-assets/server/boot.js +++ b/tools/static-assets/server/boot.js @@ -500,7 +500,7 @@ var runMain = Profile("Run main()", async function () { await Profile.run('Server startup', async function() { const asyncLocalStorage = global.__METEOR_ASYNC_LOCAL_STORAGE; - let existingStore = asyncLocalStorage.getStore(); + const existingStore = asyncLocalStorage.getStore(); return global.__METEOR_ASYNC_LOCAL_STORAGE.run(existingStore || {}, async () => { await loadServerBundles(); await callStartupHooks(); From 1a497a0ecd22bec5ee622119f9c327090f974f79 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Nacho=20Codo=C3=B1er?= Date: Mon, 24 Feb 2025 14:22:04 +0100 Subject: [PATCH 11/11] remove als initialization as part of server startup --- tools/static-assets/server/boot.js | 10 +++------- 1 file changed, 3 insertions(+), 7 deletions(-) diff --git a/tools/static-assets/server/boot.js b/tools/static-assets/server/boot.js index 1cee390bee..43c2668bde 100644 --- a/tools/static-assets/server/boot.js +++ b/tools/static-assets/server/boot.js @@ -499,13 +499,9 @@ var runMain = Profile("Run main()", async function () { } await Profile.run('Server startup', async function() { - const asyncLocalStorage = global.__METEOR_ASYNC_LOCAL_STORAGE; - const existingStore = asyncLocalStorage.getStore(); - return global.__METEOR_ASYNC_LOCAL_STORAGE.run(existingStore || {}, async () => { - await loadServerBundles(); - await callStartupHooks(); - await runMain(); - }); + await loadServerBundles(); + await callStartupHooks(); + await runMain(); }); })().catch(e => { console.log('error on boot.js', e )