Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

util: avoid run debug when enabled is false #57494

Open
wants to merge 1 commit into
base: main
Choose a base branch
from
Open

util: avoid run debug when enabled is false #57494

wants to merge 1 commit into from
+3 −1

Conversation

fengmk2
Copy link
Contributor

@fengmk2 fengmk2 commented Mar 16, 2025

Once there are more than 2 inputs to the debug logger, e.g.: debug(1, 2, 3),
there is a significant performance degradation.

This change can improve performance 700x faster.

Benchmark

Test script

import { debuglog } from 'node:util';
import { run, bench, boxplot, summary } from 'mitata';

const debug = debuglog('test');

boxplot(() => {
  summary(() => {
    bench('debug()', () => {
      debug();
    });

    bench('debug(arg1)', () => {
      debug('arg1');
    });

    bench('debug(arg1, arg2)', () => {
      debug('arg1', 'arg2');
    });

    bench('debug(arg1, arg2, arg3)', () => {
      debug('arg1', 'arg2', 'arg3');
    });

    bench('debug(arg1, arg2, arg3, arg4)', () => {
      debug('arg1', 'arg2', 'arg3', 'arg4');
    });

    bench('debug(arg1, arg2, arg3, arg4, arg5)', () => {
      debug('arg1', 'arg2', 'arg3', 'arg4', 'arg5');
    });

    bench('debug(arg1, arg2, arg3, arg4, arg5, arg6)', () => {
      debug('arg1', 'arg2', 'arg3', 'arg4', 'arg5', 'arg6');
    });
  });
});

await run();

Before

clk: ~2.77 GHz
cpu: Apple M1
runtime: node 22.14.0 (arm64-darwin)

benchmark                                avg (min … max) p75 / p99    (min … top 1%)
-------------------------------------------------------- -------------------------------
debug()                                    48.10 ns/iter  46.31 ns █▇                   
                                  (44.68 ns … 537.07 ns)  77.05 ns ██                   
                                 ( 95.53  b … 256.21  b) 184.23  b ██▄▂▂▁▁▁▁▁▁▁▁▁▁▂▂▂▁▁▁

debug(arg1)                                 2.49 ns/iter   2.18 ns █                    
                                    (1.66 ns … 53.58 ns)  26.13 ns █                    
                                 ( 33.25  b …  88.13  b)  56.15  b █▃▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁

debug(arg1, arg2)                           2.96 ns/iter   2.56 ns █                    
                                    (1.95 ns … 83.79 ns)  27.63 ns █                    
                                 (  5.38  b …  96.13  b)  64.14  b █▆▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁

debug(arg1, arg2, arg3)                   134.43 ns/iter 129.98 ns  █                   
                                 (125.27 ns … 645.71 ns) 202.32 ns ▃█                   
                                 (378.88  b … 683.47  b) 528.22  b ██▃▂▁▁▂▄▂▁▁▁▁▁▁▁▁▁▁▁▁

debug(arg1, arg2, arg3, arg4)             175.44 ns/iter 176.32 ns     █                
                                   (156.77 ns … 1.29 µs) 221.29 ns   ▆▅█                
                                 (435.13  b … 702.23  b) 584.06  b ▅▂████▅▅▂▂▂▂▃▂▃▂▁▂▁▁▁

debug(arg1, arg2, arg3, arg4, arg5)       189.31 ns/iter 189.73 ns   █                  
                                 (179.46 ns … 299.87 ns) 225.29 ns ▇▅█                  
                                 (505.08  b … 663.07  b) 639.79  b ████▇▄▃▂▂▁▁▃▄▄▃▂▂▂▂▁▁

