improve logging logic and add a dbg.time call for easy tracking

Author: velzie

src/client/shared/sourcemaps.ts

@@ -191,23 +191,7 @@ export default function (client: ScramjetClient, self: Self) {
 			value: (buf: Array<number>, tag: string) => {
 				const before = performance.now();
 				registerRewrites(buf, tag);
-				const after = performance.now();
-
-				const duration = after - before;
-
-				if (flagEnabled("rewriterLogs", new URL(location.href))) {
-					let timespan: string;
-					if (duration < 1) {
-						timespan = "BLAZINGLY FAST";
-					} else if (duration < 500) {
-						timespan = "decent speed";
-					} else {
-						timespan = "really slow";
-					}
-					console.log(
-						`js rewrite parsing for scramtag ${tag} was ${timespan} (${duration.toFixed(2)}ms)`
-					);
-				}
+				dbg.time(client.meta, before, `scramtag parse for ${tag}`);
 			},
 			enumerable: false,
 			writable: false,
@@ -221,23 +205,7 @@ export default function (client: ScramjetClient, self: Self) {
 		apply(ctx) {
 			const before = performance.now();
 			doUnrewrite(ctx);
-			const after = performance.now();
-
-			const duration = after - before;
-
-			if (flagEnabled("rewriterLogs", new URL(location.href))) {
-				let timespan: string;
-				if (duration < 1) {
-					timespan = "BLAZINGLY FAST";
-				} else if (duration < 500) {
-					timespan = "decent speed";
-				} else {
-					timespan = "really slow";
-				}
-				console.log(
-					`js unrewrite for function was ${timespan} (${duration.toFixed(2)}ms)`
-				);
-			}
+			dbg.time(client.meta, before, `scramtag unrewrite for ${ctx.fn.name}`);
 		},
 	});
 }

src/global.d.ts

@@ -3,6 +3,7 @@ declare const dbg: {
 	warn: (message: string, ...args: any[]) => void;
 	error: (message: string, ...args: any[]) => void;
 	debug: (message: string, ...args: any[]) => void;
+	time: (meta: URLMeta, before: number, type: string) => void;
 };
 
 declare const COMMITHASH: string;

src/log.ts

@@ -1,3 +1,6 @@
+import { flagEnabled } from "./scramjet";
+import type { URLMeta } from "./shared/rewriters/url";
+
 export default {
 	fmt: function (severity: string, message: string, ...args: any[]) {
 		const old = Error.prepareStackTrace;
@@ -30,6 +33,9 @@ export default {
 
 		Error.prepareStackTrace = old;
 
+		this.print(severity, fmt, message, ...args);
+	},
+	print(severity: string, tag: string, message: string, ...args: any[]) {
 		const fn = console[severity] || console.log;
 		const bg = {
 			log: "#000",
@@ -51,15 +57,15 @@ export default {
 		}[severity];
 
 		fn(
-			`%c${fmt}%c ${message}`,
+			`%c${tag}%c ${message}`,
 			`
-		background-color: ${bg};
-		color: ${fg};
-		padding: ${padding}px;
-		font-weight: bold;
-		font-family: monospace;
-		font-size: 0.9em;
-	`,
+  	background-color: ${bg};
+  	color: ${fg};
+  	padding: ${padding}px;
+  	font-weight: bold;
+  	font-family: monospace;
+  	font-size: 0.9em;
+  `,
 			`${severity === "debug" ? "color: gray" : ""}`,
 			...args
 		);
@@ -76,4 +82,23 @@ export default {
 	debug: function (message: string, ...args: any[]) {
 		this.fmt("debug", message, ...args);
 	},
+	time(meta: URLMeta, before: number, type: string) {
+		if (!flagEnabled("rewriterLogs", meta.base)) return;
+		const after = performance.now();
+		const duration = after - before;
+
+		let timespan: string;
+		if (duration < 1) {
+			timespan = "BLAZINGLY FAST";
+		} else if (duration < 500) {
+			timespan = "decent speed";
+		} else {
+			timespan = "really slow";
+		}
+		this.print(
+			"debug",
+			"[time]",
+			`${type} was ${timespan} (${duration.toFixed(2)}ms)`
+		);
+	},
 };

src/shared/rewriters/html.ts

@@ -98,14 +98,14 @@ export function rewriteHtml(
 	fromTop: boolean = false
 ) {
 	const before = performance.now();
-	let ret = rewriteHtmlInner(html, cookieStore, meta, fromTop);
-	const after = performance.now();
+	const ret = rewriteHtmlInner(html, cookieStore, meta, fromTop);
+	dbg.time(meta, before, "html rewrite");
 	// let wasm = rewriteHtmlWasm(html, cookieStore, meta, fromTop);
 	// let js = after - before;
-	console.log(`html rewrite took ${after - before}ms`);
 	// console.log(
 	// 	`html rewrite took ${js}ms in js and ${wasm}ms in wasm, ${((wasm - js) / js) * 100}%`
 	// );
+
 	return ret;
 }
 

src/shared/rewriters/js.ts

@@ -40,9 +40,9 @@ function rewriteJsWasm(
 
 			return { js: input, tag: "", map: null };
 		}
-		const after = performance.now();
+		dbg.time(meta, before, `oxc rewrite for "${source || "(unknown)"}"`);
+
 		let { js, map, scramtag, errors } = out;
-		let duration = after - before;
 
 		if (flagEnabled("sourcemaps", meta.base) && !globalThis.clients) {
 			globalThis[globalThis.$scramjet.config.globals.pushsourcemapfn](
@@ -59,20 +59,6 @@ function rewriteJsWasm(
 			}
 		}
 
-		if (flagEnabled("rewriterLogs", meta.base)) {
-			let timespan: string;
-			if (duration < 1) {
-				timespan = "BLAZINGLY FAST";
-			} else if (duration < 500) {
-				timespan = "decent speed";
-			} else {
-				timespan = "really slow";
-			}
-			console.log(
-				`oxc rewrite for "${source || "(unknown)"}" was ${timespan} (${duration}ms)`
-			);
-		}
-
 		return {
 			js: typeof input === "string" ? decoder.decode(js) : js,
 			tag: scramtag,