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.

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

src,http2: refactor + generalize http2 debugging #20987

Closed
wants to merge 4 commits into from

Conversation

addaleax
Copy link
Member

@addaleax addaleax commented May 27, 2018

tl;dr: Instead of having to compile with ./configure --debug-http2, get the same output with NODE_DEBUG_NATIVE=http2 node at runtime, in a way that makes implementing similar debugging for other core modules easier.

  • src: implement debug output utilities

    Implement utilities for easier debugging of Node.js core code,
    inspired by the HTTP/2 debugging code. Debugging is, however,
    implemented at runtime rather than at compile time, controlled
    through a new through a new NODE_DEBUG_NATIVE=categories
    environment variable.

    The runtime overhead in the debugging-disabled case amounts to
    1 well-cachable one-byte read per debug call.

  • http2: switch to new runtime-controlled debugging system

    Remove --debug-http2 as a compile-time feature and
    make all debug statements available using NODE_DEBUG_NATIVE=http2
    at runtime.

    This probably makes the debugging-enabled case a bit slower due to
    additional string concatenations, but switching to a runtime-checking
    system makes debugging more flexible and can be applied more easily
    to other parts of the source code as well.

Checklist
  • make -j4 test (UNIX), or vcbuild test (Windows) passes
  • tests and/or benchmarks are included
  • commit message follows commit guidelines

@addaleax addaleax requested a review from jasnell May 27, 2018 15:24
@nodejs-github-bot nodejs-github-bot added c++ Issues and PRs that require attention from people who are familiar with C++. lib / src Issues and PRs related to general changes in the lib or src directory. labels May 27, 2018
@addaleax addaleax added the http2 Issues or PRs related to the http2 subsystem. label May 27, 2018
@@ -293,6 +293,13 @@ char ToLower(char c) {
return c >= 'A' && c <= 'Z' ? c + ('a' - 'A') : c;
}

std::string ToLower(const std::string& in) {
Copy link
Member

Choose a reason for hiding this comment

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

Random unrelated questions - since we always build with an ICU - isn't this the sort of thing the ICU can do?

Also - is the loop below not a for(auto elm : in) due to stylistic preference or something else?

Copy link
Member Author

Choose a reason for hiding this comment

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

isn't this the sort of thing the ICU can do?

No idea – doing it this way doesn’t cost us much though, though. @srl295 probably has a more helpful answer :)

Also - is the loop below not a for(auto elm : in) due to stylistic preference or something else?

We’d probably still want to set the characters in the output string directly rather than appending them one at a time, so we’d want to maintain an index for that. In those cases, yes, I prefer to use the explicit index for the input as well, even though we could do it without. :)

@joyeecheung
Copy link
Member

We have the NODE_DEBUG environment variable for this and it's documented. Any reason to introduce a new command line flag?

@addaleax
Copy link
Member Author

@joyeecheung Nothing besides that this works slightly differently (currently category names correspond to AsyncWrap types rather than core modules) and that it targets the C++ layer rather than the JS layer. If you think we should re-use NODE_DEBUG here, that’s not an issue for me. :)

@joyeecheung
Copy link
Member

@addaleax I am OK if the flag is dedicated for debugging output from the C++ side, as far as I know the environment variable is only honored in the JS land. But if we provide two mechanisms to achieve a similar purpose it would be rather confusing.

src/env.cc Outdated
break;
// Use everything after the `,` as the list for the next iteration.
debug_categories =
debug_categories.substr(comma_pos);
Copy link
Contributor

Choose a reason for hiding this comment

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

Why is this on a new line?

Copy link
Member Author

Choose a reason for hiding this comment

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

Because the line was originally a bit longer. Fixed! :)

Implement utilities for easier debugging of Node.js core code,
inspired by the HTTP/2 debugging code. Debugging is, however,
implemented at runtime rather than at compile time, controlled
through a new `NODE_DEBUG_NATIVE=categories` environment variable.

The runtime overhead in the debugging-disabled case amounts to
1 well-cachable one-byte read per debug call.
@addaleax
Copy link
Member Author

@joyeecheung I’ve switched this to use NODE_DEBUG_NATIVE as an environment variable – if you want, I can fully merge with NODE_DEBUG (atm the categories and the parsing are still different for the two). Does that sound okay?

@addaleax
Copy link
Member Author

addaleax commented May 27, 2018

The benchmark machine still doesn’t have h2load, but I ran HTTP/2 benchmarks locally and saw a -3 % regression in some of them. I’ve added hints to the compiler, so that it generates more sensible code in terms of inlining and register pressure … not a pretty solution, but the benchmarks seem better now (will post the full results as soon as I have them).

