From 1d35a066e75c4f99a307b5f7f83321ca7ae8e1aa Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Micha=C3=ABl=20Zasso?= Date: Tue, 13 Aug 2024 14:37:02 +0200 Subject: [PATCH] src,test: ensure that V8 fast APIs are called MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Adds a debug-only macro that can be used to track when a V8 fast API is called. A map of counters is maintained in in thread-local storage and an internal API can be called to get the total count associated with a call id. Specific tests are added and `crypto.timingSafeEqual` as well as internal documentation are updated to show how to use the macro and test fast API calls without running long loops. PR-URL: https://github.com/nodejs/node/pull/54317 Reviewed-By: Robert Nagy Reviewed-By: James M Snell Reviewed-By: Yagiz Nizipli Reviewed-By: Tobias Nießen --- doc/contributing/adding-v8-fast-api.md | 48 +++++++++ node.gyp | 2 + src/crypto/crypto_timing.cc | 5 +- src/node_binding.cc | 7 ++ src/node_debug.cc | 101 ++++++++++++++++++ src/node_debug.h | 24 +++++ test/benchmark/test-benchmark-napi.js | 2 +- test/common/index.js | 4 +- test/parallel/test-debug-v8-fast-api.js | 59 ++++++++++ .../test-crypto-timing-safe-equal.js | 23 ++++ typings/globals.d.ts | 2 + typings/internalBinding/debug.d.ts | 10 ++ 12 files changed, 284 insertions(+), 3 deletions(-) create mode 100644 src/node_debug.cc create mode 100644 src/node_debug.h create mode 100644 test/parallel/test-debug-v8-fast-api.js create mode 100644 typings/internalBinding/debug.d.ts diff --git a/doc/contributing/adding-v8-fast-api.md b/doc/contributing/adding-v8-fast-api.md index 9af5858e59fca9..5326f8e5fd6987 100644 --- a/doc/contributing/adding-v8-fast-api.md +++ b/doc/contributing/adding-v8-fast-api.md @@ -29,6 +29,12 @@ for example, they may not trigger garbage collection. * To test fast APIs, make sure to run the tests in a loop with a decent iterations count to trigger relevant optimizations that prefer the fast API over the slow one. +* In debug mode (`--debug` or `--debug-node` flags), the fast API calls can be + tracked using the `TRACK_V8_FAST_API_CALL("key")` macro. This can be used to + count how many times fast paths are taken during tests. The key is a global + identifier and should be unique across the codebase. + Use `"binding_name.function_name"` or `"binding_name.function_name.suffix"` to + ensure uniqueness. * The fast callback must be idempotent up to the point where error and fallback conditions are checked, because otherwise executing the slow callback might produce visible side effects twice. @@ -77,6 +83,7 @@ A typical function that communicates between JavaScript and C++ is as follows. * On the C++ side: ```cpp + #include "node_debug.h" #include "v8-fast-api-calls.h" namespace node { @@ -102,9 +109,11 @@ A typical function that communicates between JavaScript and C++ is as follows. const int32_t b, v8::FastApiCallbackOptions& options) { if (b == 0) { + TRACK_V8_FAST_API_CALL("custom_namespace.divide.error"); options.fallback = true; return 0; } else { + TRACK_V8_FAST_API_CALL("custom_namespace.divide.ok"); return a / b; } } @@ -148,3 +157,42 @@ A typical function that communicates between JavaScript and C++ is as follows. const int32_t b, v8::FastApiCallbackOptions& options); ``` + +* In the unit tests: + + Since the fast API function uses `TRACK_V8_FAST_API_CALL`, we can ensure that + the fast paths are taken and test them by writing tests that force + V8 optimizations and check the counters. + + ```js + // Flags: --expose-internals --no-warnings --allow-natives-syntax + 'use strict'; + const common = require('../common'); + + const { internalBinding } = require('internal/test/binding'); + // We could also require a function that uses the internal binding internally. + const { divide } = internalBinding('custom_namespace'); + + if (common.isDebug) { + const { getV8FastApiCallCount } = internalBinding('debug'); + + // The function that will be optimized. It has to be a function written in + // JavaScript. Since `divide` comes from the C++ side, we need to wrap it. + function testFastPath(a, b) { + return divide(a, b); + } + + eval('%PrepareFunctionForOptimization(testFastPath)'); + // This call will let V8 know about the argument types that the function expects. + assert.strictEqual(testFastPath(6, 3), 2); + + eval('%OptimizeFunctionOnNextCall(testFastPath)'); + assert.strictEqual(testFastPath(8, 2), 4); + assert.throws(() => testFastPath(1, 0), { + code: 'ERR_INVALID_STATE', + }); + + assert.strictEqual(getV8FastApiCallCount('custom_namespace.divide.ok'), 1); + assert.strictEqual(getV8FastApiCallCount('custom_namespace.divide.error'), 1); + } + ``` diff --git a/node.gyp b/node.gyp index 7515d7f8fc0151..700606e9061deb 100644 --- a/node.gyp +++ b/node.gyp @@ -107,6 +107,7 @@ 'src/node_constants.cc', 'src/node_contextify.cc', 'src/node_credentials.cc', + 'src/node_debug.cc', 'src/node_dir.cc', 'src/node_dotenv.cc', 'src/node_env_var.cc', @@ -229,6 +230,7 @@ 'src/node_constants.h', 'src/node_context_data.h', 'src/node_contextify.h', + 'src/node_debug.h', 'src/node_dir.h', 'src/node_dotenv.h', 'src/node_errors.h', diff --git a/src/crypto/crypto_timing.cc b/src/crypto/crypto_timing.cc index 103a620d63726f..3d8ccc77b5952a 100644 --- a/src/crypto/crypto_timing.cc +++ b/src/crypto/crypto_timing.cc @@ -1,9 +1,10 @@ #include "crypto/crypto_timing.h" #include "crypto/crypto_util.h" #include "env-inl.h" +#include "node.h" +#include "node_debug.h" #include "node_errors.h" #include "v8.h" -#include "node.h" #include @@ -57,10 +58,12 @@ bool FastTimingSafeEqual(Local receiver, uint8_t* data_b; if (a.length() != b.length() || !a.getStorageIfAligned(&data_a) || !b.getStorageIfAligned(&data_b)) { + TRACK_V8_FAST_API_CALL("crypto.timingSafeEqual.error"); options.fallback = true; return false; } + TRACK_V8_FAST_API_CALL("crypto.timingSafeEqual.ok"); return CRYPTO_memcmp(data_a, data_b, a.length()) == 0; } diff --git a/src/node_binding.cc b/src/node_binding.cc index 4f1e221c86de94..c2ef9b36d5b296 100644 --- a/src/node_binding.cc +++ b/src/node_binding.cc @@ -20,6 +20,12 @@ #define NODE_BUILTIN_PROFILER_BINDINGS(V) #endif +#ifdef DEBUG +#define NODE_BUILTIN_DEBUG_BINDINGS(V) V(debug) +#else +#define NODE_BUILTIN_DEBUG_BINDINGS(V) +#endif + // A list of built-in bindings. In order to do binding registration // in node::Init(), need to add built-in bindings in the following list. // Then in binding::RegisterBuiltinBindings(), it calls bindings' registration @@ -96,6 +102,7 @@ NODE_BUILTIN_OPENSSL_BINDINGS(V) \ NODE_BUILTIN_ICU_BINDINGS(V) \ NODE_BUILTIN_PROFILER_BINDINGS(V) \ + NODE_BUILTIN_DEBUG_BINDINGS(V) \ NODE_BUILTIN_QUIC_BINDINGS(V) // This is used to load built-in bindings. Instead of using diff --git a/src/node_debug.cc b/src/node_debug.cc new file mode 100644 index 00000000000000..d87cdf61d2d92d --- /dev/null +++ b/src/node_debug.cc @@ -0,0 +1,101 @@ +#include "node_debug.h" + +#ifdef DEBUG +#include "node_binding.h" + +#include "env-inl.h" +#include "util.h" +#include "v8-fast-api-calls.h" +#include "v8.h" + +#include +#include +#endif // DEBUG + +namespace node { +namespace debug { + +#ifdef DEBUG +using v8::Context; +using v8::FastApiCallbackOptions; +using v8::FunctionCallbackInfo; +using v8::Local; +using v8::Number; +using v8::Object; +using v8::Value; + +thread_local std::unordered_map v8_fast_api_call_counts; + +void TrackV8FastApiCall(std::string_view key) { + v8_fast_api_call_counts[key]++; +} + +int GetV8FastApiCallCount(std::string_view key) { + return v8_fast_api_call_counts[key]; +} + +void GetV8FastApiCallCount(const FunctionCallbackInfo& args) { + Environment* env = Environment::GetCurrent(args); + if (!args[0]->IsString()) { + env->ThrowError("getV8FastApiCallCount must be called with a string"); + return; + } + Utf8Value utf8_key(env->isolate(), args[0]); + args.GetReturnValue().Set(GetV8FastApiCallCount(utf8_key.ToString())); +} + +void SlowIsEven(const FunctionCallbackInfo& args) { + Environment* env = Environment::GetCurrent(args); + if (!args[0]->IsNumber()) { + env->ThrowError("isEven must be called with a number"); + return; + } + int64_t value = args[0].As()->Value(); + args.GetReturnValue().Set(value % 2 == 0); +} + +bool FastIsEven(Local receiver, + const int64_t value, + // NOLINTNEXTLINE(runtime/references) + FastApiCallbackOptions& options) { + TRACK_V8_FAST_API_CALL("debug.isEven"); + return value % 2 == 0; +} + +void SlowIsOdd(const FunctionCallbackInfo& args) { + Environment* env = Environment::GetCurrent(args); + if (!args[0]->IsNumber()) { + env->ThrowError("isOdd must be called with a number"); + return; + } + int64_t value = args[0].As()->Value(); + args.GetReturnValue().Set(value % 2 != 0); +} + +bool FastIsOdd(Local receiver, + const int64_t value, + // NOLINTNEXTLINE(runtime/references) + FastApiCallbackOptions& options) { + TRACK_V8_FAST_API_CALL("debug.isOdd"); + return value % 2 != 0; +} + +static v8::CFunction fast_is_even(v8::CFunction::Make(FastIsEven)); +static v8::CFunction fast_is_odd(v8::CFunction::Make(FastIsOdd)); + +void Initialize(Local target, + Local unused, + Local context, + void* priv) { + SetMethod(context, target, "getV8FastApiCallCount", GetV8FastApiCallCount); + SetFastMethod(context, target, "isEven", SlowIsEven, &fast_is_even); + SetFastMethod(context, target, "isOdd", SlowIsOdd, &fast_is_odd); +} +#endif // DEBUG + +} // namespace debug +} // namespace node + +#ifdef DEBUG +NODE_BINDING_CONTEXT_AWARE_INTERNAL(debug, node::debug::Initialize) +#endif // DEBUG diff --git a/src/node_debug.h b/src/node_debug.h new file mode 100644 index 00000000000000..f42aeb8ba01162 --- /dev/null +++ b/src/node_debug.h @@ -0,0 +1,24 @@ +#pragma once + +#if defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS + +#ifdef DEBUG +#include +#endif // DEBUG + +namespace node { +namespace debug { + +#ifdef DEBUG +void TrackV8FastApiCall(std::string_view key); +int GetV8FastApiCallCount(std::string_view key); + +#define TRACK_V8_FAST_API_CALL(key) node::debug::TrackV8FastApiCall(key) +#else // !DEBUG +#define TRACK_V8_FAST_API_CALL(key) +#endif // DEBUG + +} // namespace debug +} // namespace node + +#endif // defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS diff --git a/test/benchmark/test-benchmark-napi.js b/test/benchmark/test-benchmark-napi.js index 5c6a8aa01187ea..7164efe3d4e718 100644 --- a/test/benchmark/test-benchmark-napi.js +++ b/test/benchmark/test-benchmark-napi.js @@ -10,7 +10,7 @@ if (!common.isMainThread) { common.skip('addons are not supported in workers'); } -if (process.features.debug) { +if (common.isDebug) { common.skip('benchmark does not work with debug build yet'); } const runBenchmark = require('../common/benchmark'); diff --git a/test/common/index.js b/test/common/index.js index 8bf8136e5025f0..c70f5b6016870c 100644 --- a/test/common/index.js +++ b/test/common/index.js @@ -143,6 +143,7 @@ const isOpenBSD = process.platform === 'openbsd'; const isLinux = process.platform === 'linux'; const isMacOS = process.platform === 'darwin'; const isASan = process.config.variables.asan === 1; +const isDebug = process.features.debug; const isPi = (() => { try { // Normal Raspberry Pi detection is to find the `Raspberry Pi` string in @@ -280,7 +281,7 @@ function platformTimeout(ms) { const multipliers = typeof ms === 'bigint' ? { two: 2n, four: 4n, seven: 7n } : { two: 2, four: 4, seven: 7 }; - if (process.features.debug) + if (isDebug) ms = multipliers.two * ms; if (exports.isAIX || exports.isIBMi) @@ -998,6 +999,7 @@ const common = { invalidArgTypeHelper, isAlive, isASan, + isDebug, isDumbTerminal, isFreeBSD, isLinux, diff --git a/test/parallel/test-debug-v8-fast-api.js b/test/parallel/test-debug-v8-fast-api.js new file mode 100644 index 00000000000000..78a9ebbb15fe78 --- /dev/null +++ b/test/parallel/test-debug-v8-fast-api.js @@ -0,0 +1,59 @@ +// Flags: --expose-internals --no-warnings --allow-natives-syntax +'use strict'; +const common = require('../common'); + +const assert = require('assert'); +const { internalBinding } = require('internal/test/binding'); + +if (!common.isDebug) { + assert.throws(() => internalBinding('debug'), { + message: 'No such binding: debug' + }); + return; +} + +const { + getV8FastApiCallCount, + isEven, + isOdd, +} = internalBinding('debug'); + +assert.throws(() => getV8FastApiCallCount(), { + message: 'getV8FastApiCallCount must be called with a string', +}); + +function testIsEven() { + for (let i = 0; i < 10; i++) { + assert.strictEqual(isEven(i), i % 2 === 0); + } +} + +function testIsOdd() { + for (let i = 0; i < 20; i++) { + assert.strictEqual(isOdd(i), i % 2 !== 0); + } +} + +// Should return 0 by default for any string. +assert.strictEqual(getV8FastApiCallCount(''), 0); +assert.strictEqual(getV8FastApiCallCount('foo'), 0); +assert.strictEqual(getV8FastApiCallCount('debug.isEven'), 0); +assert.strictEqual(getV8FastApiCallCount('debug.isOdd'), 0); + +eval('%PrepareFunctionForOptimization(testIsEven)'); +testIsEven(); +eval('%PrepareFunctionForOptimization(testIsOdd)'); +testIsOdd(); + +// Functions should not be optimized yet. +assert.strictEqual(getV8FastApiCallCount('debug.isEven'), 0); +assert.strictEqual(getV8FastApiCallCount('debug.isOdd'), 0); + +eval('%OptimizeFunctionOnNextCall(testIsEven)'); +testIsEven(); +eval('%OptimizeFunctionOnNextCall(testIsOdd)'); +testIsOdd(); + +// Functions should have been optimized and fast path taken. +assert.strictEqual(getV8FastApiCallCount('debug.isEven'), 10); +assert.strictEqual(getV8FastApiCallCount('debug.isOdd'), 20); diff --git a/test/sequential/test-crypto-timing-safe-equal.js b/test/sequential/test-crypto-timing-safe-equal.js index 13190692b84749..97fd35448c98b4 100644 --- a/test/sequential/test-crypto-timing-safe-equal.js +++ b/test/sequential/test-crypto-timing-safe-equal.js @@ -1,3 +1,4 @@ +// Flags: --expose-internals --no-warnings --allow-natives-syntax 'use strict'; const common = require('../common'); if (!common.hasCrypto) @@ -91,3 +92,25 @@ assert.throws( name: 'TypeError', } ); + +if (common.isDebug) { + const { internalBinding } = require('internal/test/binding'); + const { getV8FastApiCallCount } = internalBinding('debug'); + + const foo = Buffer.from('foo'); + const bar = Buffer.from('bar'); + const longer = Buffer.from('longer'); + function testFastPath(buf1, buf2) { + return crypto.timingSafeEqual(buf1, buf2); + } + eval('%PrepareFunctionForOptimization(testFastPath)'); + assert.strictEqual(testFastPath(foo, bar), false); + eval('%OptimizeFunctionOnNextCall(testFastPath)'); + assert.strictEqual(testFastPath(foo, bar), false); + assert.strictEqual(testFastPath(foo, foo), true); + assert.throws(() => testFastPath(foo, longer), { + code: 'ERR_CRYPTO_TIMING_SAFE_EQUAL_LENGTH', + }); + assert.strictEqual(getV8FastApiCallCount('crypto.timingSafeEqual.ok'), 2); + assert.strictEqual(getV8FastApiCallCount('crypto.timingSafeEqual.error'), 1); +} diff --git a/typings/globals.d.ts b/typings/globals.d.ts index c7f382e5ace11a..8c7ba495cdf26e 100644 --- a/typings/globals.d.ts +++ b/typings/globals.d.ts @@ -2,6 +2,7 @@ import { AsyncWrapBinding } from './internalBinding/async_wrap'; import { BlobBinding } from './internalBinding/blob'; import { ConfigBinding } from './internalBinding/config'; import { ConstantsBinding } from './internalBinding/constants'; +import { DebugBinding } from './internalBinding/debug'; import { HttpParserBinding } from './internalBinding/http_parser'; import { FsBinding } from './internalBinding/fs'; import { FsDirBinding } from './internalBinding/fs_dir'; @@ -35,6 +36,7 @@ interface InternalBindingMap { blob: BlobBinding; config: ConfigBinding; constants: ConstantsBinding; + debug: DebugBinding; fs: FsBinding; fs_dir: FsDirBinding; http_parser: HttpParserBinding; diff --git a/typings/internalBinding/debug.d.ts b/typings/internalBinding/debug.d.ts new file mode 100644 index 00000000000000..2d57b33a1f0b6c --- /dev/null +++ b/typings/internalBinding/debug.d.ts @@ -0,0 +1,10 @@ +/** + * The `internalBinding('debug')` binding provides access to internal debugging + * utilities. They are only available when Node.js is built with the `--debug` + * or `--debug-node` compile-time flags. + */ +export interface DebugBinding { + getV8FastApiCallCount(name: string): number; + isEven(value: number): boolean; + isOdd(value: number): boolean; +}