diff --git a/src/plugins/nunjucks.ts b/src/plugins/nunjucks.ts index 3c9e2a097..09536e9c4 100644 --- a/src/plugins/nunjucks.ts +++ b/src/plugins/nunjucks.ts @@ -140,26 +140,41 @@ export class NunjucksTemplateEngine implements TemplateEngineComponent { this.env.addFilter('t', NunjucksBuiltInFilters.t); } + getTimer(podPath?: string) { + podPath = podPath || 'self'; + return this.pod.profiler.timer( + `templates.render.${podPath}`, + 'Template render', + { + podPath: podPath, + } + ); + } + render(path: string, context: any): Promise { return new Promise((resolve, reject) => { + const timer = this.getTimer(path); this.env.render(path, context, (err, res) => { if (err) { reject(err); return; } resolve(res || ''); + timer.stop(); }); }); } renderFromString(template: string, context: any): Promise { return new Promise((resolve, reject) => { + const timer = this.getTimer(); this.env.renderString(template, context, (err, res) => { if (err) { reject(err); return; } resolve(res || ''); + timer.stop(); }); }); } diff --git a/src/profile.ts b/src/profile.ts index f62f4f89c..09863a42f 100644 --- a/src/profile.ts +++ b/src/profile.ts @@ -1,4 +1,5 @@ import Table = require('cli-table'); + import {performance} from 'perf_hooks'; interface TimeParts { @@ -49,7 +50,7 @@ export class Profiler { // They also do not provide much value for diffing benchmarks since they // are so small. For now, filter them out of the output file. const filteredKeys = allKeys.filter(key => { - return !key.match(/builder\.build\..*/i); + return !key.match(ProfileReport.EXCLUDE_FROM_BENCHMARK_REGEX); }); for (const key of filteredKeys) { @@ -223,10 +224,12 @@ export class Timer { } export class ProfileReport { - static BUILD_REPORT_REGEX = /^builder\.build\./; + static BUILD_REPORT_REGEX = /(^builder\.build\..*)|(^templates\.render\..*)/i; + static EXCLUDE_FROM_BENCHMARK_REGEX = ProfileReport.BUILD_REPORT_REGEX; static HOOK_REPORT_REGEX = /^plugins\.hook\..*/; static HOOK_REPORT_SUB_REGEX = /^plugins\.hook\.[^\.]*\./; static IGNORED_THRESHOLDS = new Set([/^builder\.build\./]); + static TEMPLATE_REPORT_REGEX = /^templates\.render\./; static MAX_WIDTH = 80; logMethod: Function; profiler: Profiler; @@ -258,6 +261,7 @@ export class ProfileReport { this.reportHooks(shownTimerKeys); this.reportTimers(shownTimerKeys); this.reportSlowBuilds(shownTimerKeys); + this.reportTemplates(shownTimerKeys); } reportHooks(shownTimerKeys: Set) { @@ -290,6 +294,35 @@ export class ProfileReport { } } + reportTemplates(shownTimerKeys: Set) { + const duration = this.profiler.duration; + const filteredTimerTypes = this.filter((timerType: TimerType) => { + return ProfileReport.TEMPLATE_REPORT_REGEX.test(timerType.key); + }); + for (const timerType of filteredTimerTypes) { + shownTimerKeys.add(timerType.key); + } + const reportSection = new ProfileReportSection( + 'Templates', + filteredTimerTypes, + duration + ); + + // Show the longest timers first. + reportSection.timerTypes.sort( + (a: TimerType, b: TimerType) => b.duration - a.duration + ); + + // Use the podPath as the label. + reportSection.labelFunc = (timerType: TimerType): string => + timerType.meta.podPath; + + const reportOutput = reportSection.toString(12); + if (reportOutput) { + this.logMethod(reportOutput); + } + } + reportSlowBuilds(shownTimerKeys: Set) { const duration = this.profiler.duration; const filteredTimerTypes = this.filter((timerType: TimerType) => {