From f99b54612abb0ff4239bac37d36465217dc67b8c Mon Sep 17 00:00:00 2001 From: Jon Edvald Date: Thu, 19 Mar 2020 04:36:51 +0100 Subject: [PATCH] chore: add profiler for performance analysis Adding some tooling to analyze how long specific parts of our code take to complete. A summary is printed at the end of unit and integ test runs, which should help us where we can make optimizations. Note that the syntax for wrapping/profiling individual functions is slightly odd, simply because there isn't any native support for function decorators in JS. Other ideas are welcome, but I think this is fine for now. --- garden-service/src/actions.ts | 2 + garden-service/src/build-dir.ts | 3 +- garden-service/src/garden.ts | 2 + garden-service/src/resolve-module.ts | 5 +- garden-service/src/task-graph.ts | 2 + garden-service/src/tasks/base.ts | 2 + garden-service/src/tasks/build.ts | 2 + garden-service/src/tasks/deploy.ts | 2 + .../src/tasks/get-service-status.ts | 2 + garden-service/src/tasks/get-task-result.ts | 2 + garden-service/src/tasks/hot-reload.ts | 2 + garden-service/src/tasks/resolve-provider.ts | 2 + garden-service/src/tasks/stage-build.ts | 2 + garden-service/src/tasks/task.ts | 2 + garden-service/src/tasks/test.ts | 2 + garden-service/src/template-string.ts | 5 +- garden-service/src/util/profiling.ts | 203 ++++++++++++++++++ .../src/util/validate-dependencies.ts | 2 + garden-service/src/vcs/git.ts | 2 + garden-service/test/setup.ts | 11 +- .../test/unit/src/util/profiling.ts | 117 ++++++++++ 21 files changed, 366 insertions(+), 8 deletions(-) create mode 100644 garden-service/src/util/profiling.ts create mode 100644 garden-service/test/unit/src/util/profiling.ts diff --git a/garden-service/src/actions.ts b/garden-service/src/actions.ts index c5f8636dd2..21bfc9be7b 100644 --- a/garden-service/src/actions.ts +++ b/garden-service/src/actions.ts @@ -99,6 +99,7 @@ import { getArtifactKey } from "./util/artifacts" import { AugmentGraphResult, AugmentGraphParams } from "./types/plugin/provider/augmentGraph" import { DeployTask } from "./tasks/deploy" import { BuildDependencyConfig } from "./config/module" +import { Profile } from "./util/profiling" const maxArtifactLogLines = 5 // max number of artifacts to list in console after task+test runs @@ -120,6 +121,7 @@ export interface DeployServicesParams { * Each plugin and module action has a corresponding method on this class (aside from configureProvider, which * is handled especially elsewhere). */ +@Profile() export class ActionRouter implements TypeGuard { private readonly actionHandlers: WrappedPluginActionMap private readonly moduleActionHandlers: WrappedModuleActionMap diff --git a/garden-service/src/build-dir.ts b/garden-service/src/build-dir.ts index 57883eee11..d8a0627985 100644 --- a/garden-service/src/build-dir.ts +++ b/garden-service/src/build-dir.ts @@ -20,6 +20,7 @@ import { ConfigGraph } from "./config-graph" import { exec } from "./util/util" import { LogLevel } from "./logger/log-node" import { deline } from "./util/string" +import { Profile } from "./util/profiling" const minRsyncVersion = "3.1.0" const versionRegex = /rsync version ([\d\.]+) / @@ -39,7 +40,7 @@ const versionDetectFailure = new RuntimeError( ) // Lazily construct a directory of modules inside which all build steps are performed. - +@Profile() export class BuildDir { constructor(private projectRoot: string, public buildDirPath: string, public buildMetadataDirPath: string) {} diff --git a/garden-service/src/garden.ts b/garden-service/src/garden.ts index ef65208af0..29f913d706 100644 --- a/garden-service/src/garden.ts +++ b/garden-service/src/garden.ts @@ -60,6 +60,7 @@ import { loadPlugins, getDependencyOrder, getModuleTypes } from "./plugins" import { deline, naturalList } from "./util/string" import { ensureConnected } from "./db/connection" import { DependencyValidationGraph } from "./util/validate-dependencies" +import { Profile } from "./util/profiling" export interface ActionHandlerMap { [actionName: string]: PluginActionHandlers[T] @@ -115,6 +116,7 @@ export interface GardenParams { workingCopyId: string } +@Profile() export class Garden { public readonly log: LogEntry private loadedPlugins: GardenPlugin[] diff --git a/garden-service/src/resolve-module.ts b/garden-service/src/resolve-module.ts index dcda921cc6..2d438cb476 100644 --- a/garden-service/src/resolve-module.ts +++ b/garden-service/src/resolve-module.ts @@ -17,12 +17,13 @@ import { deline } from "./util/string" import { getModuleKey } from "./types/module" import { getModuleTypeBases } from "./plugins" import { ModuleConfig, moduleConfigSchema } from "./config/module" +import { profileAsync } from "./util/profiling" export interface ModuleConfigResolveOpts extends ContextResolveOpts { configContext?: ModuleConfigContext } -export async function resolveModuleConfig( +export const resolveModuleConfig = profileAsync(async function $resolveModuleConfig( garden: Garden, config: ModuleConfig, opts: ModuleConfigResolveOpts @@ -159,4 +160,4 @@ export async function resolveModuleConfig( } return config -} +}) diff --git a/garden-service/src/task-graph.ts b/garden-service/src/task-graph.ts index ddd7529c94..7043f15696 100644 --- a/garden-service/src/task-graph.ts +++ b/garden-service/src/task-graph.ts @@ -20,6 +20,7 @@ import { dedent } from "./util/string" import { defer, relationshipClasses, uuidv4 } from "./util/util" import { renderError } from "./logger/renderers" import { DependencyValidationGraph } from "./util/validate-dependencies" +import { Profile } from "./util/profiling" class TaskGraphError extends GardenBaseError { type = "task-graph" @@ -55,6 +56,7 @@ export interface ProcessTasksOpts { unlimitedConcurrency?: boolean } +@Profile() export class TaskGraph { private roots: TaskNodeMap private index: TaskNodeMap diff --git a/garden-service/src/tasks/base.ts b/garden-service/src/tasks/base.ts index 20aabe69c4..1d5e8b5a79 100644 --- a/garden-service/src/tasks/base.ts +++ b/garden-service/src/tasks/base.ts @@ -15,6 +15,7 @@ import { pickBy, mapValues, mapKeys } from "lodash" import { ServiceStatus } from "../types/service" import { RunTaskResult } from "../types/plugin/task/runTask" import { splitLast } from "../util/util" +import { Profile } from "../util/profiling" export type TaskType = | "build" @@ -42,6 +43,7 @@ export interface TaskParams { version: ModuleVersion } +@Profile() export abstract class BaseTask { abstract type: TaskType garden: Garden diff --git a/garden-service/src/tasks/build.ts b/garden-service/src/tasks/build.ts index ec6de5ff80..1a63ba48a0 100644 --- a/garden-service/src/tasks/build.ts +++ b/garden-service/src/tasks/build.ts @@ -15,6 +15,7 @@ import { Garden } from "../garden" import { LogEntry } from "../logger/log-entry" import { StageBuildTask } from "./stage-build" import { flatten } from "lodash" +import { Profile } from "../util/profiling" export interface BuildTaskParams { garden: Garden @@ -23,6 +24,7 @@ export interface BuildTaskParams { force: boolean } +@Profile() export class BuildTask extends BaseTask { type: TaskType = "build" diff --git a/garden-service/src/tasks/deploy.ts b/garden-service/src/tasks/deploy.ts index ac2d621309..400ca3adaf 100644 --- a/garden-service/src/tasks/deploy.ts +++ b/garden-service/src/tasks/deploy.ts @@ -21,6 +21,7 @@ import { TaskResults } from "../task-graph" import { prepareRuntimeContext } from "../runtime-context" import { GetServiceStatusTask } from "./get-service-status" import { GetTaskResultTask } from "./get-task-result" +import { Profile } from "../util/profiling" export interface DeployTaskParams { garden: Garden @@ -33,6 +34,7 @@ export interface DeployTaskParams { hotReloadServiceNames?: string[] } +@Profile() export class DeployTask extends BaseTask { type: TaskType = "deploy" diff --git a/garden-service/src/tasks/get-service-status.ts b/garden-service/src/tasks/get-service-status.ts index 1e4e6978a6..80c84820d0 100644 --- a/garden-service/src/tasks/get-service-status.ts +++ b/garden-service/src/tasks/get-service-status.ts @@ -18,6 +18,7 @@ import { getTaskVersion } from "./task" import Bluebird from "bluebird" import { GetTaskResultTask } from "./get-task-result" import chalk from "chalk" +import { Profile } from "../util/profiling" export interface GetServiceStatusTaskParams { garden: Garden @@ -28,6 +29,7 @@ export interface GetServiceStatusTaskParams { hotReloadServiceNames?: string[] } +@Profile() export class GetServiceStatusTask extends BaseTask { type: TaskType = "get-service-status" diff --git a/garden-service/src/tasks/get-task-result.ts b/garden-service/src/tasks/get-task-result.ts index 84ea38a837..86a371e574 100644 --- a/garden-service/src/tasks/get-task-result.ts +++ b/garden-service/src/tasks/get-task-result.ts @@ -13,6 +13,7 @@ import { Garden } from "../garden" import { Task } from "../types/task" import { RunTaskResult } from "../types/plugin/task/runTask" import { ModuleVersion } from "../vcs/vcs" +import { Profile } from "../util/profiling" export interface GetTaskResultTaskParams { force: boolean @@ -22,6 +23,7 @@ export interface GetTaskResultTaskParams { version: ModuleVersion } +@Profile() export class GetTaskResultTask extends BaseTask { type: TaskType = "get-task-result" diff --git a/garden-service/src/tasks/hot-reload.ts b/garden-service/src/tasks/hot-reload.ts index e97683c401..0dc109bc4c 100644 --- a/garden-service/src/tasks/hot-reload.ts +++ b/garden-service/src/tasks/hot-reload.ts @@ -12,6 +12,7 @@ import { BaseTask, TaskType } from "./base" import { Service } from "../types/service" import { Garden } from "../garden" import { ConfigGraph } from "../config-graph" +import { Profile } from "../util/profiling" interface Params { force: boolean @@ -22,6 +23,7 @@ interface Params { service: Service } +@Profile() export class HotReloadTask extends BaseTask { type: TaskType = "hot-reload" diff --git a/garden-service/src/tasks/resolve-provider.ts b/garden-service/src/tasks/resolve-provider.ts index 02b6686df7..430114d249 100644 --- a/garden-service/src/tasks/resolve-provider.ts +++ b/garden-service/src/tasks/resolve-provider.ts @@ -21,6 +21,7 @@ import { validateWithPath } from "../config/validation" import Bluebird from "bluebird" import { defaultEnvironmentStatus } from "../types/plugin/provider/getEnvironmentStatus" import { getPluginBases, getPluginBaseNames } from "../plugins" +import { Profile } from "../util/profiling" interface Params extends TaskParams { plugin: GardenPlugin @@ -31,6 +32,7 @@ interface Params extends TaskParams { /** * Resolves the configuration for the specified provider. */ +@Profile() export class ResolveProviderTask extends BaseTask { type: TaskType = "resolve-provider" diff --git a/garden-service/src/tasks/stage-build.ts b/garden-service/src/tasks/stage-build.ts index 140055d5dd..7d1225836d 100644 --- a/garden-service/src/tasks/stage-build.ts +++ b/garden-service/src/tasks/stage-build.ts @@ -14,6 +14,7 @@ import { BuildResult } from "../types/plugin/module/build" import { BaseTask, TaskType } from "../tasks/base" import { Garden } from "../garden" import { LogEntry } from "../logger/log-entry" +import { Profile } from "../util/profiling" export interface StageBuildTaskParams { garden: Garden @@ -23,6 +24,7 @@ export interface StageBuildTaskParams { dependencies?: BaseTask[] } +@Profile() export class StageBuildTask extends BaseTask { type: TaskType = "stage-build" diff --git a/garden-service/src/tasks/task.ts b/garden-service/src/tasks/task.ts index 58f169a246..06c28c1b86 100644 --- a/garden-service/src/tasks/task.ts +++ b/garden-service/src/tasks/task.ts @@ -20,6 +20,7 @@ import { BuildTask } from "./build" import { RunTaskResult } from "../types/plugin/task/runTask" import { TaskResults } from "../task-graph" import { GetTaskResultTask } from "./get-task-result" +import { Profile } from "../util/profiling" export interface TaskTaskParams { garden: Garden @@ -36,6 +37,7 @@ class RunTaskError extends Error { } } +@Profile() export class TaskTask extends BaseTask { // ... to be renamed soon. type: TaskType = "task" diff --git a/garden-service/src/tasks/test.ts b/garden-service/src/tasks/test.ts index 38aa397741..190f7ad714 100644 --- a/garden-service/src/tasks/test.ts +++ b/garden-service/src/tasks/test.ts @@ -25,6 +25,7 @@ import { makeTestTaskName } from "./helpers" import { BuildTask } from "./build" import { TaskTask } from "./task" import { TaskResults } from "../task-graph" +import { Profile } from "../util/profiling" class TestError extends Error { toString() { @@ -43,6 +44,7 @@ export interface TestTaskParams { hotReloadServiceNames?: string[] } +@Profile() export class TestTask extends BaseTask { type: TaskType = "test" diff --git a/garden-service/src/template-string.ts b/garden-service/src/template-string.ts index 5eb486c9f1..f91bddee56 100644 --- a/garden-service/src/template-string.ts +++ b/garden-service/src/template-string.ts @@ -13,6 +13,7 @@ import { GardenBaseError, ConfigurationError } from "./exceptions" import { ConfigContext, ContextResolveOpts, ScanContext, ContextResolveOutput } from "./config/config-context" import { uniq, isPlainObject, isNumber } from "lodash" import { Primitive, isPrimitive } from "./config/common" +import { profileAsync } from "./util/profiling" export type StringOrStringPromise = Promise | string @@ -119,7 +120,7 @@ export async function resolveTemplateString( /** * Recursively parses and resolves all templated strings in the given object. */ -export async function resolveTemplateStrings( +export const resolveTemplateStrings = profileAsync(async function $resolveTemplateStrings( obj: T, context: ConfigContext, opts: ContextResolveOpts = {} @@ -130,7 +131,7 @@ export async function resolveTemplateStrings( // need to iterate sequentially to catch potential circular dependencies { concurrency: 1 } ) -} +}) /** * Scans for all template strings in the given object and lists the referenced keys. diff --git a/garden-service/src/util/profiling.ts b/garden-service/src/util/profiling.ts new file mode 100644 index 0000000000..e509c2cd4a --- /dev/null +++ b/garden-service/src/util/profiling.ts @@ -0,0 +1,203 @@ +/* + * Copyright (C) 2018-2020 Garden Technologies, Inc. + * + * This Source Code Form is subject to the terms of the Mozilla Public + * License, v. 2.0. If a copy of the MPL was not distributed with this + * file, You can obtain one at http://mozilla.org/MPL/2.0/. + */ + +import { performance } from "perf_hooks" +import { sum, sortBy } from "lodash" +import { renderTable, tablePresets } from "./string" +import chalk from "chalk" + +// Just storing the invocation duration for now +type Invocation = number + +interface Profiles { + [key: string]: Invocation[] +} + +export class Profiler { + private data: Profiles + + constructor(private enabled = true) { + this.data = {} + } + + isEnabled() { + return this.enabled + } + + setEnabled(enabled: boolean) { + this.enabled = enabled + } + + getData() { + return this.data + } + + report() { + function formatKey(key: string) { + const split = key.split("#") + + if (split.length === 1) { + return chalk.greenBright(key) + } else { + return chalk.cyan(split[0]) + "#" + chalk.greenBright(split[1]) + } + } + + function formatDuration(duration: number) { + return duration.toFixed(2) + chalk.gray(" ms") + } + + const keys = Object.keys(this.data) + + const heading = ["Function/method", "# Invocations", "Total time", "Avg. time"].map((h) => chalk.white.underline(h)) + const tableData = sortBy( + keys.map((key) => { + const invocations = this.data[key].length + const total = sum(this.data[key]) + const average = total / invocations + return [formatKey(key), invocations, total, average] + }), + // Sort by total duration + (row) => -row[2] + ).map((row) => [row[0], row[1], formatDuration(row[2]), formatDuration(row[3])]) + + const table = renderTable([heading, [], ...tableData], tablePresets["no-borders"]) + + return ` + ${chalk.white.bold("Profiling data:")} + ──────────────────────────────────────────────────────────────────────────────── +${table} + ──────────────────────────────────────────────────────────────────────────────── + ` + } + + reset() { + this.data = {} + } + + log(key: string, start: number) { + const duration = performance.now() - start + if (this.data[key]) { + this.data[key].push(duration) + } else { + this.data[key] = [duration] + } + } +} + +const defaultProfiler = new Profiler(process.env.GARDEN_ENABLE_PROFILING === "1") + +export function getDefaultProfiler() { + return defaultProfiler +} + +/** + * Class decorator that collects profiling data on every method invocation (if GARDEN_ENABLE_PROFILING=1). + */ +// tslint:disable-next-line: function-name +export function Profile(profiler?: Profiler) { + if (!profiler) { + profiler = getDefaultProfiler() + } + + return function(target: Function) { + for (const propertyName of Object.getOwnPropertyNames(target.prototype)) { + const propertyValue = target.prototype[propertyName] + const isMethod = propertyValue instanceof Function + if (!isMethod) { + continue + } + + const descriptor = Object.getOwnPropertyDescriptor(target.prototype, propertyName)! + const originalMethod = descriptor.value + + const timingKey = `${target.name}#${propertyName}` + + descriptor.value = function(...args: any[]) { + const start = performance.now() + // tslint:disable-next-line: no-invalid-this + const result = originalMethod.apply(this, args) + + if (!profiler!.isEnabled()) { + return result + } else if (isPromise(result)) { + return result + .catch((err: Error) => { + profiler!.log(timingKey, start) + throw err + }) + .then((v) => { + profiler!.log(timingKey, start) + return v + }) + } else { + profiler!.log(timingKey, start) + return result + } + } + + Object.defineProperty(target.prototype, propertyName, descriptor) + } + } +} + +/** + * Function decorator that collects profiling data on every function invocation (if GARDEN_ENABLE_PROFILING=1). + */ +export const profile = , U>(fn: (...args: T) => U, profiler?: Profiler) => { + if (!profiler) { + profiler = getDefaultProfiler() + } + + const timingKey = fn.name + + return (...args: T): U => { + const result = fn(...args) + const start = performance.now() + + if (!profiler!.isEnabled()) { + return result + } else { + profiler!.log(timingKey, start) + return result + } + } +} + +/** + * Async function decorator that collects profiling data on every function invocation (if GARDEN_ENABLE_PROFILING=1). + */ +export const profileAsync = , U>(fn: (...args: T) => Promise, profiler?: Profiler) => { + if (!profiler) { + profiler = getDefaultProfiler() + } + + const timingKey = fn.name + + return async (...args: T): Promise => { + const start = performance.now() + + if (!profiler!.isEnabled()) { + return fn(...args) + } else { + return fn(...args) + .catch((err: Error) => { + profiler!.log(timingKey, start) + throw err + }) + .then((v) => { + profiler!.log(timingKey, start) + return v + }) + } + } +} + +function isPromise(obj: any): obj is Promise { + return !!obj && (typeof obj === "object" || typeof obj === "function") && typeof obj.then === "function" +} diff --git a/garden-service/src/util/validate-dependencies.ts b/garden-service/src/util/validate-dependencies.ts index 457595c59a..8260037f00 100644 --- a/garden-service/src/util/validate-dependencies.ts +++ b/garden-service/src/util/validate-dependencies.ts @@ -15,6 +15,7 @@ import { ConfigurationError, ParameterError } from "../exceptions" import { ModuleConfig } from "../config/module" import { deline } from "./string" import { DependencyGraph, DependencyGraphNode, nodeKey as configGraphNodeKey } from "../config-graph" +import { Profile } from "./profiling" export function handleDependencyErrors( missingDepsError: ConfigurationError | null, @@ -97,6 +98,7 @@ export type DependencyValidationGraphNode = { description?: string // used instead of key when rendering node in circular dependency error messages } +@Profile() export class DependencyValidationGraph { graph: { [nodeKey: string]: DependencyValidationGraphNode } diff --git a/garden-service/src/vcs/git.ts b/garden-service/src/vcs/git.ts index cde497df3d..2d8b205a27 100644 --- a/garden-service/src/vcs/git.ts +++ b/garden-service/src/vcs/git.ts @@ -21,6 +21,7 @@ import { deline } from "../util/string" import { splitLast, exec } from "../util/util" import { LogEntry } from "../logger/log-entry" import parseGitConfig from "parse-git-config" +import { Profile } from "../util/profiling" export function getCommitIdFromRefList(refList: string[]): string { try { @@ -54,6 +55,7 @@ interface Submodule { } // TODO Consider moving git commands to separate (and testable) functions +@Profile() export class GitHandler extends VcsHandler { name = "git" diff --git a/garden-service/test/setup.ts b/garden-service/test/setup.ts index 345398471f..35b40aaba6 100644 --- a/garden-service/test/setup.ts +++ b/garden-service/test/setup.ts @@ -11,6 +11,7 @@ import timekeeper from "timekeeper" import { Logger } from "../src/logger/logger" import { LogLevel } from "../src/logger/log-node" import { makeTestGardenA } from "./helpers" +import { getDefaultProfiler } from "../src/util/profiling" // import { BasicTerminalWriter } from "../src/logger/writers/basic-terminal-writer" // make sure logger is initialized @@ -23,14 +24,18 @@ try { } catch (_) {} // Global hooks -before(async function(this: any) { - // tslint:disable-next-line:no-invalid-this - this.timeout(10000) +before(async () => { + getDefaultProfiler().setEnabled(true) // doing this to make sure ts-node completes compilation before running tests await makeTestGardenA() }) +after(() => { + // tslint:disable-next-line: no-console + console.log(getDefaultProfiler().report()) +}) + beforeEach(() => {}) afterEach(() => { td.reset() diff --git a/garden-service/test/unit/src/util/profiling.ts b/garden-service/test/unit/src/util/profiling.ts new file mode 100644 index 0000000000..8a20489a79 --- /dev/null +++ b/garden-service/test/unit/src/util/profiling.ts @@ -0,0 +1,117 @@ +/* + * Copyright (C) 2018-2020 Garden Technologies, Inc. + * + * This Source Code Form is subject to the terms of the Mozilla Public + * License, v. 2.0. If a copy of the MPL was not distributed with this + * file, You can obtain one at http://mozilla.org/MPL/2.0/. + */ + +import { Profiler, Profile, profile, profileAsync } from "../../../../src/util/profiling" +import { expect } from "chai" + +describe("profiling", () => { + let profiler: Profiler + + beforeEach(() => { + profiler = new Profiler(true) + }) + + describe("Profile", () => { + it("should collect timing on a basic class method", () => { + @Profile(profiler) + class TestClass { + someMethod() { + return 123 + } + } + + const instance = new TestClass() + + const value = instance.someMethod() + expect(value).to.equal(123) + + const profiling = profiler.getData() + const invocations = profiling["TestClass#someMethod"] + + expect(invocations).to.exist + expect(invocations.length).to.equal(1) + }) + + it("should collect timing on an async class method", async () => { + @Profile(profiler) + class TestClass { + async someMethod() { + return 123 + } + } + + const instance = new TestClass() + + const value = await instance.someMethod() + expect(value).to.equal(123) + + const profiling = profiler.getData() + const invocations = profiling["TestClass#someMethod"] + + expect(invocations).to.exist + expect(invocations.length).to.equal(1) + }) + }) + + describe("profile", () => { + it("should collect timing on a function call", () => { + const func = profile(function fn() { + return 123 + }, profiler) + + const value = func() + expect(value).to.equal(123) + + const profiling = profiler.getData() + const invocations = profiling["fn"] + + expect(invocations).to.exist + expect(invocations.length).to.equal(1) + }) + }) + + describe("profile", () => { + it("should collect timing on an async function call", async () => { + const func = profileAsync(async function fn() { + return 123 + }, profiler) + + const value = await func() + expect(value).to.equal(123) + + const profiling = profiler.getData() + const invocations = profiling["fn"] + + expect(invocations).to.exist + expect(invocations.length).to.equal(1) + }) + }) + + describe("reportProfiling", () => { + it("should return a profiling summary", async () => { + @Profile(profiler) + class TestClass { + someMethod() { + return 123 + } + async asyncMethod() { + return 123 + } + } + + const instance = new TestClass() + + for (let i = 0; i < 10; i++) { + instance.someMethod() + await instance.asyncMethod() + } + + profiler.report() + }) + }) +})