CI: https://ci.nodejs.org/job/node-test-commit/18808/

Remove `--debug-http2` as a compile-time feature and
make all debug statements available using `NODE_DEBUG_NATIVE=http2`
at runtime.

This probably makes the debugging-enabled case a bit slower due to
additional string concatenations, but switching to a runtime-checking
system makes debugging more flexible and can be applied more easily
to other parts of the source code as well.
@addaleax
Copy link
Member Author

Benchmark results now look the way we want them to:

Output in the fold
$ Rscript benchmark/compare.R < 20987.benchmark 
                                                                                      confidence improvement accuracy (*)    (**)   (***)
 http2/headers.js benchmarker='h2load' nheaders=0 n=1000                                              0.75 %       ±0.76%  ±1.01%  ±1.31%
 http2/headers.js benchmarker='h2load' nheaders=1000 n=1000                                           0.31 %       ±0.64%  ±0.86%  ±1.11%
 http2/headers.js benchmarker='h2load' nheaders=100 n=1000                                            0.12 %       ±0.64%  ±0.85%  ±1.11%
 http2/headers.js benchmarker='h2load' nheaders=10 n=1000                                     **      1.01 %       ±0.68%  ±0.91%  ±1.18%
 http2/respond-with-fd.js benchmarker='h2load' clients=1 streams=1000 requests=100                   -0.10 %       ±2.39%  ±3.18%  ±4.14%
 http2/respond-with-fd.js benchmarker='h2load' clients=1 streams=1000 requests=1000                   0.81 %       ±2.21%  ±2.94%  ±3.83%
 http2/respond-with-fd.js benchmarker='h2load' clients=1 streams=1000 requests=10000                  1.41 %       ±2.43%  ±3.23%  ±4.21%
 http2/respond-with-fd.js benchmarker='h2load' clients=1 streams=1000 requests=100000                -0.07 %       ±1.72%  ±2.29%  ±2.98%
 http2/respond-with-fd.js benchmarker='h2load' clients=1 streams=100 requests=100                    -0.26 %       ±1.69%  ±2.25%  ±2.93%
 http2/respond-with-fd.js benchmarker='h2load' clients=1 streams=100 requests=1000                    0.04 %       ±1.99%  ±2.65%  ±3.45%
 http2/respond-with-fd.js benchmarker='h2load' clients=1 streams=100 requests=10000                   1.07 %       ±2.16%  ±2.87%  ±3.74%
 http2/respond-with-fd.js benchmarker='h2load' clients=1 streams=100 requests=100000                  0.61 %       ±1.96%  ±2.61%  ±3.40%
 http2/respond-with-fd.js benchmarker='h2load' clients=1 streams=200 requests=100                     0.48 %       ±1.98%  ±2.64%  ±3.44%
 http2/respond-with-fd.js benchmarker='h2load' clients=1 streams=200 requests=1000                    0.95 %       ±1.94%  ±2.58%  ±3.35%
 http2/respond-with-fd.js benchmarker='h2load' clients=1 streams=200 requests=10000                   0.50 %       ±2.14%  ±2.85%  ±3.71%
 http2/respond-with-fd.js benchmarker='h2load' clients=1 streams=200 requests=100000                  0.29 %       ±1.58%  ±2.11%  ±2.74%
 http2/respond-with-fd.js benchmarker='h2load' clients=2 streams=1000 requests=100                   -1.11 %       ±2.50%  ±3.33%  ±4.33%
 http2/respond-with-fd.js benchmarker='h2load' clients=2 streams=1000 requests=1000                   0.35 %       ±1.45%  ±1.93%  ±2.52%
 http2/respond-with-fd.js benchmarker='h2load' clients=2 streams=1000 requests=10000           *      1.77 %       ±1.72%  ±2.28%  ±2.97%
 http2/respond-with-fd.js benchmarker='h2load' clients=2 streams=1000 requests=100000                 0.30 %       ±1.48%  ±1.97%  ±2.56%
 http2/respond-with-fd.js benchmarker='h2load' clients=2 streams=100 requests=100                     0.95 %       ±2.47%  ±3.29%  ±4.29%
 http2/respond-with-fd.js benchmarker='h2load' clients=2 streams=100 requests=1000                    0.90 %       ±1.63%  ±2.17%  ±2.83%
 http2/respond-with-fd.js benchmarker='h2load' clients=2 streams=100 requests=10000                   1.10 %       ±1.65%  ±2.19%  ±2.85%
 http2/respond-with-fd.js benchmarker='h2load' clients=2 streams=100 requests=100000                  0.89 %       ±1.52%  ±2.02%  ±2.63%
 http2/respond-with-fd.js benchmarker='h2load' clients=2 streams=200 requests=100                     1.32 %       ±2.60%  ±3.46%  ±4.50%
 http2/respond-with-fd.js benchmarker='h2load' clients=2 streams=200 requests=1000             *      1.78 %       ±1.39%  ±1.85%  ±2.41%
 http2/respond-with-fd.js benchmarker='h2load' clients=2 streams=200 requests=10000                   0.07 %       ±1.60%  ±2.13%  ±2.77%
 http2/respond-with-fd.js benchmarker='h2load' clients=2 streams=200 requests=100000                  0.24 %       ±1.19%  ±1.59%  ±2.07%
 http2/simple.js benchmarker='h2load' clients=1 streams=1000 requests=100                            -1.40 %       ±6.87%  ±9.39% ±12.74%
 http2/simple.js benchmarker='h2load' clients=1 streams=1000 requests=1000                            0.77 %       ±2.21%  ±3.01%  ±4.07%
 http2/simple.js benchmarker='h2load' clients=1 streams=1000 requests=10000                          -0.16 %       ±2.26%  ±3.09%  ±4.18%
 http2/simple.js benchmarker='h2load' clients=1 streams=1000 requests=100000                         -0.21 %       ±2.70%  ±3.69%  ±4.99%
 http2/simple.js benchmarker='h2load' clients=1 streams=100 requests=100                              1.70 %       ±7.41% ±10.13% ±13.75%
 http2/simple.js benchmarker='h2load' clients=1 streams=100 requests=1000                            -0.39 %       ±2.08%  ±2.85%  ±3.88%
 http2/simple.js benchmarker='h2load' clients=1 streams=100 requests=10000                            0.77 %       ±1.84%  ±2.55%  ±3.55%
 http2/simple.js benchmarker='h2load' clients=1 streams=100 requests=100000                           0.57 %       ±2.32%  ±3.16%  ±4.28%
 http2/simple.js benchmarker='h2load' clients=1 streams=200 requests=100                              4.38 %       ±7.54% ±10.33% ±14.08%
 http2/simple.js benchmarker='h2load' clients=1 streams=200 requests=1000                            -1.61 %       ±2.65%  ±3.62%  ±4.89%
 http2/simple.js benchmarker='h2load' clients=1 streams=200 requests=10000                           -0.52 %       ±2.40%  ±3.27%  ±4.43%
 http2/simple.js benchmarker='h2load' clients=1 streams=200 requests=100000                    *     -2.25 %       ±2.25%  ±3.07%  ±4.15%
 http2/simple.js benchmarker='h2load' clients=2 streams=1000 requests=100                            -3.38 %       ±5.65%  ±7.70% ±10.43%
 http2/simple.js benchmarker='h2load' clients=2 streams=1000 requests=1000                            0.72 %       ±2.60%  ±3.55%  ±4.82%
 http2/simple.js benchmarker='h2load' clients=2 streams=1000 requests=10000                          -0.30 %       ±1.93%  ±2.66%  ±3.65%
 http2/simple.js benchmarker='h2load' clients=2 streams=1000 requests=100000                          0.92 %       ±1.64%  ±2.26%  ±3.08%
 http2/simple.js benchmarker='h2load' clients=2 streams=100 requests=100                             -2.94 %       ±8.55% ±11.70% ±15.90%
 http2/simple.js benchmarker='h2load' clients=2 streams=100 requests=1000                             0.58 %       ±2.83%  ±3.88%  ±5.28%
 http2/simple.js benchmarker='h2load' clients=2 streams=100 requests=10000                           -0.10 %       ±1.85%  ±2.54%  ±3.49%
 http2/simple.js benchmarker='h2load' clients=2 streams=100 requests=100000                           0.37 %       ±1.57%  ±2.14%  ±2.89%
 http2/simple.js benchmarker='h2load' clients=2 streams=200 requests=100                             -0.55 %       ±6.85%  ±9.35% ±12.65%
 http2/simple.js benchmarker='h2load' clients=2 streams=200 requests=1000                             0.54 %       ±3.15%  ±4.31%  ±5.86%
 http2/simple.js benchmarker='h2load' clients=2 streams=200 requests=10000                            0.42 %       ±2.03%  ±2.77%  ±3.75%
 http2/simple.js benchmarker='h2load' clients=2 streams=200 requests=100000                           0.04 %       ±1.46%  ±1.99%  ±2.70%

