async_hooks: create the storage hook only when needed by RaisinTen · Pull Request #40810 · nodejs/node

RaisinTen · 2021-11-14T07:44:24Z

The storage hook got created whenever the async_hooks module was being
required. There is no reason to do that if we don't use the
AsyncLocalStorage class later on.

Signed-off-by: Darshan Sen darshan.sen@postman.com

RaisinTen · 2021-11-14T07:58:01Z

Benchmark CI for async_hooks: https://ci.nodejs.org/job/benchmark-node-micro-benchmarks/1057/

The storage hook got created whenever the `async_hooks` module was being required. There is no reason to do that if we don't use the `AsyncLocalStorage` class later on. Signed-off-by: Darshan Sen <darshan.sen@postman.com>

RaisinTen · 2021-11-20T08:51:54Z

@nodejs/async_hooks review plz. I was also wondering if the benchmarks for async_hooks are known to be this flaky or is there something wrong?

https://ci.nodejs.org/job/benchmark-node-micro-benchmarks/1055/ - pauses forever while trying to execute "old","async_hooks/async-resource-vs-destroy.js","n=1000000 duration=5 connections=500 path='/' asyncMethod='callbacks' type='async-resource' benchmarker='wrk'"
https://ci.nodejs.org/job/benchmark-node-micro-benchmarks/1056/ - pauses forever while trying to execute "new","async_hooks/async-resource-vs-destroy.js","n=1000000 duration=5 connections=500 path='/' asyncMethod='callbacks' type='async-resource' benchmarker='wrk'"
https://ci.nodejs.org/job/benchmark-node-micro-benchmarks/1057/ - pauses forever while trying to execute "new","async_hooks/async-resource-vs-destroy.js","n=1000000 duration=5 connections=500 path='/' asyncMethod='callbacks' type='async-local-storage' benchmarker='wrk'"

vdeturckheim · 2021-11-22T09:49:51Z

I am not sure this is a big change as the hook is disabled until there is a need for it. Also, this makes the code a bit harder to read for me - could we add comments if we go this way?

RaisinTen · 2021-11-22T15:37:01Z

@vdeturckheim I didn't know know how long it took to construct the hook compared to the rest of the things that happen when this module gets loaded, so I guessed that this was the main reason for the overhead #40804 (comment) was talking about. I'm okay with closing this if isn't significant but I would still like to know where the overhead comes from when we load async_hooks. Do you know about it?

vdeturckheim · 2021-11-22T15:42:10Z

I don't know really where the overhead is from, it might be useful to do some profiling here :)

RaisinTen · 2021-11-22T15:51:53Z

Running the profiler, it seems that the overhead is the same as what you get when you load any module and it doesn't have much to do with async_hooks in particular, so yea this change is defo not significant. Closing!

Details

