Implement deno.trace() (#795)

BUILD.gn

@@ -80,6 +80,7 @@ ts_sources = [
   "js/symlink.ts",
   "js/text_encoding.ts",
   "js/timers.ts",
+  "js/trace.ts",
   "js/types.ts",
   "js/util.ts",
   "js/v8_source_maps.ts",

js/deno.ts

@@ -13,4 +13,5 @@ export { writeFileSync, writeFile } from "./write_file";
 export { ErrorKind, DenoError } from "./errors";
 export { libdeno } from "./libdeno";
 export { arch, platform } from "./platform";
+export { trace } from "./trace";
 export const argv: string[] = [];

js/dispatch.ts

@@ -4,6 +4,7 @@ import { flatbuffers } from "flatbuffers";
 import * as fbs from "gen/msg_generated";
 import * as errors from "./errors";
 import * as util from "./util";
+import { maybePushTrace } from "./trace";
 
 let nextCmdId = 0;
 const promiseTable = new Map<number, util.Resolvable<fbs.Base>>();
@@ -29,6 +30,7 @@ export function sendAsync(
   msgType: fbs.Any,
   msg: flatbuffers.Offset
 ): Promise<fbs.Base> {
+  maybePushTrace(msgType, false); // add to trace if tracing
   const [cmdId, resBuf] = sendInternal(builder, msgType, msg, false);
   util.assert(resBuf == null);
   const promise = util.createResolvable<fbs.Base>();
@@ -42,6 +44,7 @@ export function sendSync(
   msgType: fbs.Any,
   msg: flatbuffers.Offset
 ): null | fbs.Base {
+  maybePushTrace(msgType, true); // add to trace if tracing
   const [cmdId, resBuf] = sendInternal(builder, msgType, msg, true);
   util.assert(cmdId >= 0);
   if (resBuf == null) {

js/trace.ts

@@ -0,0 +1,80 @@
+// Copyright 2018 the Deno authors. All rights reserved. MIT license.
+import * as fbs from "gen/msg_generated";
+
+export interface TraceInfo {
+  sync: boolean; // is synchronous call
+  name: string; // name of operation
+}
+
+interface TraceStackNode {
+  list: TraceInfo[];
+  prev: TraceStackNode | null;
+}
+
+let current: TraceStackNode | null = null;
+
+// Push a new list to trace stack
+function pushStack(): void {
+  if (current === null) {
+    current = { list: [], prev: null };
+  } else {
+    const newStack = { list: [], prev: current };
+    current = newStack;
+  }
+}
+
+// Pop from trace stack and (if possible) concat to parent trace stack node
+function popStack(): TraceInfo[] {
+  if (current === null) {
+    throw new Error("trace list stack should not be empty");
+  }
+  const resultList = current!.list;
+  if (!!current!.prev) {
+    const prev = current!.prev!;
+    // concat inner results to outer stack
+    prev.list = prev.list.concat(resultList);
+    current = prev;
+  } else {
+    current = null;
+  }
+  return resultList;
+}
+
+// Push to trace stack if we are tracing
+export function maybePushTrace(op: fbs.Any, sync: boolean): void {
+  if (current === null) {
+    return; // no trace requested
+  }
+  // Freeze the object, avoid tampering
+  current!.list.push(
+    Object.freeze({
+      sync,
+      name: fbs.Any[op] // convert to enum names
+    })
+  );
+}
+
+/**
+ * Trace operations executed inside a given function or promise.
+ * Notice: To capture every operation in asynchronous deno.* calls,
+ * you might want to put them in functions instead of directly invoking.
+ *
+ *     import { trace, mkdir } from "deno";
+ *
+ *     const ops = await trace(async () => {
+ *       await mkdir("my_dir");
+ *     });
+ *     // ops becomes [{ sync: false, name: "Mkdir" }]
+ */
+export async function trace(
+  // tslint:disable-next-line:no-any
+  fnOrPromise: Function | Promise<any>
+): Promise<TraceInfo[]> {
+  pushStack();
+  if (typeof fnOrPromise === "function") {
+    await fnOrPromise();
+  } else {
+    await fnOrPromise;
+  }
+  return popStack();
+}

js/trace_test.ts

@@ -0,0 +1,81 @@
+import { testPerm, assertEqual } from "./test_util.ts";
+import * as deno from "deno";
+
+testPerm({ write: true }, async function traceFunctionSuccess() {
+  const op = await deno.trace(async () => {
+    const enc = new TextEncoder();
+    const data = enc.encode("Hello");
+    // Mixing sync and async calls
+    const filename = deno.makeTempDirSync() + "/test.txt";
+    await deno.writeFile(filename, data, 0o666);
+    await deno.removeSync(filename);
+  });
+  assertEqual(op.length, 3);
+  assertEqual(op[0], { sync: true, name: "MakeTempDir" });
+  assertEqual(op[1], { sync: false, name: "WriteFile" });
+  assertEqual(op[2], { sync: true, name: "Remove" });
+});
+
+testPerm({ write: true }, async function tracePromiseSuccess() {
+  // Ensure we don't miss any send actions
+  // (new Promise(fn), fn runs synchronously)
+  const asyncFunction = async () => {
+    const enc = new TextEncoder();
+    const data = enc.encode("Hello");
+    // Mixing sync and async calls
+    const filename = deno.makeTempDirSync() + "/test.txt";
+    await deno.writeFile(filename, data, 0o666);
+    await deno.removeSync(filename);
+  };
+  const promise = Promise.resolve().then(asyncFunction);
+  const op = await deno.trace(promise);
+  assertEqual(op.length, 3);
+  assertEqual(op[0], { sync: true, name: "MakeTempDir" });
+  assertEqual(op[1], { sync: false, name: "WriteFile" });
+  assertEqual(op[2], { sync: true, name: "Remove" });
+});
+
+testPerm({ write: true }, async function traceRepeatSuccess() {
+  const op1 = await deno.trace(async () => await deno.makeTempDir());
+  assertEqual(op1.length, 1);
+  assertEqual(op1[0], { sync: false, name: "MakeTempDir" });
+  const op2 = await deno.trace(async () => await deno.statSync("."));
+  assertEqual(op2.length, 1);
+  assertEqual(op2[0], { sync: true, name: "Stat" });
+});
+
+testPerm({ write: true }, async function traceIdempotence() {
+  let op1, op2, op3;
+  op1 = await deno.trace(async () => {
+    const filename = (await deno.makeTempDir()) + "/test.txt";
+    op2 = await deno.trace(async () => {
+      const enc = new TextEncoder();
+      const data = enc.encode("Hello");
+      deno.writeFileSync(filename, data, 0o666);
+      op3 = await deno.trace(async () => {
+        await deno.remove(filename);
+      });
+      await deno.makeTempDir();
+    });
+  });
+
+  // Flatten the calls
+  assertEqual(op1.length, 4);
+  assertEqual(op1[0], { sync: false, name: "MakeTempDir" });
+  assertEqual(op1[1], { sync: true, name: "WriteFile" });
+  assertEqual(op1[2], { sync: false, name: "Remove" });
+  assertEqual(op1[3], { sync: false, name: "MakeTempDir" });
+
+  assertEqual(op2.length, 3);
+  assertEqual(op2[0], { sync: true, name: "WriteFile" });
+  assertEqual(op2[1], { sync: false, name: "Remove" });
+  assertEqual(op2[2], { sync: false, name: "MakeTempDir" });
+
+  assertEqual(op3.length, 1);
+  assertEqual(op3[0], { sync: false, name: "Remove" });
+
+  // Expect top-level repeat still works after all the nestings
+  const op4 = await deno.trace(async () => await deno.statSync("."));
+  assertEqual(op4.length, 1);
+  assertEqual(op4[0], { sync: true, name: "Stat" });
+});

js/unit_tests.ts

@@ -16,3 +16,4 @@ import "./timers_test.ts";
 import "./symlink_test.ts";
 import "./platform_test.ts";
 import "./text_encoding_test.ts";
+import "./trace_test.ts";