debug(arg1, arg2, arg3, arg4, arg5, arg6) 209.56 ns/iter 212.41 ns █                    
                                 (201.88 ns … 266.42 ns) 247.06 ns █▆                   
                                 (334.36  b … 856.20  b) 695.85  b ██▄▂▂▂▂▁▁▁▁▄▄▃▁▁▁▁▁▁▁

                                          ┌                                            ┐
                                                  ┌┬    ╷
                                  debug()         ││────┤
                                                  └┴    ╵
                                          ┬   ╷
                              debug(arg1) │───┤
                                          ┴   ╵
                                          ┬    ╷
                        debug(arg1, arg2) │────┤
                                          ┴    ╵
                                                                 ┌┬            ╷
                  debug(arg1, arg2, arg3)                        ││────────────┤
                                                                 └┴            ╵
                                                                      ╷ ┌─┬       ╷
            debug(arg1, arg2, arg3, arg4)                             ├─┤ │───────┤
                                                                      ╵ └─┴       ╵
                                                                           ┌┬      ╷
      debug(arg1, arg2, arg3, arg4, arg5)                                  ││──────┤
                                                                           └┴      ╵
                                                                               ┌┬┐     ╷
debug(arg1, arg2, arg3, arg4, arg5, arg6)                                      ││├─────┤
                                                                               └┴┘     ╵
                                          └                                            ┘
                                          1.66 ns          124.36 ns           247.06 ns

summary
  debug(arg1)
   1.19x faster than debug(arg1, arg2)
   19.32x faster than debug()
   54.01x faster than debug(arg1, arg2, arg3)
   70.48x faster than debug(arg1, arg2, arg3, arg4)
   76.06x faster than debug(arg1, arg2, arg3, arg4, arg5)
   84.19x faster than debug(arg1, arg2, arg3, arg4, arg5, arg6)

After

clk: ~3.08 GHz
cpu: Apple M1
runtime: node 24.0.0-pre (arm64-darwin)

benchmark                                avg (min … max) p75 / p99    (min … top 1%)
-------------------------------------------------------- -------------------------------
debug()                                   165.97 ps/iter 162.84 ps              █       
                                  (142.33 ps … 13.80 ns) 173.10 ps              █       
                                 (  0.03  b …  53.95  b)   0.09  b ▁▁▁▁▁▁▁▁▁▁▁▁▁█▁▁▁▁▁▁▄

debug(arg1)                               167.87 ps/iter 172.85 ps           █          
                                  (142.33 ps … 14.18 ns) 183.11 ps           █    ▂     
                                 (  0.09  b …  23.35  b)   0.09  b ▁▁▁▁▁▁▁▁▁▁█▁▁▁▁█▁▁▁▁▁

debug(arg1, arg2)                         164.65 ps/iter 162.84 ps              █       
                                  (142.33 ps … 12.07 ns) 173.10 ps              █       
                                 (  0.09  b …  23.60  b)   0.09  b ▁▁▁▁▁▁▁▁▁▁▁▁▁█▁▁▁▁▁▁▂

debug(arg1, arg2, arg3)                   165.38 ps/iter 162.84 ps           █          
                                  (142.33 ps … 24.65 ns) 183.11 ps           █          
                                 (  0.09  b …  23.60  b)   0.09  b ▁▁▁▁▁▁▁▁▁▁█▁▁▁▁▂▁▁▁▁▁

debug(arg1, arg2, arg3, arg4)             167.57 ps/iter 172.85 ps           █          
                                  (142.33 ps … 10.47 ns) 183.11 ps           █    ▂     
                                 (  0.09  b …  76.49  b)   0.09  b ▁▁▁▁▁▁▁▁▁▁█▁▁▁▁█▁▁▁▁▁

debug(arg1, arg2, arg3, arg4, arg5)       165.38 ps/iter 162.84 ps           █          
                                  (142.33 ps … 30.79 ns) 183.11 ps           █          
                                 (  0.09  b …  28.22  b)   0.09  b ▁▁▁▁▁▁▁▁▁▁█▁▁▁▁▂▁▁▁▁▁