Statistical profiling result from isolate-0x7fc7b5400000-8584-v8.log, (96 ticks, 1 unaccounted, 0 excluded).

 [Shared libraries]:
   ticks  total  nonlib   name
     13   13.5%          /usr/lib/system/libsystem_pthread.dylib
      3    3.1%          /usr/lib/system/libsystem_c.dylib
      2    2.1%          /usr/lib/libc++.1.dylib
      1    1.0%          /usr/lib/system/libsystem_platform.dylib
      1    1.0%          /usr/lib/system/libsystem_malloc.dylib
      1    1.0%          /usr/lib/libobjc.A.dylib

 [JavaScript]:
   ticks  total  nonlib   name

 [C++]:
   ticks  total  nonlib   name
     58   60.4%   77.3%  T node::native_module::NativeModuleLoader::GetModuleIds()
     11   11.5%   14.7%  T __kernelrpc_mach_port_get_refs
      3    3.1%    4.0%  t std::__1::ostreambuf_iterator<char, std::__1::char_traits<char> > std::__1::__pad_and_output<char, std::__1::char_traits<char> >(std::__1::ostreambuf_iterator<char, std::__1::char_traits<char> >, char const*, char const*, char const*, std::__1::ios_base&, char)
      1    1.0%    1.3%  T _task_for_pid
      1    1.0%    1.3%  T ___getrlimit

 [Summary]:
   ticks  total  nonlib   name
      0    0.0%    0.0%  JavaScript
     74   77.1%   98.7%  C++
      1    1.0%    1.3%  GC
     21   21.9%          Shared libraries
      1    1.0%          Unaccounted

 [C++ entry points]:
   ticks    cpp   total   name
     68  100.0%   70.8%  T node::native_module::NativeModuleLoader::GetModuleIds()

 [Bottom up (heavy) profile]:
  Note: percentage shows a share of a particular caller in the total
  amount of its parent calls.
  Callers occupying less than 1.0% are not shown.

   ticks parent  name
     58   60.4%  T node::native_module::NativeModuleLoader::GetModuleIds()
     47   81.0%    T node::native_module::NativeModuleLoader::GetModuleIds()
     26   55.3%      Function: ^compileForInternalLoader node:internal/bootstrap/loaders:299:27
     26  100.0%        Function: ^nativeModuleRequire node:internal/bootstrap/loaders:332:29
      7   26.9%          Function: ~<anonymous> node:internal/webstreams/adapters:1:1
      7  100.0%            Function: ^compileForInternalLoader node:internal/bootstrap/loaders:299:27
      4   15.4%          Function: ~<anonymous> node:internal/webstreams/readablestream:1:1
      4  100.0%            Function: ^compileForInternalLoader node:internal/bootstrap/loaders:299:27
      3   11.5%          Function: ~<anonymous> node:internal/modules/esm/load:1:1
      3  100.0%            Function: ^compileForInternalLoader node:internal/bootstrap/loaders:299:27
      3   11.5%          Function: ~<anonymous> node:internal/modules/esm/get_source:1:1
      3  100.0%            Function: ^compileForInternalLoader node:internal/bootstrap/loaders:299:27
      2    7.7%          Function: ~<anonymous> node:internal/process/esm_loader:1:1
      2  100.0%            Function: ^compileForInternalLoader node:internal/bootstrap/loaders:299:27
      2    7.7%          Function: ~<anonymous> node:internal/modules/esm/loader:1:1
      2  100.0%            Function: ^compileForInternalLoader node:internal/bootstrap/loaders:299:27
      2    7.7%          Function: ~<anonymous> node:internal/fs/promises:1:1
      2  100.0%            Function: ^compileForInternalLoader node:internal/bootstrap/loaders:299:27
      1    3.8%          Function: ~<anonymous> node:internal/modules/esm/resolve:1:1
      1  100.0%            Function: ^compileForInternalLoader node:internal/bootstrap/loaders:299:27
      1    3.8%          Function: ~<anonymous> node:internal/modules/esm/module_map:1:1
      1  100.0%            Function: ^compileForInternalLoader node:internal/bootstrap/loaders:299:27
      1    3.8%          Function: ~<anonymous> node:internal/modules/cjs/loader:1:1
      1  100.0%            LazyCompile: ~compileForInternalLoader node:internal/bootstrap/loaders:299:27
      9   19.1%      LazyCompile: ~compileForInternalLoader node:internal/bootstrap/loaders:299:27
      9  100.0%        LazyCompile: ~nativeModuleRequire node:internal/bootstrap/loaders:332:29
      3   33.3%          LazyCompile: ~initializeCJSLoader node:internal/bootstrap/pre_execution:412:29
      3  100.0%            LazyCompile: ~prepareMainThreadExecution node:internal/bootstrap/pre_execution:22:36
      2   22.2%          Function: ~<anonymous> node:internal/source_map/source_map_cache:1:1
      2  100.0%            LazyCompile: ~compileForInternalLoader node:internal/bootstrap/loaders:299:27
      1   11.1%          LazyCompile: ~setupInspectorHooks node:internal/bootstrap/pre_execution:223:29
      1  100.0%            LazyCompile: ~prepareMainThreadExecution node:internal/bootstrap/pre_execution:22:36
      1   11.1%          LazyCompile: ~initializeSourceMapsHandlers node:internal/bootstrap/pre_execution:451:38
      1  100.0%            LazyCompile: ~prepareMainThreadExecution node:internal/bootstrap/pre_execution:22:36
      1   11.1%          LazyCompile: ~initializeReport node:internal/bootstrap/pre_execution:173:26
      1  100.0%            LazyCompile: ~prepareMainThreadExecution node:internal/bootstrap/pre_execution:22:36
      1   11.1%          Function: ~<anonymous> node:internal/main/run_main_module:1:1
      2    4.3%      LazyCompile: ~realpathSync node:fs:2408:22
      2  100.0%        LazyCompile: ~toRealPath node:internal/modules/cjs/loader:393:20
      2  100.0%          LazyCompile: ~Module._findPath node:internal/modules/cjs/loader:494:28
      2  100.0%            LazyCompile: ~resolveMainPath node:internal/modules/run_main:12:25
      1    2.1%      T node::native_module::NativeModuleLoader::GetModuleIds()
      1  100.0%        LazyCompile: ~Module._findPath node:internal/modules/cjs/loader:494:28
      1  100.0%          LazyCompile: ~resolveMainPath node:internal/modules/run_main:12:25
      1  100.0%            LazyCompile: ~executeUserEntryPoint node:internal/modules/run_main:74:31
      1    2.1%      LazyCompile: ~tryReadSync node:fs:429:21
      1  100.0%        LazyCompile: ~readFileSync node:fs:450:22
      1  100.0%          LazyCompile: ~Module._extensions..js node:internal/modules/cjs/loader:1106:37
      1  100.0%            LazyCompile: ~Module.load node:internal/modules/cjs/loader:963:33
      1    2.1%      LazyCompile: ~resolve node:path:1091:10
      1  100.0%        LazyCompile: ~patchProcessObject node:internal/bootstrap/pre_execution:81:28
      1  100.0%          LazyCompile: ~prepareMainThreadExecution node:internal/bootstrap/pre_execution:22:36
      1  100.0%            Function: ~<anonymous> node:internal/main/run_main_module:1:1
      1    2.1%      LazyCompile: ~getSourceMapsEnabled node:internal/source_map/source_map_cache:43:30
      1  100.0%        LazyCompile: ~maybeCacheSourceMap node:internal/source_map/source_map_cache:74:29
      1  100.0%          LazyCompile: ~Module._compile node:internal/modules/cjs/loader:1051:37
      1  100.0%            LazyCompile: ~Module._extensions..js node:internal/modules/cjs/loader:1106:37
      1    2.1%      LazyCompile: ~findLongestRegisteredExtension node:internal/modules/cjs/loader:413:40
      1  100.0%        LazyCompile: ~Module.load node:internal/modules/cjs/loader:963:33
      1  100.0%          LazyCompile: ~Module._load node:internal/modules/cjs/loader:757:24
      1  100.0%            LazyCompile: ~executeUserEntryPoint node:internal/modules/run_main:74:31
      1    2.1%      LazyCompile: ~compileFunction node:vm:308:25
      1  100.0%        LazyCompile: ~wrapSafe node:internal/modules/cjs/loader:1011:18
      1  100.0%          LazyCompile: ~Module._compile node:internal/modules/cjs/loader:1051:37
      1  100.0%            LazyCompile: ~Module._extensions..js node:internal/modules/cjs/loader:1106:37
      1    2.1%      LazyCompile: ~addListener node:events:486:58
      1  100.0%        LazyCompile: ~setupWarningHandler node:internal/bootstrap/pre_execution:132:29
      1  100.0%          LazyCompile: ~prepareMainThreadExecution node:internal/bootstrap/pre_execution:22:36
      1  100.0%            Function: ~<anonymous> node:internal/main/run_main_module:1:1
      1    2.1%      Function: ~<anonymous> node:internal/webstreams/readablestream:1:1
      1  100.0%        Function: ^compileForInternalLoader node:internal/bootstrap/loaders:299:27
      1  100.0%          Function: ^nativeModuleRequire node:internal/bootstrap/loaders:332:29
      1  100.0%            Function: ~<anonymous> node:internal/webstreams/adapters:1:1
      1    2.1%      Function: ~<anonymous> node:internal/fs/rimraf:1:1
      1  100.0%        Function: ^compileForInternalLoader node:internal/bootstrap/loaders:299:27
      1  100.0%          Function: ^nativeModuleRequire node:internal/bootstrap/loaders:332:29
      1  100.0%            Function: ~<anonymous> node:internal/fs/promises:1:1
      1    2.1%      Function: ~<anonymous> node:internal/fs/promises:1:1
      1  100.0%        Function: ^compileForInternalLoader node:internal/bootstrap/loaders:299:27
      1  100.0%          Function: ^nativeModuleRequire node:internal/bootstrap/loaders:332:29
      1  100.0%            Function: ~<anonymous> node:internal/modules/esm/get_source:1:1
      1    1.7%    Function: ^normalizeString node:path:66:25
      1  100.0%      LazyCompile: ~resolve node:path:1091:10
      1  100.0%        LazyCompile: ~Module._initPaths node:internal/modules/cjs/loader:1223:29
      1  100.0%          LazyCompile: ~initializeCJSLoader node:internal/bootstrap/pre_execution:412:29
      1  100.0%            LazyCompile: ~prepareMainThreadExecution node:internal/bootstrap/pre_execution:22:36

     13   13.5%  /usr/lib/system/libsystem_pthread.dylib
     10   76.9%    T node::native_module::NativeModuleLoader::GetModuleIds()
      3   30.0%      LazyCompile: ~toRealPath node:internal/modules/cjs/loader:393:20
      3  100.0%        LazyCompile: ~Module._findPath node:internal/modules/cjs/loader:494:28
      3  100.0%          LazyCompile: ~resolveMainPath node:internal/modules/run_main:12:25
      3  100.0%            LazyCompile: ~executeUserEntryPoint node:internal/modules/run_main:74:31
      3   30.0%      LazyCompile: ~patchProcessObject node:internal/bootstrap/pre_execution:81:28
      3  100.0%        LazyCompile: ~prepareMainThreadExecution node:internal/bootstrap/pre_execution:22:36
      3  100.0%          Function: ~<anonymous> node:internal/main/run_main_module:1:1
      2   20.0%      LazyCompile: ~realpathSync node:fs:2408:22
      2  100.0%        LazyCompile: ~toRealPath node:internal/modules/cjs/loader:393:20
      2  100.0%          LazyCompile: ~Module._findPath node:internal/modules/cjs/loader:494:28
      2  100.0%            LazyCompile: ~resolveMainPath node:internal/modules/run_main:12:25
      1   10.0%      LazyCompile: ~addReadOnlyProcessAlias node:internal/bootstrap/pre_execution:120:33
      1  100.0%        LazyCompile: ~patchProcessObject node:internal/bootstrap/pre_execution:81:28
      1  100.0%          LazyCompile: ~prepareMainThreadExecution node:internal/bootstrap/pre_execution:22:36
      1  100.0%            Function: ~<anonymous> node:internal/main/run_main_module:1:1
      1   10.0%      Function: ~<anonymous> node:internal/main/run_main_module:1:1

     11   11.5%  T __kernelrpc_mach_port_get_refs
      3   27.3%    T node::native_module::NativeModuleLoader::GetModuleIds()
      1   33.3%      LazyCompile: ~Module._load node:internal/modules/cjs/loader:757:24
      1  100.0%        LazyCompile: ~executeUserEntryPoint node:internal/modules/run_main:74:31
      1  100.0%          Function: ~<anonymous> node:internal/main/run_main_module:1:1
      1   33.3%      Function: ~<instance_members_initializer> node:internal/util/iterable_weak_map:17:3
      1  100.0%        LazyCompile: ~IterableWeakMap node:internal/util/iterable_weak_map:16:1
      1  100.0%          Function: ~<anonymous> node:internal/source_map/source_map_cache:1:1
      1  100.0%            LazyCompile: ~compileForInternalLoader node:internal/bootstrap/loaders:299:27
      1   33.3%      Function: ~<anonymous> node:internal/modules/cjs/loader:1:1
      1  100.0%        LazyCompile: ~compileForInternalLoader node:internal/bootstrap/loaders:299:27
      1  100.0%          LazyCompile: ~nativeModuleRequire node:internal/bootstrap/loaders:332:29
      1  100.0%            LazyCompile: ~initializeCJSLoader node:internal/bootstrap/pre_execution:412:29

      3    3.1%  t std::__1::ostreambuf_iterator<char, std::__1::char_traits<char> > std::__1::__pad_and_output<char, std::__1::char_traits<char> >(std::__1::ostreambuf_iterator<char, std::__1::char_traits<char> >, char const*, char const*, char const*, std::__1::ios_base&, char)
      3  100.0%    T node::native_module::NativeModuleLoader::GetModuleIds()
      1   33.3%      LazyCompile: ~prepareMainThreadExecution node:internal/bootstrap/pre_execution:22:36
      1  100.0%        Function: ~<anonymous> node:internal/main/run_main_module:1:1
      1   33.3%      LazyCompile: ~fromString node:buffer:431:20
      1  100.0%        LazyCompile: ~from node:buffer:295:28
      1  100.0%          Function: ~<anonymous> node:internal/fs/rimraf:1:1
      1  100.0%            Function: ^compileForInternalLoader node:internal/bootstrap/loaders:299:27
      1   33.3%      Function: ~<anonymous> node:internal/fs/rimraf:1:1
      1  100.0%        Function: ^compileForInternalLoader node:internal/bootstrap/loaders:299:27
      1  100.0%          Function: ^nativeModuleRequire node:internal/bootstrap/loaders:332:29
      1  100.0%            Function: ~<anonymous> node:internal/fs/promises:1:1

      3    3.1%  /usr/lib/system/libsystem_c.dylib
      1   33.3%    T node::native_module::NativeModuleLoader::GetModuleIds()
      1  100.0%      LazyCompile: ~setupWarningHandler node:internal/bootstrap/pre_execution:132:29
      1  100.0%        LazyCompile: ~prepareMainThreadExecution node:internal/bootstrap/pre_execution:22:36
      1  100.0%          Function: ~<anonymous> node:internal/main/run_main_module:1:1

      2    2.1%  /usr/lib/libc++.1.dylib
      1   50.0%    T node::native_module::NativeModuleLoader::GetModuleIds()
      1  100.0%      Function: ~<anonymous> node:internal/fs/promises:1:1
      1  100.0%        Function: ^compileForInternalLoader node:internal/bootstrap/loaders:299:27
      1  100.0%          Function: ^nativeModuleRequire node:internal/bootstrap/loaders:332:29
      1  100.0%            Function: ~<anonymous> node:internal/modules/esm/get_source:1:1

      1    1.0%  UNKNOWN
      1  100.0%    T node::native_module::NativeModuleLoader::GetModuleIds()
      1  100.0%      LazyCompile: ~realpathSync node:fs:2408:22
      1  100.0%        LazyCompile: ~toRealPath node:internal/modules/cjs/loader:393:20
      1  100.0%          LazyCompile: ~Module._findPath node:internal/modules/cjs/loader:494:28
      1  100.0%            LazyCompile: ~resolveMainPath node:internal/modules/run_main:12:25

      1    1.0%  T _task_for_pid
      1  100.0%    T node::native_module::NativeModuleLoader::GetModuleIds()
      1  100.0%      LazyCompile: ~prepareMainThreadExecution node:internal/bootstrap/pre_execution:22:36
      1  100.0%        Function: ~<anonymous> node:internal/main/run_main_module:1:1

      1    1.0%  T ___getrlimit

      1    1.0%  /usr/lib/system/libsystem_platform.dylib
      1  100.0%    T node::native_module::NativeModuleLoader::GetModuleIds()
      1  100.0%      LazyCompile: ~toRealPath node:internal/modules/cjs/loader:393:20
      1  100.0%        LazyCompile: ~Module._findPath node:internal/modules/cjs/loader:494:28
      1  100.0%          LazyCompile: ~resolveMainPath node:internal/modules/run_main:12:25
      1  100.0%            LazyCompile: ~executeUserEntryPoint node:internal/modules/run_main:74:31

      1    1.0%  /usr/lib/system/libsystem_malloc.dylib

      1    1.0%  /usr/lib/libobjc.A.dylib

