Replace log execution latency (#141341)

This commit is contained in:
Joseph Crail 2022-09-22 02:44:10 -07:00 committed by GitHub
parent 8586270d13
commit cea17e3dbe
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
2 changed files with 75 additions and 77 deletions

View file

@ -10,7 +10,6 @@ import { INDEX_EVENTS } from '../../common';
import { ProfilingESClient } from '../utils/create_profiling_es_client';
import { withProfilingSpan } from '../utils/with_profiling_span';
import { downsampleEventsRandomly, findDownsampledIndex } from './downsampling';
import { logExecutionLatency } from './logger';
import { ProjectTimeQuery } from './query';
import {
mgetExecutables,
@ -51,14 +50,14 @@ export async function getExecutablesAndStackTraces({
if (totalCount > sampleSize * 1.1) {
p = sampleSize / totalCount;
logger.info('downsampling events with p=' + p);
await logExecutionLatency(logger, 'downsampling events', async () => {
const downsampledTotalCount = downsampleEventsRandomly(
stackTraceEvents,
p,
filter.toString()
);
logger.info('downsampled total count: ' + downsampledTotalCount);
});
const t0 = new Date().getTime();
const downsampledTotalCount = downsampleEventsRandomly(
stackTraceEvents,
p,
filter.toString()
);
logger.info(`downsampling events took ${new Date().getTime() - t0} ms`);
logger.info('downsampled total count: ' + downsampledTotalCount);
logger.info('unique downsampled stacktraces: ' + stackTraceEvents.size);
}

View file

@ -28,7 +28,6 @@ import {
import { ProfilingESClient } from '../utils/create_profiling_es_client';
import { withProfilingSpan } from '../utils/with_profiling_span';
import { DownsampledEventsIndex } from './downsampling';
import { logExecutionLatency } from './logger';
import { ProjectTimeQuery } from './query';
const traceLRU = new LRUCache<StackTraceID, StackTrace>({ max: 20000 });
@ -270,36 +269,36 @@ export async function mgetStackTraces({
const stackFrameDocIDs = new Set<string>();
const executableDocIDs = new Set<string>();
await logExecutionLatency(logger, 'processing data', async () => {
// flatMap() is significantly slower than an explicit for loop
for (const res of stackResponses) {
for (const trace of res.docs) {
if ('error' in trace) {
continue;
const t0 = new Date().getTime();
// flatMap() is significantly slower than an explicit for loop
for (const res of stackResponses) {
for (const trace of res.docs) {
if ('error' in trace) {
continue;
}
// Sometimes we don't find the trace.
// This is due to ES delays writing (data is not immediately seen after write).
// Also, ES doesn't know about transactions.
if (trace.found) {
const traceid = trace._id as StackTraceID;
let stackTrace = traceLRU.get(traceid) as StackTrace;
if (!stackTrace) {
stackTrace = decodeStackTrace(trace._source as EncodedStackTrace);
traceLRU.set(traceid, stackTrace);
}
// Sometimes we don't find the trace.
// This is due to ES delays writing (data is not immediately seen after write).
// Also, ES doesn't know about transactions.
if (trace.found) {
const traceid = trace._id as StackTraceID;
let stackTrace = traceLRU.get(traceid) as StackTrace;
if (!stackTrace) {
stackTrace = decodeStackTrace(trace._source as EncodedStackTrace);
traceLRU.set(traceid, stackTrace);
}
totalFrames += stackTrace.FrameIDs.length;
stackTraces.set(traceid, stackTrace);
for (const frameID of stackTrace.FrameIDs) {
stackFrameDocIDs.add(frameID);
}
for (const fileID of stackTrace.FileIDs) {
executableDocIDs.add(fileID);
}
totalFrames += stackTrace.FrameIDs.length;
stackTraces.set(traceid, stackTrace);
for (const frameID of stackTrace.FrameIDs) {
stackFrameDocIDs.add(frameID);
}
for (const fileID of stackTrace.FileIDs) {
executableDocIDs.add(fileID);
}
}
}
});
}
logger.info(`processing data took ${new Date().getTime() - t0} ms`);
if (stackTraces.size !== 0) {
logger.info('Average size of stacktrace: ' + totalFrames / stackTraces.size);
@ -337,32 +336,32 @@ export async function mgetStackFrames({
// Create a lookup map StackFrameID -> StackFrame.
let framesFound = 0;
await logExecutionLatency(logger, 'processing data', async () => {
const docs = resStackFrames.docs;
for (const frame of docs) {
if ('error' in frame) {
continue;
}
if (frame.found) {
stackFrames.set(frame._id, {
FileName: frame._source!.Stackframe.file?.name,
FunctionName: frame._source!.Stackframe.function?.name,
FunctionOffset: frame._source!.Stackframe.function?.offset,
LineNumber: frame._source!.Stackframe.line?.number,
SourceType: frame._source!.Stackframe.source?.type,
});
framesFound++;
} else {
stackFrames.set(frame._id, {
FileName: '',
FunctionName: '',
FunctionOffset: 0,
LineNumber: 0,
SourceType: 0,
});
}
const t0 = new Date().getTime();
const docs = resStackFrames.docs;
for (const frame of docs) {
if ('error' in frame) {
continue;
}
});
if (frame.found) {
stackFrames.set(frame._id, {
FileName: frame._source!.Stackframe.file?.name,
FunctionName: frame._source!.Stackframe.function?.name,
FunctionOffset: frame._source!.Stackframe.function?.offset,
LineNumber: frame._source!.Stackframe.line?.number,
SourceType: frame._source!.Stackframe.source?.type,
});
framesFound++;
} else {
stackFrames.set(frame._id, {
FileName: '',
FunctionName: '',
FunctionOffset: 0,
LineNumber: 0,
SourceType: 0,
});
}
}
logger.info(`processing data took ${new Date().getTime() - t0} ms`);
logger.info('found ' + framesFound + ' / ' + stackFrameIDs.size + ' frames');
@ -392,24 +391,24 @@ export async function mgetExecutables({
// Create a lookup map StackFrameID -> StackFrame.
let exeFound = 0;
await logExecutionLatency(logger, 'processing data', async () => {
const docs = resExecutables.docs;
for (const exe of docs) {
if ('error' in exe) {
continue;
}
if (exe.found) {
executables.set(exe._id, {
FileName: exe._source!.Executable.file.name,
});
exeFound++;
} else {
executables.set(exe._id, {
FileName: '',
});
}
const t0 = new Date().getTime();
const docs = resExecutables.docs;
for (const exe of docs) {
if ('error' in exe) {
continue;
}
});
if (exe.found) {
executables.set(exe._id, {
FileName: exe._source!.Executable.file.name,
});
exeFound++;
} else {
executables.set(exe._id, {
FileName: '',
});
}
}
logger.info(`processing data took ${new Date().getTime() - t0} ms`);
logger.info('found ' + exeFound + ' / ' + executableIDs.size + ' executables');