Chore: Mobile: Log startup performance information (#12776)

Co-authored-by: Laurent Cozic <laurent22@users.noreply.github.com>
2025-11-26 22:41:17 +02:00 · 2025-07-25 01:20:38 -07:00
parent 999ec8c11f
commit 4c90cd62fe
11 changed files with 784 additions and 437 deletions
--- a/packages/lib/PerformanceLogger.ts
+++ b/packages/lib/PerformanceLogger.ts
@@ -0,0 +1,148 @@
+import { Second } from '@joplin/utils/time';
+
+const formatDuration = (durationMs: number) => {
+	const round = (n: number) => Math.round(n * 100) / 100;
+	if (durationMs < Second / 4) {
+		return `${round(durationMs)}ms`;
+	} else {
+		return `${round(durationMs / Second)}s`;
+	}
+};
+
+const formatTaskDuration = (durationMs: number) => {
+	const formatted = formatDuration(durationMs);
+	if (durationMs < Second / 2) {
+		return formatted;
+	} else if (durationMs < Second) {
+		return `[ ${formatted} ]`;
+	} else {
+		// Wrap in [[ ]]s to make longer durations more visible.
+		return `[[ ${formatted} ]]`;
+	}
+};
+
+let timeOrigin = 0;
+const formatAbsoluteTime = (time: number) => {
+	return formatDuration(time - timeOrigin);
+};
+
+const hasPerformanceMarkApi = typeof performance.mark === 'function' && typeof performance.measure === 'function';
+
+type LogCallback = (message: string)=> void;
+type LogEntry = {
+	isDebug: boolean;
+	message: string;
+};
+
+type LoggerSlice = {
+	info: (message: string)=> void;
+	debug: (message: string)=> void;
+};
+
+export default class PerformanceLogger {
+	// Since one of the performance logger's uses is profiling
+	// startup code, it's useful to have a default log implementation
+	// (for before the logger is initialized).
+	private static logBuffer_: LogEntry[] = [];
+	private static readonly defaultLog_: LogCallback = message => {
+		this.logBuffer_.push({ message, isDebug: false });
+	};
+	private static readonly defaultLogDebug_: LogCallback = message => {
+		this.logBuffer_.push({ message, isDebug: true });
+	};
+	private static log_: LogCallback = this.defaultLog_;
+	private static logDebug_: LogCallback = this.defaultLogDebug_;
+
+	// For testing
+	public static reset_() {
+		timeOrigin = 0;
+		this.logBuffer_ = [];
+		this.log_ = this.defaultLog_;
+		this.logDebug_ = this.defaultLogDebug_;
+	}
+
+	// In some environments, performance.now() gives the number of milliseconds since
+	// application startup. This does not seem to be the case on all environments, however,
+	// so we allow customizing the app start time.
+	public static onAppStartBegin() {
+		const now = performance.now();
+		timeOrigin = now;
+
+		this.log_(`Starting application at ${formatDuration(now)}`);
+	}
+
+	public static setLogger(logger: LoggerSlice) {
+		const tag = 'Performance';
+		this.log_ = (message) => logger.info(`${tag}: ${message}`);
+		this.logDebug_ = (message) => logger.debug(`${tag}: ${message}`);
+
+		for (const item of this.logBuffer_) {
+			if (item.isDebug) {
+				this.logDebug_(item.message);
+			} else {
+				this.log_(item.message);
+			}
+		}
+		this.logBuffer_ = [];
+	}
+
+	private lastLogTime_ = 0;
+	public static create(prefix: string) {
+		return new PerformanceLogger(prefix);
+	}
+
+	private constructor(private readonly prefix_: string) { }
+
+	public mark(name: string) {
+		name = `${this.prefix_}/${name}`;
+
+		// If available, make it possible to inspect the performance mark from the F12
+		// developer tools.
+		if (hasPerformanceMarkApi) {
+			performance.mark(name);
+		}
+
+		const now = performance.now();
+		const timeDelta = now - this.lastLogTime_;
+		this.lastLogTime_ = now;
+		PerformanceLogger.log_(`${name}: Mark at ${formatAbsoluteTime(now)}   +${formatDuration(timeDelta)}`);
+	}
+
+	public async track<T>(name: string, task: ()=> Promise<T>): Promise<T> {
+		const tracker = this.taskStart(name);
+		try {
+			return await task();
+		} finally {
+			tracker.onEnd();
+		}
+	}
+
+	public taskStart(name: string) {
+		name = `${this.prefix_}/${name}`;
+
+		if (typeof performance.mark === 'function') {
+			performance.mark(`${name}-start`);
+		}
+
+		const startTime = performance.now();
+		PerformanceLogger.logDebug_(`${name}: Start at ${formatAbsoluteTime(startTime)}`);
+
+		const onEnd = () => {
+			const now = performance.now();
+			if (hasPerformanceMarkApi) {
+				performance.mark(`${name}-end`);
+				performance.measure(name, `${name}-start`, `${name}-end`);
+			}
+
+			const duration = now - startTime;
+			// Increase the log level for long-running tasks
+			const isLong = duration >= Second / 10;
+			const log = isLong ? PerformanceLogger.log_ : PerformanceLogger.logDebug_;
+
+			log(`${name}: End at ${formatAbsoluteTime(now)} (took ${formatTaskDuration(now - startTime)})`);
+		};
+		return {
+			onEnd,
+		};
+	}
+}