Be aware that when doing many comparisions the risk of a false-positive
result increases. In this case there are 52 comparisions, you can thus
expect the following amount of false-positive results:
  2.60 false positives, when considering a   5% risk acceptance (*, **, ***),
  0.52 false positives, when considering a   1% risk acceptance (**, ***),
  0.05 false positives, when considering a 0.1% risk acceptance (***)

@benjamingr
Copy link
Member

Can someone explain to me why the benchmark tool is confident that this improves performance by 1% in that benchmark? I don't see any changes that should do that but I don't know the http2 code well at all :)

@addaleax
Copy link
Member Author

@benjamingr I’d expect it to be one of the 0.52 false positives we should expect. Running that benchmark more frequently shows no significant change:

$ ./node benchmark/compare.js --new ./node --old ./node-master --runs 180 --filter headers --set nheaders=10 --set n=1000 http2 | Rscript benchmark/compare.R
[00:04:08|% 100| 1/1 files | 360/360 runs | 1/1 configs]: Done
                                                           confidence improvement accuracy (*)   (**)  (***)
 http2/headers.js benchmarker='h2load' nheaders=10 n=1000                 0.14 %       ±0.33% ±0.43% ±0.56%

@joyeecheung
Copy link
Member

@benjamingr It could be just fluctuations

