Skip to content

Commit

Permalink
fix: avoid crashes with profiler double-stops + test tracing info (si…
Browse files Browse the repository at this point in the history 
…gnalfx#508)

* fix: only invoke send only if there is a payload

`undefined` happens when syncronously calling start-stop for example.

* test: create tests to assert we catch span and trace data

* fix: return `null` when no profiling data to be returned

* fix: prevent crashing when stopping profiling adruptly

* fix: reinit start times

... and comment about why profile can be null

* refactor: allow making ProfileTitle by arbitrary sequence nr
  • Loading branch information
@rauno56
rauno56 committed Jul 18, 2022
1 parent 7439434 commit 681cfb2
Show file tree
Hide file tree
Showing 5 changed files with 154 additions and 58 deletions.
58 changes: 39 additions & 19 deletions src/native_ext/profiling.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -323,8 +323,8 @@ void V8StartProfiling(v8::CpuProfiler* profiler, const char* title) {
#endif
}

void ProfileTitle(Profiling* profiling, char* buffer, size_t length) {
snprintf(buffer, length, "splunk-otel-js-%" PRId64, profiling->profilerSeq);
void ProfileTitle(int64_t profilerSeq, char* buffer, size_t length) {
snprintf(buffer, length, "splunk-otel-js-%" PRId64, profilerSeq);
}

NAN_METHOD(StartProfiling) {
Expand Down Expand Up @@ -367,7 +367,7 @@ NAN_METHOD(StartProfiling) {
profiling->profiler->SetSamplingInterval(samplingIntervalMicros);

char title[64];
ProfileTitle(profiling, title, sizeof(title));
ProfileTitle(profiling->profilerSeq, title, sizeof(title));

profiling->activationDepth = 0;
profiling->startTime = HrTime();
Expand Down Expand Up @@ -846,18 +846,16 @@ void ProfilingReset(Profiling* profiling) {
}

NAN_METHOD(CollectProfilingData) {
auto jsProfilingData = Nan::New<v8::Object>();
info.GetReturnValue().Set(jsProfilingData);

info.GetReturnValue().SetNull();
if (!profiling) {
return;
}

char prevTitle[64];
ProfileTitle(profiling, prevTitle, sizeof(prevTitle));
ProfileTitle(profiling->profilerSeq, prevTitle, sizeof(prevTitle));
profiling->profilerSeq++;
char nextTitle[64];
ProfileTitle(profiling, nextTitle, sizeof(nextTitle));
ProfileTitle(profiling->profilerSeq, nextTitle, sizeof(nextTitle));

profiling->activationDepth = 0;
int64_t newStartTime = HrTime();
Expand All @@ -867,6 +865,15 @@ NAN_METHOD(CollectProfilingData) {

v8::CpuProfile* profile =
profiling->profiler->StopProfiling(Nan::New(prevTitle).ToLocalChecked());
if (!profile) {
// profile with this title might've already be ended using a previous stop call
profiling->startTime = newStartTime;
profiling->wallStartTime = newWallStart;
return;
}

auto jsProfilingData = Nan::New<v8::Object>();
info.GetReturnValue().Set(jsProfilingData);

ProfilingBuildStacktraces(profiling, profile, jsProfilingData);
ProfilingRecordDebugInfo(profiling, jsProfilingData);
Expand All @@ -878,18 +885,16 @@ NAN_METHOD(CollectProfilingData) {
}

NAN_METHOD(CollectProfilingDataRaw) {
auto jsProfilingData = Nan::New<v8::Object>();
info.GetReturnValue().Set(jsProfilingData);

info.GetReturnValue().SetNull();
if (!profiling) {
return;
}

char prevTitle[64];
ProfileTitle(profiling, prevTitle, sizeof(prevTitle));
ProfileTitle(profiling->profilerSeq, prevTitle, sizeof(prevTitle));
profiling->profilerSeq++;
char nextTitle[64];
ProfileTitle(profiling, nextTitle, sizeof(nextTitle));
ProfileTitle(profiling->profilerSeq, nextTitle, sizeof(nextTitle));

profiling->activationDepth = 0;
int64_t newStartTime = HrTime();
Expand All @@ -899,6 +904,15 @@ NAN_METHOD(CollectProfilingDataRaw) {

v8::CpuProfile* profile =
profiling->profiler->StopProfiling(Nan::New(prevTitle).ToLocalChecked());
if (!profile) {
// profile with this title might've already be ended using a previous stop call
profiling->startTime = newStartTime;
profiling->wallStartTime = newWallStart;
return;
}

auto jsProfilingData = Nan::New<v8::Object>();
info.GetReturnValue().Set(jsProfilingData);

ProfilingBuildRawStacktraces(profiling, profile, jsProfilingData);
ProfilingRecordDebugInfo(profiling, jsProfilingData);
Expand All @@ -910,17 +924,23 @@ NAN_METHOD(CollectProfilingDataRaw) {
}

NAN_METHOD(StopProfiling) {
auto jsProfilingData = Nan::New<v8::Object>();
info.GetReturnValue().Set(jsProfilingData);

info.GetReturnValue().SetNull();
if (!profiling) {
return;
}

char title[64];
ProfileTitle(profiling, title, sizeof(title));
char prevTitle[64];
ProfileTitle(profiling->profilerSeq, prevTitle, sizeof(prevTitle));

v8::CpuProfile* profile = profiling->profiler->StopProfiling(Nan::New(title).ToLocalChecked());
v8::CpuProfile* profile =
profiling->profiler->StopProfiling(Nan::New(prevTitle).ToLocalChecked());
if (!profile) {
// profile with this title might've already be ended using a previous stop call
return;
}

auto jsProfilingData = Nan::New<v8::Object>();
info.GetReturnValue().Set(jsProfilingData);

ProfilingBuildStacktraces(profiling, profile, jsProfilingData);
ProfilingRecordDebugInfo(profiling, jsProfilingData);
Expand Down
12 changes: 8 additions & 4 deletions src/profiling/index.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -101,8 +101,10 @@ export function startProfiling(opts: Partial<ProfilingOptions> = {}) {
const interval = setInterval(() => {
const profilingData = extCollectSamples(extension);

for (const exporter of exporters) {
exporter.send(profilingData);
if (profilingData) {
for (const exporter of exporters) {
exporter.send(profilingData);
}
}
}, options.collectionDuration);

Expand All @@ -113,8 +115,10 @@ export function startProfiling(opts: Partial<ProfilingOptions> = {}) {
clearInterval(interval);
const profilingData = extStopProfiling(extension);

for (const exporter of exporters) {
exporter.send(profilingData);
if (profilingData) {
for (const exporter of exporters) {
exporter.send(profilingData);
}
}
},
};
Expand Down
36 changes: 21 additions & 15 deletions test/profiling/extension.test.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -14,17 +14,13 @@
* limitations under the License.
*/

import * as assert from 'assert';
import { strict as assert } from 'assert';
import { hrtime } from 'process';
import { ProfilingExtension } from '../../src/profiling/types';
import * as utils from '../utils';

const extension: ProfilingExtension = require('../../src/native_ext').profiling;

function spinMs(ms: number) {
const start = Date.now();
while (Date.now() - start < ms) {}
}

function assertNanoSecondString(timestamp: any) {
assert.equal(typeof timestamp, 'string');
assert(
Expand All @@ -42,14 +38,21 @@ describe('profiling native extension', () => {
extension.stop();
});

it('calling stop without initialized profiling returns null', () => {
assert.equal(extension.stop(), null);
});

it('is possible to collect stacktraces', () => {
// returns null if no profiling started
assert.equal(extension.collect(), null);

// Use a lower interval to make sure we capture something
extension.start({
samplingIntervalMicroseconds: 1_000,
recordDebugInfo: false,
});

spinMs(100);
utils.spinMs(100);

const result = extension.collect();
// The types might not be what is declared in typescript, a sanity check.
Expand All @@ -70,8 +73,8 @@ describe('profiling native extension', () => {
// The first two lines are intentionally empty,
// as we don't have information about the thread state.
const lines = stacktrace.split('\n');
assert.deepStrictEqual(lines[0], '');
assert.deepStrictEqual(lines[1], '');
assert.deepEqual(lines[0], '');
assert.deepEqual(lines[1], '');
const stacklines = lines.slice(2, -1);

for (const stackline of stacklines) {
Expand All @@ -81,13 +84,16 @@ describe('profiling native extension', () => {
});

it('is possible to collect raw data on stacktraces', () => {
// returns null if no profiling started
assert.equal(extension.collectRaw(), null);

// Use a lower interval to make sure we capture something
extension.start({
samplingIntervalMicroseconds: 1_000,
recordDebugInfo: false,
});

spinMs(100);
utils.spinMs(100);

const result = extension.collectRaw();
// The types might not be what is declared in typescript, a sanity check.
Expand All @@ -107,11 +113,11 @@ describe('profiling native extension', () => {

for (const traceline of stacktrace) {
assert(Array.isArray(traceline));
assert.strictEqual(traceline.length, 4);
assert.strictEqual(typeof traceline[0], 'string'); // filename
assert.strictEqual(typeof traceline[1], 'string'); // function name
assert.strictEqual(typeof traceline[2], 'number'); // line number
assert.strictEqual(typeof traceline[3], 'number'); // column number
assert.equal(traceline.length, 4);
assert.equal(typeof traceline[0], 'string'); // filename
assert.equal(typeof traceline[1], 'string'); // function name
assert.equal(typeof traceline[2], 'number'); // line number
assert.equal(typeof traceline[3], 'number'); // column number
}
}
});
Expand Down
101 changes: 81 additions & 20 deletions test/profiling/profiling.test.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -16,17 +16,28 @@

import * as assert from 'assert';
import { hrtime } from 'process';
import { inspect } from 'util';

import { context, trace, propagation } from '@opentelemetry/api';
import { Resource } from '@opentelemetry/resources';
import { SemanticResourceAttributes } from '@opentelemetry/semantic-conventions';

import {
defaultExporterFactory,
startProfiling,
_setDefaultOptions,
} from '../../src/profiling';
import { start, stop } from '../../src';
import { ProfilingExporter, ProfilingData } from '../../src/profiling/types';
import { ProfilingContextManager } from '../../src/profiling/ProfilingContextManager';
import { detect as detectResource } from '../../src/resource';
import { Resource } from '@opentelemetry/resources';
import { SemanticResourceAttributes } from '@opentelemetry/semantic-conventions';

import * as utils from '../utils';

const sleep = (ms: number) => {
return new Promise(r => setTimeout(r, ms));
};

describe('profiling', () => {
describe('options', () => {
beforeEach(() => {
Expand Down Expand Up @@ -76,38 +87,88 @@ describe('profiling', () => {
});

describe('startProfiling', () => {
it('exports stacktraces', done => {
let stacktracesReceived = 0;
it('exports stacktraces', async () => {
let sendCallCount = 0;
const stacktracesReceived = [];
const exporter: ProfilingExporter = {
send(profilingData: ProfilingData) {
const { stacktraces } = profilingData;
stacktracesReceived += stacktraces.length;
sendCallCount += 1;
stacktracesReceived.push(...stacktraces);
},
};

// enabling tracing is required for span information to be caught
start({
profiling: {
serviceName: 'slow-service',
callstackInterval: 50,
collectionDuration: 500,
exporterFactory: () => [exporter],
},
});

assert(context._getContextManager() instanceof ProfilingContextManager);

// let runtime empty the task-queue and enable profiling
await sleep(10);

const span = trace.getTracer('test-tracer').startSpan('test-span');
const { spanId: expectedSpanId, traceId: expectedTraceId } =
span.spanContext();

context.with(trace.setSpan(context.active(), span), () => {
utils.spinMs(1_000);
span.end();
});

// let runtime empty the task-queue and disable profiling
await sleep(10);

stop();
// It might be possible all stacktraces will not be available,
// due to the first few stacktraces having random timings
// after a profiling run is started.
const expectedStacktraces = 5;
assert(
stacktracesReceived.length >= expectedStacktraces,
`expected at least ${expectedStacktraces}, got ${stacktracesReceived.length}`
);

assert(
stacktracesReceived.some(({ spanId, traceId }, idx) => {
return (
spanId?.toString('hex') === expectedSpanId &&
traceId?.toString('hex') === expectedTraceId
);
}),
`No stacktrace had span info: ${inspect(stacktracesReceived)}`
);

// Stop flushes the exporters, hence the extra call count
assert.deepStrictEqual(sendCallCount, 2);
});

it('does not call Exporter#send if profiling has not started', async () => {
let sendCallCount = 0;
const stacktracesReceived = [];
const exporter: ProfilingExporter = {
send(profilingData: ProfilingData) {
sendCallCount += 1;
},
};

// enabling tracing is required for span information to be caught
const { stop } = startProfiling({
serviceName: 'slow-service',
callstackInterval: 50,
collectionDuration: 1_000,
collectionDuration: 500,
exporterFactory: () => [exporter],
});

setTimeout(() => {
stop();
// It might be possible all stacktraces will not be available,
// due to the first few stacktraces having random timings
// after a profiling run is started.
const expectedStacktraces = 5;
assert(
stacktracesReceived >= expectedStacktraces,
`expected at least ${expectedStacktraces}, got ${stacktracesReceived}`
);
// Stop flushes the exporters, hence the extra call count
assert.deepStrictEqual(sendCallCount, 2);
done();
}, 1_100);
stop();

assert.equal(sendCallCount, 0);
});
});
});
5 changes: 5 additions & 0 deletions test/utils.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -39,3 +39,8 @@ export const cleanEnvironment = () => {
delete process.env[key];
});
};

export const spinMs = (ms: number) => {
const start = Date.now();
while (Date.now() - start < ms) {}
};

0 comments on commit 681cfb2

Please sign in to comment.