debug(arg1, arg2, arg3, arg4, arg5, arg6) 166.64 ps/iter 162.84 ps         █            
                                  (142.33 ps … 10.51 ns) 193.12 ps         █            
                                 (  0.10  b …  31.22  b)   0.10  b ▁▁▁▁▁▁▁▁█▁▁▁▆▁▁▁▁▁▁▁▁

                                          ┌                                            ┐
                                          ╷                 ┌──┬     ╷
                                  debug() ├─────────────────┤  │─────┤
                                          ╵                 └──┴     ╵
                                          ╷                 ┌────┬───┐        ╷
                              debug(arg1) ├─────────────────┤    │   ├────────┤
                                          ╵                 └────┴───┘        ╵
                                          ╷                 ┌─┬      ╷
                        debug(arg1, arg2) ├─────────────────┤ │──────┤
                                          ╵                 └─┴      ╵
                                          ╷                 ┌─┬               ╷
                  debug(arg1, arg2, arg3) ├─────────────────┤ │───────────────┤
                                          ╵                 └─┴               ╵
                                          ╷                 ┌───┬────┐        ╷
            debug(arg1, arg2, arg3, arg4) ├─────────────────┤   │    ├────────┤
                                          ╵                 └───┴────┘        ╵
                                          ╷                 ┌─┬               ╷
      debug(arg1, arg2, arg3, arg4, arg5) ├─────────────────┤ │───────────────┤
                                          ╵                 └─┴               ╵
                                          ╷                 ┌───┬                      ╷
debug(arg1, arg2, arg3, arg4, arg5, arg6) ├─────────────────┤   │──────────────────────┤
                                          ╵                 └───┴                      ╵
                                          └                                            ┘
                                          142.33 ps         167.72 ps          193.12 ps

summary
  debug(arg1, arg2)
   1x faster than debug(arg1, arg2, arg3)
   1x faster than debug(arg1, arg2, arg3, arg4, arg5)
   1.01x faster than debug()
   1.01x faster than debug(arg1, arg2, arg3, arg4, arg5, arg6)
   1.02x faster than debug(arg1, arg2, arg3, arg4)
   1.02x faster than debug(arg1)

@nodejs-github-bot nodejs-github-bot added needs-ci PRs that need a full CI run. util Issues and PRs related to the built-in util module. labels Mar 16, 2025
fengmk2
fengmk2 commented Mar 16, 2025
View reviewed changes
lib/internal/util/debuglog.js
@@ -62,7 +62,7 @@ function lazyUtilColors() {
return utilColors;
}

function debuglogImpl(enabled, set, args) {
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

args was never used

@fengmk2
util: avoid run debug when enabled is false
f6b4d12 
it can improve performace 700x faster
@fengmk2 fengmk2 force-pushed the improve-debuglog-perf branch from 713532d to f6b4d12 Compare March 16, 2025 11:15
gurgunday
gurgunday reviewed Mar 16, 2025
View reviewed changes
Copy link
Contributor

@gurgunday gurgunday left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Lgtm!

@codecov Codecov
Copy link

codecov bot commented Mar 16, 2025 •
edited
Loading

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 90.22%. Comparing base (d5ac3e3) to head (f6b4d12).
Report is 9 commits behind head on main.

Additional details and impacted files 
@@            Coverage Diff             @@
##             main   #57494      +/-   ##
==========================================
- Coverage   90.23%   90.22%   -0.01%     
==========================================
  Files         629      629              
  Lines      184823   184849      +26     
  Branches    36203    36213      +10     
==========================================
+ Hits       166780   166787       +7     
- Misses      11013    11028      +15     
- Partials     7030     7034       +4
Files with missing lines Coverage Δ
lib/internal/util/debuglog.js 95.21% <100.00%> (+0.01%) ⬆️

... and 44 files with indirect coverage changes

🚀 New features to boost your workflow:
  • ❄ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.
  • 📦 JS Bundle Analysis: Save yourself from yourself by tracking and limiting bundle sizes in JS merges.

@anonrig anonrig added author ready PRs that have at least one approval, no pending requests for changes, and a CI started. request-ci Add this label to start a Jenkins CI on a PR. labels Mar 16, 2025
@github-actions github-actions bot removed the request-ci Add this label to start a Jenkins CI on a PR. label Mar 16, 2025
@nodejs-github-bot
Copy link
Collaborator

CI: https://ci.nodejs.org/job/node-test-pull-request/65783/

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@gurgunday gurgunday gurgunday left review comments

@jasnell jasnell jasnell approved these changes

@anonrig anonrig anonrig approved these changes

@cjihrig cjihrig cjihrig approved these changes

Assignees
No one assigned
Labels
author ready PRs that have at least one approval, no pending requests for changes, and a CI started. needs-ci PRs that need a full CI run. util Issues and PRs related to the built-in util module.
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
6 participants
@fengmk2 @nodejs-github-bot @jasnell @anonrig @cjihrig @gurgunday