Skip to content
This repository has been archived by the owner on May 12, 2024. It is now read-only.

node 20 is slow (minutes) compared to node 18 (seconds) on certain links #39

Open
marcindulak opened this issue Mar 2, 2024 · 0 comments

Comments

@marcindulak
Copy link
Contributor

marcindulak commented Mar 2, 2024

See https://github.com/marcindulak/asciidoc-link-check-39 for a reproduction in a github action

Using this test.adocfile

https://docs.docker.com/compose[docker compose]

Node 20.0.0 check runs for 4 minutes, and node 18.19.1 for less than a second

time node --prof ./asciidoc-link-check test.adoc

Here is the beginning of node 20 prof file

Statistical profiling result from 20.0.0.log, (337 ticks, 5 unaccounted, 0 excluded).

 [Shared libraries]:
   ticks  total  nonlib   name
    228   67.7%          /opt/hostedtoolcache/node/20.0.0/x64/bin/node
     34   10.1%          /usr/lib/x86_64-linux-gnu/libc.so.6
      1    0.3%          [vdso]
      1    0.3%          /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.32

 [JavaScript]:
   ticks  total  nonlib   name
      1    0.3%    1.4%  JS: *normalizeString node:path:66:25

 [C++]:
   ticks  total  nonlib   name
     23    6.8%   31.5%  __write@@GLIBC_2.2.5
     16    4.7%   21.9%  epoll_pwait@@GLIBC_2.6
      8    2.4%   11.0%  _IO_fwrite@@GLIBC_2.2.5
      5    1.5%    6.8%  std::basic_ostream<char, std::char_traits<char> >& std::__ostream_insert<char, std::char_traits<char> >(std::basic_ostream<char, std::char_traits<char> >&, char const*, long)@@GLIBCXX_3.4.9
      5    1.5%    6.8%  _IO_file_xsputn@@GLIBC_2.2.5
      2    0.6%    2.7%  std::ostream::sentry::sentry(std::ostream&)@@GLIBCXX_3.4
      2    0.6%    2.7%  pthread_cond_signal@@GLIBC_2.3.2
      2    0.6%    2.7%  __munmap@@GLIBC_PRIVATE
      1    0.3%    1.4%  std::_Rb_tree_increment(std::_Rb_tree_node_base*)@@GLIBCXX_3.4
      1    0.3%    1.4%  fputc@@GLIBC_2.2.5
      1    0.3%    1.4%  __default_morecore@GLIBC_2.2.5
      1    0.3%    1.4%  __clock_gettime@@GLIBC_PRIVATE

 [Summary]:
   ticks  total  nonlib   name
      1    0.3%    1.4%  JavaScript
     67   19.9%   91.8%  C++
     40   11.9%   54.8%  GC
    264   78.3%          Shared libraries
      5    1.5%          Unaccounted

 [C++ entry points]:
   ticks    cpp   total   name
     14   38.9%    4.2%  __write@@GLIBC_2.2.5
      8   22.2%    2.4%  _IO_fwrite@@GLIBC_2.2.5
      5   13.9%    1.5%  _IO_file_xsputn@@GLIBC_2.2.5
      4   11.1%    1.2%  std::basic_ostream<char, std::char_traits<char> >& std::__ostream_insert<char, std::char_traits<char> >(std::basic_ostream<char, std::char_traits<char> >&, char const*, long)@@GLIBCXX_3.4.9
      2    5.6%    0.6%  std::ostream::sentry::sentry(std::ostream&)@@GLIBCXX_3.4
      1    2.8%    0.3%  std::_Rb_tree_increment(std::_Rb_tree_node_base*)@@GLIBCXX_3.4
      1    2.8%    0.3%  fputc@@GLIBC_2.2.5
      1    2.8%    0.3%  __clock_gettime@@GLIBC_PRIVATE

 [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
    228   67.7%  /opt/hostedtoolcache/node/20.0.0/x64/bin/node
    210   92.1%    /opt/hostedtoolcache/node/20.0.0/x64/bin/node
     64   30.5%      JS: ^compileForInternalLoader node:internal/bootstrap/realm:360:27
     57   89.1%        JS: ^requireBuiltin node:internal/bootstrap/realm:397:24
      6   10.5%          JS: ~<anonymous> node:crypto:1:1
      6  100.0%            JS: ^compileForInternalLoader node:internal/bootstrap/realm:360:27
      4    7.0%          JS: ~<anonymous> node:tty:1:1
      4  100.0%            JS: ^compileForInternalLoader node:internal/bootstrap/realm:360:27
      4    7.0%          JS: ~<anonymous> node:tls:1:1
      4  100.0%            JS: ^compileForInternalLoader node:internal/bootstrap/realm:360:27
      4    7.0%          JS: ~<anonymous> node:internal/fs/promises:1:1
      4  100.0%            JS: ^compileForInternalLoader node:internal/bootstrap/realm:360:27
      3    5.3%          JS: ~get node:internal/util:585:17
      2   66.7%            /opt/hostedtoolcache/node/20.0.0/x64/bin/node
      1   33.3%            JS: *getOwn node:internal/bootstrap/realm:198:16
...

and here is node 18

Statistical profiling result from 18.19.1.log, (329 ticks, 0 unaccounted, 0 excluded).

 [Shared libraries]:
   ticks  total  nonlib   name
    256   77.8%          /opt/hostedtoolcache/node/18.19.1/x64/bin/node
      8    2.4%          /usr/lib/x86_64-linux-gnu/libc.so.6
      1    0.3%          [vdso]

 [JavaScript]:
   ticks  total  nonlib   name
      1    0.3%    1.6%  Function: ^validateStringArray node:internal/validators:305:29
      1    0.3%    1.6%  Function: ^Module._nodeModulePaths node:internal/modules/cjs/loader:783:37
      1    0.3%    1.6%  Function: ^<anonymous> node:internal/util:769:18

 [C++]:
   ticks  total  nonlib   name
     23    7.0%   35.9%  __write@@GLIBC_2.2.5
     11    3.3%   17.2%  epoll_pwait@@GLIBC_2.6
      7    2.1%   10.9%  _IO_file_xsputn@@GLIBC_2.2.5
      6    1.8%    9.4%  std::basic_ostream<char, std::char_traits<char> >& std::__ostream_insert<char, std::char_traits<char> >(std::basic_ostream<char, std::char_traits<char> >&, char const*, long)@@GLIBCXX_3.4.9
      3    0.9%    4.7%  __mprotect@@GLIBC_PRIVATE
      3    0.9%    4.7%  _IO_fwrite@@GLIBC_2.2.5
      2    0.6%    3.1%  std::ostream::sentry::sentry(std::ostream&)@@GLIBCXX_3.4
      1    0.3%    1.6%  std::ostreambuf_iterator<char, std::char_traits<char> > std::num_put<char, std::ostreambuf_iterator<char, std::char_traits<char> > >::_M_insert_int<long>(std::ostreambuf_iterator<char, std::char_traits<char> >, std::ios_base&, char, long) const@@GLIBCXX_3.4
      1    0.3%    1.6%  std::_Rb_tree_insert_and_rebalance(bool, std::_Rb_tree_node_base*, std::_Rb_tree_node_base*, std::_Rb_tree_node_base&)@@GLIBCXX_3.4
      1    0.3%    1.6%  shutdown@@GLIBC_2.2.5
      1    0.3%    1.6%  __libc_malloc@@GLIBC_2.2.5
      1    0.3%    1.6%  __libc_free@@GLIBC_2.2.5
      1    0.3%    1.6%  _IO_fflush@@GLIBC_2.2.5

 [Summary]:
   ticks  total  nonlib   name
      3    0.9%    4.7%  JavaScript
     61   18.5%   95.3%  C++
      4    1.2%    6.3%  GC
    265   80.5%          Shared libraries

 [C++ entry points]:
   ticks    cpp   total   name
     16   41.0%    4.9%  __write@@GLIBC_2.2.5
      6   15.4%    1.8%  _IO_file_xsputn@@GLIBC_2.2.5
      5   12.8%    1.5%  std::basic_ostream<char, std::char_traits<char> >& std::__ostream_insert<char, std::char_traits<char> >(std::basic_ostream<char, std::char_traits<char> >&, char const*, long)@@GLIBCXX_3.4.9
      3    7.7%    0.9%  __mprotect@@GLIBC_PRIVATE
      3    7.7%    0.9%  _IO_fwrite@@GLIBC_2.2.5
      2    5.1%    0.6%  std::ostream::sentry::sentry(std::ostream&)@@GLIBCXX_3.4
      1    2.6%    0.3%  std::ostreambuf_iterator<char, std::char_traits<char> > std::num_put<char, std::ostreambuf_iterator<char, std::char_traits<char> > >::_M_insert_int<long>(std::ostreambuf_iterator<char, std::char_traits<char> >, std::ios_base&, char, long) const@@GLIBCXX_3.4
      1    2.6%    0.3%  std::_Rb_tree_insert_and_rebalance(bool, std::_Rb_tree_node_base*, std::_Rb_tree_node_base*, std::_Rb_tree_node_base&)@@GLIBCXX_3.4
      1    2.6%    0.3%  __libc_malloc@@GLIBC_2.2.5
      1    2.6%    0.3%  _IO_fflush@@GLIBC_2.2.5

 [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
    256   77.8%  /opt/hostedtoolcache/node/18.19.1/x64/bin/node
    229   89.5%    /opt/hostedtoolcache/node/18.19.1/x64/bin/node
     61   26.6%      Function: ^compileForInternalLoader node:internal/bootstrap/realm:375:27
     56   91.8%        Function: ^requireBuiltin node:internal/bootstrap/realm:412:24
      7   12.5%          Function: ~<anonymous> node:crypto:1:1
      7  100.0%            Function: ^compileForInternalLoader node:internal/bootstrap/realm:375:27
      4    7.1%          Function: ~<anonymous> node:internal/streams/duplex:1:1
      4  100.0%            Function: ^compileForInternalLoader node:internal/bootstrap/realm:375:27
      4    7.1%          Function: ~<anonymous> node:internal/fs/promises:1:1
      4  100.0%            Function: ^compileForInternalLoader node:internal/bootstrap/realm:375:27
      3    5.4%          LazyCompile: ~get node:internal/util:595:17
      3  100.0%            /opt/hostedtoolcache/node/18.19.1/x64/bin/node
      2   66.7%        LazyCompile: ~resolvePackageTargetString node:internal/modules/esm/resolve:429:36
      2  100.0%          LazyCompile: ~resolvePackageTarget node:internal/modules/esm/resolve:533:30
      2  100.0%            LazyCompile: ~resolvePackageTarget node:internal/modules/esm/resolve:533:30
      1   33.3%        Function: ^resolve node:path:1091:10
      1  100.0%          Function: ^readPackage node:internal/modules/package_json_reader:139:21
      1  100.0%            Function: ^readPackageScope node:internal/modules/package_json_reader:148:26
...
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

No branches or pull requests

1 participant