From f69399ff4941fbfe63e1401fae6d1c501c4cd9a0 Mon Sep 17 00:00:00 2001 From: Francesco Gualazzi Date: Thu, 24 Feb 2022 19:12:16 +0100 Subject: [PATCH] Use logger instead of conosle.log (#22) * replace console logs with plugin logger * poor man's functions tracing via logs Signed-off-by: inge4pres --- src/plugins/profiling/common/index.ts | 29 +-- src/plugins/profiling/server/plugin.ts | 10 +- .../profiling/server/routes/flamegraph.ts | 95 ++++---- src/plugins/profiling/server/routes/index.ts | 6 +- .../server/routes/search_flamechart.ts | 221 ++++++++++-------- 5 files changed, 187 insertions(+), 174 deletions(-) diff --git a/src/plugins/profiling/common/index.ts b/src/plugins/profiling/common/index.ts index e2d9d3b3007e2b..df5f8f527c57fc 100644 --- a/src/plugins/profiling/common/index.ts +++ b/src/plugins/profiling/common/index.ts @@ -47,7 +47,7 @@ function toMilliseconds(seconds: string): number { export function getTopN(obj) { const data = []; - if (obj.topN?.histogram?.buckets !== undefined) { + if (obj.topN?.histogram?.buckets!) { // needed for data served from Elasticsearch for (let i = 0; i < obj.topN.histogram.buckets.length; i++) { const bucket = obj.topN.histogram.buckets[i]; @@ -56,13 +56,15 @@ export function getTopN(obj) { data.push({ x: bucket.key, y: v.Count.value, g: v.key }); } } - } else if (obj.TopN !== undefined) { + } else if (obj.TopN!) { // needed for data served from fixtures for (const x in obj.TopN) { - const values = obj.TopN[x]; - for (let i = 0; i < values.length; i++) { - const v = values[i]; - data.push({ x: toMilliseconds(x), y: v.Count, g: v.Value }); + if (obj.TopN.hasOwnProperty(x)) { + const values = obj.TopN[x]; + for (let i = 0; i < values.length; i++) { + const v = values[i]; + data.push({ x: toMilliseconds(x), y: v.Count, g: v.Value }); + } } } } @@ -88,18 +90,3 @@ export function timeRangeFromRequest(request: any): [number, number] { const timeTo = parseInt(request.query.timeTo!, 10); return [timeFrom, timeTo]; } - -export const now = (label?: string) => { - if (label) { - console.log('Started', label); - } - return new Date().getTime(); -}; - -export const elapsed = (start: number, label?: string) => { - const duration = new Date().getTime() - start; - if (label) { - console.log(label, `${duration / 1000}s`); - } - return duration; -}; diff --git a/src/plugins/profiling/server/plugin.ts b/src/plugins/profiling/server/plugin.ts index 843f9a7a1b5e78..905a2f394e1a78 100644 --- a/src/plugins/profiling/server/plugin.ts +++ b/src/plugins/profiling/server/plugin.ts @@ -5,13 +5,7 @@ * in compliance with, at your election, the Elastic License 2.0 or the Server * Side Public License, v 1. */ -import { - PluginInitializerContext, - CoreSetup, - CoreStart, - Plugin, - Logger, -} from '../../../core/server'; +import { PluginInitializerContext, CoreSetup, CoreStart, Plugin, Logger } from 'kibana/server'; import type { DataRequestHandlerContext } from '../../data/server'; @@ -46,7 +40,7 @@ export class ProfilingPlugin core.getStartServices().then(([_, depsStart]) => { const myStrategy = mySearchStrategyProvider(depsStart.data); deps.data.search.registerSearchStrategy('myStrategy', myStrategy); - registerRoutes(router); + registerRoutes(router, this.logger); }); return {}; diff --git a/src/plugins/profiling/server/routes/flamegraph.ts b/src/plugins/profiling/server/routes/flamegraph.ts index 4e622997d78de9..480db4964c320a 100644 --- a/src/plugins/profiling/server/routes/flamegraph.ts +++ b/src/plugins/profiling/server/routes/flamegraph.ts @@ -5,40 +5,9 @@ * in compliance with, at your election, the Elastic License 2.0 or the Server * Side Public License, v 1. */ +import { Logger } from 'kibana/server'; import { StackTraceID, StackFrameID, FileID, StackTrace, StackFrame, Executable } from './types'; -function getExeFileName(exe: any, type: number) { - if (exe?.FileName === undefined) { - console.log('MISSING EXE'); - return ''; - } - if (exe.FileName !== '') { - return exe.FileName; - } - switch (type) { - case 0: - return ''; - case 1: - return 'Python'; - case 2: - return 'PHP'; - case 3: - return 'Native'; - case 4: - return 'Kernel'; - case 5: - return 'JVM/Hotspot'; - case 6: - return 'Ruby'; - case 7: - return 'Perl'; - case 8: - return 'JavaScript'; - default: - return ''; - } -} - function checkIfStringHasParentheses(s: string) { return /\(|\)/.test(s); } @@ -49,16 +18,6 @@ function getFunctionName(frame: any) { : frame.FunctionName; } -// Generates the label for a flamegraph node -// -// This is slightly modified from the original code in elastic/prodfiler_ui -function getLabel(frame: any, executable: any, type: number) { - if (frame.FunctionName !== '') { - return `${getExeFileName(executable, type)}: ${getFunctionName(frame)} in #${frame.LineNumber}`; - } - return getExeFileName(executable, type); -} - export class FlameGraph { // sampleRate is 1/5^N, with N being the downsampled index the events were fetched from. // N=0: full events table (sampleRate is 1) @@ -77,13 +36,16 @@ export class FlameGraph { stackframes: Map; executables: Map; + private readonly logger: Logger; + constructor( sampleRate: number, totalCount: number, events: Map, stackTraces: Map, stackFrames: Map, - executables: Map + executables: Map, + logger: Logger ) { this.sampleRate = sampleRate; this.totalCount = totalCount; @@ -91,6 +53,51 @@ export class FlameGraph { this.stacktraces = stackTraces; this.stackframes = stackFrames; this.executables = executables; + this.logger = logger; + } + + private getExeFileName(exe: any, type: number) { + if (exe?.FileName === undefined) { + this.logger.warn('missing executable FileName'); + return ''; + } + if (exe.FileName !== '') { + return exe.FileName; + } + switch (type) { + case 0: + return ''; + case 1: + return 'Python'; + case 2: + return 'PHP'; + case 3: + return 'Native'; + case 4: + return 'Kernel'; + case 5: + return 'JVM/Hotspot'; + case 6: + return 'Ruby'; + case 7: + return 'Perl'; + case 8: + return 'JavaScript'; + default: + return ''; + } + } + + // Generates the label for a flamegraph node + // + // This is slightly modified from the original code in elastic/prodfiler_ui + private getLabel(frame: any, executable: any, type: number) { + if (frame.FunctionName !== '') { + return `${this.getExeFileName(executable, type)}: ${getFunctionName(frame)} in #${ + frame.LineNumber + }`; + } + return this.getExeFileName(executable, type); } toElastic() { @@ -100,7 +107,7 @@ export class FlameGraph { for (const trace of this.stacktraces.values()) { const path = ['root']; for (let i = trace.FrameID.length - 1; i >= 0; i--) { - const label = getLabel( + const label = this.getLabel( this.stackframes.get(trace.FrameID[i]), this.executables.get(trace.FileID[i]), parseInt(trace.Type[i], 10) diff --git a/src/plugins/profiling/server/routes/index.ts b/src/plugins/profiling/server/routes/index.ts index 5b49f91393eb36..de398f0a2c7801 100644 --- a/src/plugins/profiling/server/routes/index.ts +++ b/src/plugins/profiling/server/routes/index.ts @@ -5,7 +5,7 @@ * in compliance with, at your election, the Elastic License 2.0 or the Server * Side Public License, v 1. */ -import type { IRouter } from 'kibana/server'; +import type { IRouter, Logger } from 'kibana/server'; import { DataRequestHandlerContext } from '../../../data/server'; import { registerFlameChartElasticRoute, registerFlameChartPixiRoute } from './load_flamechart'; import { @@ -25,7 +25,7 @@ import { registerTraceEventsTopNThreadsSearchRoute, } from './search_topn'; -export function registerRoutes(router: IRouter) { +export function registerRoutes(router: IRouter, logger?: Logger) { registerFlameChartElasticRoute(router); registerFlameChartPixiRoute(router); registerTraceEventsTopNContainersRoute(router); @@ -34,7 +34,7 @@ export function registerRoutes(router: IRouter) { registerTraceEventsTopNStackTracesRoute(router); registerTraceEventsTopNThreadsRoute(router); - registerFlameChartSearchRoute(router); + registerFlameChartSearchRoute(router, logger!); registerTraceEventsTopNContainersSearchRoute(router); registerTraceEventsTopNDeploymentsSearchRoute(router); registerTraceEventsTopNHostsSearchRoute(router); diff --git a/src/plugins/profiling/server/routes/search_flamechart.ts b/src/plugins/profiling/server/routes/search_flamechart.ts index 743374f445bc1f..6ca3e15e4d4112 100644 --- a/src/plugins/profiling/server/routes/search_flamechart.ts +++ b/src/plugins/profiling/server/routes/search_flamechart.ts @@ -6,12 +6,12 @@ * Side Public License, v 1. */ import { schema } from '@kbn/config-schema'; -import type { IRouter } from 'kibana/server'; +import type { IRouter, Logger } from 'kibana/server'; import type { DataRequestHandlerContext } from '../../../data/server'; -import { getRemoteRoutePaths, now, elapsed } from '../../common'; +import { getRemoteRoutePaths } from '../../common'; import { FlameGraph } from './flamegraph'; import { newProjectTimeQuery } from './mappings'; -import { StackTraceID, StackFrameID, FileID, StackTrace, StackFrame, Executable } from './types'; +import { Executable, FileID, StackFrame, StackFrameID, StackTrace, StackTraceID } from './types'; export interface DownsampledEventsIndex { name: string; @@ -65,7 +65,10 @@ export function getSampledTraceEventsIndex( return { name: downsampledIndex + initialExp, sampleRate: 1 / samplingFactor ** initialExp }; } -export function registerFlameChartSearchRoute(router: IRouter) { +export function registerFlameChartSearchRoute( + router: IRouter, + logger: Logger +) { const paths = getRemoteRoutePaths(); router.get( { @@ -88,103 +91,114 @@ export function registerFlameChartSearchRoute(router: IRouter { + const resp = await esClient.search({ + index: downsampledIndex + initialExp, + body: { + query: filter, + size: 0, + track_total_hits: true, + }, + }); + const sampleCountFromInitialExp = resp.body.hits.total?.value as number; + + logger.info('sampleCountFromPow6 ' + sampleCountFromInitialExp); - const eventsIndex = getSampledTraceEventsIndex( - targetSampleSize, - sampleCountFromInitialExp, - initialExp + return getSampledTraceEventsIndex( + targetSampleSize, + sampleCountFromInitialExp, + initialExp + ); + } ); - elapsed(startDS, 'findDownsampledIndex'); - - // eslint-disable-next-line no-console - console.log('EventsIndex', eventsIndex); + logger.info('EventsIndex ' + eventsIndex.name); // Using filter_path is less readable and scrollSearch seems to be buggy - it // applies filter_path only to the first array of results, but not on the following arrays. // The downside of `_source` is: it takes 2.5x more time on the ES side (see "took" field). // The `composite` keyword skips sorting the buckets as and return results 'as is'. // A max bucket size of 100000 needs a cluster level setting "search.max_buckets: 100000". - const start1 = now(); - const resEvents = await esClient.search({ - index: eventsIndex.name, - size: 0, - query: filter, - aggs: { - group_by: { - composite: { - size: 100000, // This is the upper limit of entries per event index. - sources: [ - { - traceid: { - terms: { - field: 'StackTraceID', + const resEvents = await logExecutionLatency( + logger, + 'query to find DownsampledIndex', + async () => { + return await esClient.search({ + index: eventsIndex.name, + size: 0, + query: filter, + aggs: { + group_by: { + composite: { + size: 100000, // This is the upper limit of entries per event index. + sources: [ + { + traceid: { + terms: { + field: 'StackTraceID', + }, + }, + }, + ], + }, + aggs: { + sum_count: { + sum: { + field: 'Count', }, }, }, - ], - }, - aggs: { - sum_count: { + }, + total_count: { sum: { field: 'Count', }, }, }, - }, - total_count: { - sum: { - field: 'Count', - }, - }, - }, - }); - elapsed(start1, 'resEvents'); + }); + } + ); - const totalCount: number = resEvents.body.aggregations.total_count.value; + const totalCount: number = resEvents.body.aggregations?.total_count.value; const stackTraceEvents = new Map(); let docCount = 0; let bucketCount = 0; - resEvents.body.aggregations.group_by.buckets.forEach((item: any) => { + resEvents.body.aggregations?.group_by.buckets.forEach((item: any) => { const traceid: StackTraceID = item.key.traceid; stackTraceEvents.set(traceid, item.sum_count.value); docCount += item.doc_count; bucketCount++; }); - console.log('took', resEvents.body.took); - console.log('docs', docCount); - console.log('total events', totalCount); - console.log('unique events', bucketCount); + logger.info('query time registered by ES on events ' + resEvents.body.took); + logger.info('events document count ' + docCount); + logger.info('total events count ' + totalCount); + logger.info('unique events ' + bucketCount); - const start2 = now(); - const resStackTraces = await esClient.mget({ - index: 'profiling-stacktraces', - ids: [...stackTraceEvents.keys()], - _source_includes: ['FrameID', 'FileID', 'Type'], - }); - elapsed(start2, 'resStackTraces'); + const resStackTraces = await logExecutionLatency( + logger, + 'mget query for stacktraces', + async () => { + return await esClient.mget({ + index: 'profiling-stacktraces', + ids: [...stackTraceEvents.keys()], + _source_includes: ['FrameID', 'FileID', 'Type'], + }); + } + ); // 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. // Create a lookup map StackTraceID -> StackTrace. - let stackTraces = new Map(); + const stackTraces = new Map(); for (const trace of resStackTraces.body.docs) { if (trace.found) { stackTraces.set(trace._id, { @@ -194,7 +208,7 @@ export function registerFlameChartSearchRoute(router: IRouter(); @@ -203,14 +217,18 @@ export function registerFlameChartSearchRoute(router: IRouter { + return await esClient.mget({ + index: 'profiling-stackframes', + ids: [...stackFrameDocIDs], + }); + } + ); // Create a lookup map StackFrameID -> StackFrame. const stackFrames = new Map(); @@ -235,15 +253,19 @@ export function registerFlameChartSearchRoute(router: IRouter({ - index: 'profiling-executables', - ids: [...executableDocIDs], - _source_includes: ['FileName'], - }); - elapsed(start4, 'resExecutables'); + const resExecutables = await logExecutionLatency( + logger, + 'mget query for executables', + async () => { + return await esClient.mget({ + index: 'profiling-executables', + ids: [...executableDocIDs], + _source_includes: ['FileName'], + }); + } + ); // Create a lookup map StackFrameID -> StackFrame. const executables = new Map(); @@ -257,27 +279,23 @@ export function registerFlameChartSearchRoute(router: IRouter { + return new FlameGraph( + eventsIndex.sampleRate, + totalCount, + stackTraceEvents, + stackTraces, + stackFrames, + executables, + logger + ).toElastic(); }); - elapsed(start5, 'Flamegraph aggregation'); - elapsed(startDS, 'totalDuration'); - - return ret; + return response.ok({ + body: responseBody, + }); } catch (e) { - // eslint-disable-next-line no-console - console.log('Caught', e); + logger.error('Caught exception when fetching Flamegraph data: ' + e.message); return response.customError({ statusCode: e.statusCode ?? 500, body: { @@ -288,3 +306,10 @@ export function registerFlameChartSearchRoute(router: IRouter(logger: Logger, activity: string, func: () => T): T { + const start = new Date().getTime(); + const result = func(); + logger.info(activity + ' took ' + (new Date().getTime() - start) + 'ms'); + return result; +}