nodejs-github-bot added async_hooks Issues and PRs related to the async hooks subsystem. needs-ci PRs that need a full CI run. labels Nov 14, 2021

RaisinTen mentioned this pull request Nov 14, 2021

process: deprecate _getActive* private APIs in favour of async_hooks #40804

Closed

async_hooks: create the storage hook only when needed

7f96221

The storage hook got created whenever the `async_hooks` module was being required. There is no reason to do that if we don't use the `AsyncLocalStorage` class later on. Signed-off-by: Darshan Sen <darshan.sen@postman.com>

RaisinTen force-pushed the async_hooks/remove-unnecessary-hook-creation-during-require branch from 58f78ec to 7f96221 Compare November 18, 2021 13:27

RaisinTen closed this Nov 22, 2021

RaisinTen deleted the async_hooks/remove-unnecessary-hook-creation-during-require branch November 22, 2021 15:52

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

async_hooks: create the storage hook only when needed#40810

async_hooks: create the storage hook only when needed#40810
RaisinTen wants to merge 1 commit intonodejs:masterfrom
RaisinTen:async_hooks/remove-unnecessary-hook-creation-during-require

RaisinTen commented Nov 14, 2021

Uh oh!

RaisinTen commented Nov 14, 2021 •

edited

Loading

Uh oh!

RaisinTen commented Nov 20, 2021 •

edited

Loading

Uh oh!

vdeturckheim commented Nov 22, 2021

Uh oh!

RaisinTen commented Nov 22, 2021

Uh oh!

vdeturckheim commented Nov 22, 2021

Uh oh!

RaisinTen commented Nov 22, 2021

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Uh oh!

Conversation

RaisinTen commented Nov 14, 2021

Uh oh!

RaisinTen commented Nov 14, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

RaisinTen commented Nov 20, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

vdeturckheim commented Nov 22, 2021

Uh oh!

RaisinTen commented Nov 22, 2021

Uh oh!

vdeturckheim commented Nov 22, 2021

Uh oh!

RaisinTen commented Nov 22, 2021

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

RaisinTen commented Nov 14, 2021 •

edited

Loading

RaisinTen commented Nov 20, 2021 •

edited

Loading