@benjamingr
Copy link
Member

Ok, thanks for clarifying - maybe we should add a guide for how to read significance in the benchmark output. I've considered ** as high confidence before.

@addaleax addaleax added the author ready PRs that have at least one approval, no pending requests for changes, and a CI started. label May 29, 2018
@addaleax
Copy link
Member Author

@addaleax
Copy link
Member Author

Landed in bd85844, 15c7a49

@addaleax addaleax closed this May 31, 2018
@addaleax addaleax deleted the re-debug branch May 31, 2018 08:01
addaleax added a commit that referenced this pull request May 31, 2018
Implement utilities for easier debugging of Node.js core code,
inspired by the HTTP/2 debugging code. Debugging is, however,
implemented at runtime rather than at compile time, controlled
through a new `NODE_DEBUG_NATIVE=categories` environment variable.

The runtime overhead in the debugging-disabled case amounts to
1 well-cachable one-byte read per debug call.

PR-URL: #20987
Reviewed-By: Daniel Bevenius <daniel.bevenius@gmail.com>
Reviewed-By: Joyee Cheung <joyeec9h3@gmail.com>
Reviewed-By: Minwoo Jung <minwoo@nodesource.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
addaleax added a commit that referenced this pull request May 31, 2018
Remove `--debug-http2` as a compile-time feature and
make all debug statements available using `NODE_DEBUG_NATIVE=http2`
at runtime.

This probably makes the debugging-enabled case a bit slower due to
additional string concatenations, but switching to a runtime-checking
system makes debugging more flexible and can be applied more easily
to other parts of the source code as well.

PR-URL: #20987
Reviewed-By: Daniel Bevenius <daniel.bevenius@gmail.com>
Reviewed-By: Joyee Cheung <joyeec9h3@gmail.com>
Reviewed-By: Minwoo Jung <minwoo@nodesource.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
addaleax added a commit that referenced this pull request May 31, 2018
Implement utilities for easier debugging of Node.js core code,
inspired by the HTTP/2 debugging code. Debugging is, however,
implemented at runtime rather than at compile time, controlled
through a new `NODE_DEBUG_NATIVE=categories` environment variable.

The runtime overhead in the debugging-disabled case amounts to
1 well-cachable one-byte read per debug call.

PR-URL: #20987
Reviewed-By: Daniel Bevenius <daniel.bevenius@gmail.com>
Reviewed-By: Joyee Cheung <joyeec9h3@gmail.com>
Reviewed-By: Minwoo Jung <minwoo@nodesource.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
addaleax added a commit that referenced this pull request May 31, 2018
Remove `--debug-http2` as a compile-time feature and
make all debug statements available using `NODE_DEBUG_NATIVE=http2`
at runtime.

This probably makes the debugging-enabled case a bit slower due to
additional string concatenations, but switching to a runtime-checking
system makes debugging more flexible and can be applied more easily
to other parts of the source code as well.

PR-URL: #20987
Reviewed-By: Daniel Bevenius <daniel.bevenius@gmail.com>
Reviewed-By: Joyee Cheung <joyeec9h3@gmail.com>
Reviewed-By: Minwoo Jung <minwoo@nodesource.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
@MylesBorins MylesBorins mentioned this pull request Jun 6, 2018
alexeykuzmin added a commit to electron/node that referenced this pull request Sep 3, 2018
@addaleax addaleax mentioned this pull request Oct 20, 2018
2 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
author ready PRs that have at least one approval, no pending requests for changes, and a CI started. c++ Issues and PRs that require attention from people who are familiar with C++. http2 Issues or PRs related to the http2 subsystem. lib / src Issues and PRs related to general changes in the lib or src directory.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

8 participants