From 138d5bd8c3846566a637ff467a911b8f3c503842 Mon Sep 17 00:00:00 2001 From: Margaret Nolan Date: Mon, 24 Jun 2019 12:00:39 -0700 Subject: [PATCH] feat: allow collecting profiles with more accurate line numbers (#69) * feat: allow collecting profiles with more accurate line numbers * address comments * ensure binaries are built in system tests --- .gitignore | 1 + bindings/profiler.cc | 222 +++++++++++++++++++--- package-lock.json | 6 +- system-test/Dockerfile.linux | 1 + system-test/busybench-js/package.json | 13 ++ system-test/busybench-js/src/busybench.js | 78 ++++++++ system-test/system_test.sh | 8 + system-test/test.sh | 37 +++- ts/src/time-profiler-bindings.ts | 10 +- ts/src/time-profiler.ts | 16 +- 10 files changed, 345 insertions(+), 47 deletions(-) create mode 100644 system-test/busybench-js/package.json create mode 100644 system-test/busybench-js/src/busybench.js diff --git a/.gitignore b/.gitignore index 6a30a5ed..1b6e71b1 100644 --- a/.gitignore +++ b/.gitignore @@ -6,3 +6,4 @@ out node_modules system-test/busybench/package-lock.json +system-test/busybench-js/package-lock.json diff --git a/bindings/profiler.cc b/bindings/profiler.cc index c92623cd..d88346ff 100644 --- a/bindings/profiler.cc +++ b/bindings/profiler.cc @@ -79,10 +79,14 @@ NAN_METHOD(StartSamplingHeapProfiler) { } } +// Signature: +// stopSamplingHeapProfiler() NAN_METHOD(StopSamplingHeapProfiler) { info.GetIsolate()->GetHeapProfiler()->StopSamplingHeapProfiler(); } +// Signature: +// getAllocationProfile(): AllocationProfileNode NAN_METHOD(GetAllocationProfile) { std::unique_ptr profile( info.GetIsolate()->GetHeapProfiler()->GetAllocationProfile()); @@ -101,37 +105,158 @@ CpuProfiler* cpuProfiler = CpuProfiler::New(v8::Isolate::GetCurrent()); CpuProfiler* cpuProfiler = v8::Isolate::GetCurrent()->GetCpuProfiler(); #endif +Local CreateTimeNode(Local name, Local scriptName, + Local scriptId, Local lineNumber, + Local columnNumber, Local hitCount, + Local children) { + Local js_node = Nan::New(); + js_node->Set(Nan::New("name").ToLocalChecked(), name); + js_node->Set(Nan::New("scriptName").ToLocalChecked(), scriptName); + js_node->Set(Nan::New("scriptId").ToLocalChecked(), scriptId); + js_node->Set(Nan::New("lineNumber").ToLocalChecked(), lineNumber); + js_node->Set(Nan::New("columnNumber").ToLocalChecked(), columnNumber); + js_node->Set(Nan::New("hitCount").ToLocalChecked(), hitCount); + js_node->Set(Nan::New("children").ToLocalChecked(), children); + return js_node; +} + + +#if NODE_MODULE_VERSION > NODE_11_0_MODULE_VERSION +Local TranslateLineNumbersTimeProfileNode(const CpuProfileNode* parent, + const CpuProfileNode* node); + +Local GetLineNumberTimeProfileChildren(const CpuProfileNode* parent, + const CpuProfileNode* node) { + unsigned int index = 0; + Local children; + int32_t count = node->GetChildrenCount(); + + unsigned int hitLineCount = node->GetHitLineCount(); + unsigned int hitCount = node->GetHitCount(); + if (hitLineCount > 0) { + CpuProfileNode::LineTick entries[hitLineCount]; + node->GetLineTicks(&entries[0], hitLineCount); + children = Nan::New(count + hitLineCount); + for (const CpuProfileNode::LineTick entry : entries) { + children->Set(index++, CreateTimeNode( + node->GetFunctionName(), + node->GetScriptResourceName(), + Nan::New(node->GetScriptId()), + Nan::New(entry.line), + Nan::New(0), + Nan::New(entry.hit_count), + Nan::New(0) + )); + } + } else if (hitCount > 0) { + // Handle nodes for pseudo-functions like "process" and "garbage collection" + // which do not have hit line counts. + children = Nan::New(count + 1); + children->Set(index++, CreateTimeNode( + node->GetFunctionName(), + node->GetScriptResourceName(), + Nan::New(node->GetScriptId()), + Nan::New(node->GetLineNumber()), + Nan::New(node->GetColumnNumber()), + Nan::New(hitCount), + Nan::New(0) + )); + } else { + children = Nan::New(count); + } + + for (int32_t i = 0; i < count; i++) { + children->Set(index++, TranslateLineNumbersTimeProfileNode(node, + node->GetChild(i))); + }; + + return children; +} + +Local TranslateLineNumbersTimeProfileNode(const CpuProfileNode* parent, + const CpuProfileNode* node) { + return CreateTimeNode(parent->GetFunctionName(), + parent->GetScriptResourceName(), + Nan::New(parent->GetScriptId()), + Nan::New(node->GetLineNumber()), + Nan::New(node->GetColumnNumber()), + Nan::New(0), + GetLineNumberTimeProfileChildren(parent, node)); +} + +// In profiles with line-level accurate line numbers, a node's line number +// and column number refer to the line/column from which the function was +// called. +Local TranslateLineNumbersTimeProfileRoot(const CpuProfileNode* node) { + int32_t count = node->GetChildrenCount(); + Local childrenArrs[count]; + int32_t childCount = 0; + for (int32_t i = 0; i < count; i++) { + Local c = GetLineNumberTimeProfileChildren(node, node->GetChild(i)); + childCount = childCount + c->Length(); + childrenArrs[i] = c; + } + + Local children = Nan::New(childCount); + int32_t idx = 0; + for (int32_t i = 0; i < count; i++) { + Local arr = childrenArrs[i]; + for (int32_t j = 0; j < arr->Length(); j++) { + children->Set(idx, arr->Get(j)); + idx++; + } + } + + return CreateTimeNode( + node->GetFunctionName(), + node->GetScriptResourceName(), + Nan::New(node->GetScriptId()), + Nan::New(node->GetLineNumber()), + Nan::New(node->GetColumnNumber()), + Nan::New(0), + children + ); +} +#endif Local TranslateTimeProfileNode(const CpuProfileNode* node) { - Local js_node = Nan::New(); - js_node->Set(Nan::New("name").ToLocalChecked(), - node->GetFunctionName()); - js_node->Set(Nan::New("scriptName").ToLocalChecked(), - node->GetScriptResourceName()); - js_node->Set(Nan::New("scriptId").ToLocalChecked(), - Nan::New(node->GetScriptId())); - js_node->Set(Nan::New("lineNumber").ToLocalChecked(), - Nan::New(node->GetLineNumber())); - js_node->Set(Nan::New("columnNumber").ToLocalChecked(), - Nan::New(node->GetColumnNumber())); - js_node->Set(Nan::New("hitCount").ToLocalChecked(), - Nan::New(node->GetHitCount())); int32_t count = node->GetChildrenCount(); Local children = Nan::New(count); for (int32_t i = 0; i < count; i++) { children->Set(i, TranslateTimeProfileNode(node->GetChild(i))); } - js_node->Set(Nan::New("children").ToLocalChecked(), - children); - return js_node; + + return CreateTimeNode( + node->GetFunctionName(), + node->GetScriptResourceName(), + Nan::New(node->GetScriptId()), + Nan::New(node->GetLineNumber()), + Nan::New(node->GetColumnNumber()), + Nan::New(node->GetHitCount()), + children + ); } -Local TranslateTimeProfile(const CpuProfile* profile) { +Local TranslateTimeProfile(const CpuProfile* profile, bool hasDetailedLines) { Local js_profile = Nan::New(); js_profile->Set(Nan::New("title").ToLocalChecked(), profile->GetTitle()); - js_profile->Set(Nan::New("topDownRoot").ToLocalChecked(), + +#if NODE_MODULE_VERSION > NODE_11_0_MODULE_VERSION + if (hasDetailedLines) { + js_profile->Set( + Nan::New("topDownRoot").ToLocalChecked(), + TranslateLineNumbersTimeProfileRoot(profile->GetTopDownRoot())); + } else { + js_profile->Set( + Nan::New("topDownRoot").ToLocalChecked(), + TranslateTimeProfileNode(profile->GetTopDownRoot())); + } +#else + js_profile->Set( + Nan::New("topDownRoot").ToLocalChecked(), TranslateTimeProfileNode(profile->GetTopDownRoot())); +#endif js_profile->Set(Nan::New("startTime").ToLocalChecked(), Nan::New(profile->GetStartTime())); js_profile->Set(Nan::New("endTime").ToLocalChecked(), @@ -139,23 +264,67 @@ Local TranslateTimeProfile(const CpuProfile* profile) { return js_profile; } +// Signature: +// startProfiling(runName: string, includeLineInfo: boolean) NAN_METHOD(StartProfiling) { - Local name = info[0].As(); + if (info.Length() != 2) { + return Nan::ThrowTypeError("StartProfling must have two arguments."); + } + if (!info[0]->IsString()) { + return Nan::ThrowTypeError("First argument must be a string."); + } + if (!info[1]->IsBoolean()) { + return Nan::ThrowTypeError("Second argument must be a boolean."); + } + + Local name = + Nan::MaybeLocal(info[0].As()).ToLocalChecked(); - // Sample counts and timestamps are not used, so we do not need to record - // samples. - cpuProfiler->StartProfiling(name, false); +// Sample counts and timestamps are not used, so we do not need to record +// samples. +bool recordSamples = false; + +// Line-level accurate line information is not available in Node 11 or earlier. +#if NODE_MODULE_VERSION > NODE_11_0_MODULE_VERSION + bool includeLineInfo = + Nan::MaybeLocal(info[1].As()).ToLocalChecked()->Value(); + if (includeLineInfo) { + cpuProfiler->StartProfiling(name, CpuProfilingMode::kCallerLineNumbers, + recordSamples); + } else { + cpuProfiler->StartProfiling(name, recordSamples); + } +#else + cpuProfiler->StartProfiling(name, recordSamples); +#endif } +// Signature: +// stopProfiling(runName: string, includedLineInfo: boolean): TimeProfile NAN_METHOD(StopProfiling) { - Local name = info[0].As(); - CpuProfile* profile = - cpuProfiler->StopProfiling(name); - Local translated_profile = TranslateTimeProfile(profile); + if (info.Length() != 2) { + return Nan::ThrowTypeError("StopProfling must have two arguments."); + } + if (!info[0]->IsString()) { + return Nan::ThrowTypeError("First argument must be a string."); + } + if (!info[1]->IsBoolean()) { + return Nan::ThrowTypeError("Second argument must be a boolean."); + } + Local name = + Nan::MaybeLocal(info[0].As()).ToLocalChecked(); + bool includedLineInfo = + Nan::MaybeLocal(info[1].As()).ToLocalChecked()->Value(); + + CpuProfile* profile = cpuProfiler->StopProfiling(name); + Local translated_profile = + TranslateTimeProfile(profile, includedLineInfo); profile->Delete(); info.GetReturnValue().Set(translated_profile); } +// Signature: +// setSamplingInterval(intervalMicros: number) NAN_METHOD(SetSamplingInterval) { #if NODE_MODULE_VERSION > NODE_8_0_MODULE_VERSION int us = info[0].As()->Value(); @@ -187,3 +356,4 @@ NAN_MODULE_INIT(InitAll) { } NODE_MODULE(google_cloud_profiler, InitAll); + diff --git a/package-lock.json b/package-lock.json index 6ee1c7ec..453b8d0c 100644 --- a/package-lock.json +++ b/package-lock.json @@ -3007,7 +3007,7 @@ "npm-package-arg": { "version": "6.1.0", "resolved": "https://registry.npmjs.org/npm-package-arg/-/npm-package-arg-6.1.0.tgz", - "integrity": "sha512-zYbhP2k9DbJhA0Z3HKUePUgdB1x7MfIfKssC+WLPFMKTBZKpZh5m13PgexJjCq6KW7j17r0jHWcCpxEqnnncSA==", + "integrity": "sha1-Fa4eJ1ilAn77TCUFVLhac323/ME=", "dev": true, "requires": { "hosted-git-info": "^2.6.0", @@ -3899,7 +3899,7 @@ "spdx-compare": { "version": "1.0.0", "resolved": "https://registry.npmjs.org/spdx-compare/-/spdx-compare-1.0.0.tgz", - "integrity": "sha512-C1mDZOX0hnu0ep9dfmuoi03+eOdDoz2yvK79RxbcrVEG1NO1Ph35yW102DHWKN4pk80nwCgeMmSY5L25VE4D9A==", + "integrity": "sha1-LFXxFzYgeNdAnm17CM5wqFfNPtc=", "dev": true, "requires": { "array-find-index": "^1.0.2", @@ -3942,7 +3942,7 @@ "spdx-ranges": { "version": "2.1.0", "resolved": "https://registry.npmjs.org/spdx-ranges/-/spdx-ranges-2.1.0.tgz", - "integrity": "sha512-OOWghvosfmECc9edy/A9j7GabERmn8bJWHc0J1knVytQtO5Rw7VfxK6CDqmivJhfMJqWhWWUfffNNMPYvyvyQA==", + "integrity": "sha1-AzQj64N+ySZGOq9bgJe9bykx4bg=", "dev": true }, "spdx-satisfies": { diff --git a/system-test/Dockerfile.linux b/system-test/Dockerfile.linux index a3f61b16..34e84e33 100644 --- a/system-test/Dockerfile.linux +++ b/system-test/Dockerfile.linux @@ -10,6 +10,7 @@ FROM debian:stretch ARG NODE_VERSION ARG NVM_NODEJS_ORG_MIRROR ARG ADDITIONAL_PACKAGES +ARG VERIFY_TIME_LINE_NUMBERS RUN apt-get update && apt-get install -y curl $ADDITIONAL_PACKAGES \ && rm -rf /var/lib/apt/lists/* diff --git a/system-test/busybench-js/package.json b/system-test/busybench-js/package.json new file mode 100644 index 00000000..a4db0050 --- /dev/null +++ b/system-test/busybench-js/package.json @@ -0,0 +1,13 @@ +{ + "name": "busybench", + "version": "1.0.0", + "description": "", + "main": "index.js", + "dependencies": {}, + "devDependencies": {}, + "scripts": { + "test": "echo \"Error: no test specified\" && exit 1" + }, + "author": "", + "license": "ISC" +} diff --git a/system-test/busybench-js/src/busybench.js b/system-test/busybench-js/src/busybench.js new file mode 100644 index 00000000..d7a49ffc --- /dev/null +++ b/system-test/busybench-js/src/busybench.js @@ -0,0 +1,78 @@ +/** + * Copyright 2019 Google Inc. All Rights Reserved. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +const fs = require('fs'); +const pify = require('pify'); +const pprof = require('pprof'); + +const writeFilePromise = pify(fs.writeFile); + +const startTime = Date.now(); +const testArr = []; + +/** + * Fills several arrays, then calls itself with setTimeout. + * It continues to do this until durationSeconds after the startTime. + */ +function busyLoop(durationSeconds) { + for (let i = 0; i < testArr.length; i++) { + for (let j = 0; j < testArr[i].length; j++) { + testArr[i][j] = Math.sqrt(j * testArr[i][j]); + } + } + if (Date.now() - startTime < 1000 * durationSeconds) { + setTimeout(() => busyLoop(durationSeconds), 5); + } +} + +function benchmark(durationSeconds) { + // Allocate 16 MiB in 64 KiB chunks. + for (let i = 0; i < 16 * 16; i++) { + testArr[i] = new Array(64 * 1024); + } + busyLoop(durationSeconds); +} + +async function collectAndSaveTimeProfile(durationSeconds, sourceMapper, + lineNumbers) { + const profile = await pprof.time.profile({ + durationMillis: 1000 * durationSeconds, + lineNumbers: lineNumbers, + sourceMapper: sourceMapper, + }); + const buf = await pprof.encode(profile); + await writeFilePromise('time.pb.gz', buf); +} + +async function collectAndSaveHeapProfile(sourceMapper) { + const profile = pprof.heap.profile(undefined, sourceMapper); + const buf = await pprof.encode(profile); + await writeFilePromise('heap.pb.gz', buf); +} + +async function collectAndSaveProfiles(collectLineNumberTimeProfile) { + const sourceMapper = await pprof.SourceMapper.create([process.cwd()]); + collectAndSaveHeapProfile(sourceMapper); + collectAndSaveTimeProfile(durationSeconds/2, sourceMapper, collectLineNumberTimeProfile); +} + +const durationSeconds = Number(process.argv.length > 2 ? process.argv[2] : 30); +const collectLineNumberTimeProfile = Boolean(process.argv.length > 3 ? process.argv[3] : false); + +pprof.heap.start(512 * 1024, 64); +benchmark(durationSeconds); + +collectAndSaveProfiles(collectLineNumberTimeProfile); diff --git a/system-test/system_test.sh b/system-test/system_test.sh index effa3e4c..973027cb 100755 --- a/system-test/system_test.sh +++ b/system-test/system_test.sh @@ -33,6 +33,14 @@ for i in ${NODE_VERSIONS[@]}; do docker run -v $PWD/..:/src -e BINARY_HOST="$BINARY_HOST" node$i-linux \ /src/system-test/test.sh + # Test support for accurate line numbers with node versions supporting this + # feature. + if [ "$i" != "8" ] && [ "$i" != "10" ] && [ "$i" != "11" ]; then + docker run -v $PWD/..:/src -e BINARY_HOST="$BINARY_HOST" \ + -e VERIFY_TIME_LINE_NUMBERS="true" node$i-linux \ + /src/system-test/test.sh + fi + # Skip running on alpine if NVM_NODEJS_ORG_MIRROR is specified. if [[ ! -z "$NVM_NODEJS_ORG_MIRROR" ]]; then continue diff --git a/system-test/test.sh b/system-test/test.sh index 4048c285..101382ee 100755 --- a/system-test/test.sh +++ b/system-test/test.sh @@ -38,23 +38,42 @@ npm pack >/dev/null VERSION=$(node -e "console.log(require('./package.json').version);") PROFILER="$PWD/pprof-$VERSION.tgz" +if [[ "$VERIFY_TIME_LINE_NUMBERS" == "true" ]]; then + BENCHDIR="$PWD/system-test/busybench-js" + BENCHPATH="src/busybench.js" +else + BENCHDIR="$PWD/system-test/busybench" + BENCHPATH="build/src/busybench.js" +fi + TESTDIR=$(mktemp -d) -cp -r "$PWD/system-test/busybench" "$TESTDIR" +cp -r "$BENCHDIR" "$TESTDIR/busybench" cd "$TESTDIR/busybench" retry npm_install pify @types/pify typescript gts @types/node >/dev/null retry npm_install --nodedir="$NODEDIR" \ - ${BINARY_HOST:+--pprof_binary_host_mirror=$BINARY_HOST} \ + $([ -z "$BINARY_HOST" ] && echo "--build-from-source=pprof" \ + || echo "--pprof_binary_host_mirror=$BINARY_HOST")\ "$PROFILER">/dev/null -npm run compile >/dev/null +if [[ "$VERIFY_TIME_LINE_NUMBERS" != "true" ]]; then + npm run compile +fi node -v -node --trace-warnings build/src/busybench.js 10 -ls -l +node --trace-warnings "$BENCHPATH" 10 $VERIFY_TIME_LINE_NUMBERS + +if [[ "$VERIFY_TIME_LINE_NUMBERS" == "true" ]]; then + pprof -lines -top -nodecount=2 time.pb.gz | \ + grep "busyLoop.*src/busybench.js:33" + pprof -filefunctions -top -nodecount=2 heap.pb.gz | \ + grep "busyLoop.*src/busybench.js" +else + pprof -filefunctions -top -nodecount=2 time.pb.gz | \ + grep "busyLoop.*src/busybench.ts" + pprof -filefunctions -top -nodecount=2 heap.pb.gz | \ + grep "busyLoop.*src/busybench.ts" +fi + -pprof -filefunctions -top -nodecount=2 time.pb.gz | \ - grep "busyLoop.*src/busybench.ts" -pprof -filefunctions -top -nodecount=2 heap.pb.gz | \ - grep "busyLoop.*src/busybench.ts" echo '** TEST PASSED **' diff --git a/ts/src/time-profiler-bindings.ts b/ts/src/time-profiler-bindings.ts index ac8d06a6..1d6b529c 100644 --- a/ts/src/time-profiler-bindings.ts +++ b/ts/src/time-profiler-bindings.ts @@ -23,13 +23,13 @@ const profiler = require(bindingPath); // Wrappers around native time profiler functions. - -export function startProfiling(runName: string) { - profiler.timeProfiler.startProfiling(runName); +export function startProfiling(runName: string, includeLineInfo?: boolean) { + profiler.timeProfiler.startProfiling(runName, includeLineInfo || false); } -export function stopProfiling(runName: string): TimeProfile { - return profiler.timeProfiler.stopProfiling(runName); +export function stopProfiling( + runName: string, includeLineInfo?: boolean): TimeProfile { + return profiler.timeProfiler.stopProfiling(runName, includeLineInfo || false); } export function setSamplingInterval(intervalMicros: number) { diff --git a/ts/src/time-profiler.ts b/ts/src/time-profiler.ts index fe829b49..02969bad 100644 --- a/ts/src/time-profiler.ts +++ b/ts/src/time-profiler.ts @@ -34,19 +34,27 @@ export interface TimeProfilerOptions { intervalMicros?: Microseconds; sourceMapper?: SourceMapper; name?: string; + + /** + * This configuration option is experimental. + * When set to true, functions will be aggregated at the line-level, rather + * than at the function level. + * This defaults to false. + */ + lineNumbers?: boolean; } export async function profile(options: TimeProfilerOptions) { const stop = start( options.intervalMicros || DEFAULT_INTERVAL_MICROS, options.name, - options.sourceMapper); + options.sourceMapper, options.lineNumbers); await delay(options.durationMillis); return stop(); } export function start( intervalMicros: Microseconds = DEFAULT_INTERVAL_MICROS, name?: string, - sourceMapper?: SourceMapper) { + sourceMapper?: SourceMapper, lineNumbers?: boolean) { if (profiling) { throw new Error('already profiling'); } @@ -61,10 +69,10 @@ export function start( // See https://github.com/nodejs/node/issues/19009#issuecomment-403161559. // tslint:disable-next-line no-any (process as any)._startProfilerIdleNotifier(); - startProfiling(runName); + startProfiling(runName, lineNumbers); return function stop() { profiling = false; - const result = stopProfiling(runName); + const result = stopProfiling(runName, lineNumbers); // tslint:disable-next-line no-any (process as any)._stopProfilerIdleNotifier(); const profile = serializeTimeProfile(result, intervalMicros, sourceMapper);