Using JavaScript Proxy to automatically time your functions

Using JavaScript Proxy to automatically time your functions

The Proxy class is a way of intercepting calls to an object. This post assumes basic knowledge of the Proxy object, there's plenty of good information, so read up if this is your first Proxy encounter (I like the MDN and javascript.info writeups).

The idea

Is to create a ProxyStats class that can time all calls to an object. I'll walk through the class creation in iterations, revisiting methods as functionality is added.

Initial implementation

Browse the code at github (commit #05a5e66)

class ProxyStats {
  constructor() {
    this._timers = {};
    this.stats = {};
  }

  static watch(target) {
    const proxyStats = new ProxyStats();
    return proxyStats.watch(target);
  }

  watch(target) {
    return new Proxy(target, this)
  }

  getTimeKey(target, property) {
    return `${target.constructor.name}.${property}`;
  }

  time(key) {
    this._timers[key] = Date.now();
  }

  timeEnd(key) {
    const time = Date.now() - this._timers[key];
    this.updateStats(key, time);

    console.log(key, `${time} ms (${this.stats[key].time} ms -- ${this.stats[key].count})`);
  }

  updateStats(key, time) {
    this.stats[key] = this.stats[key] || {time: 0, count: 0};

    this.stats[key].time +=  time;
    this.stats[key].count += 1;
  }

  get(target, property, receiver) {
    const timeKey = 'get ' + this.getTimeKey(target, property);

    this.time(timeKey);
    const result = Reflect.get(target, property, receiver);
    this.timeEnd(timeKey);

    return result;
  }

  set(target, property, value, receiver) {
    const timeKey = 'set ' + this.getTimeKey(target, property);

    this.time(timeKey);
    Reflect.set(target, property, value, receiver);
    this.timeEnd(timeKey);

    return true;
  }
}

The getTimeKey(), time(), timeEnd() and updateState() is used for timing and counting the calls to the object.

Both the static and prototype watch() function is used for watching an object.
The static function will automatically create a new ProxyStats, while the prototype function can be used to watch several objects with the same handler instance.
Using the same ProxyStats instance to watch several objects is helpful if you want to get statistics across all objects watched.

The get()^spec and set()^spec traps are both simple implementations. Using the Reflect^spec object to set or get the original value. This call is timed, and information is added to the ProxyStats.stats object.

Test setup

Prepare a simple class to test the proxy handler. Notice the 50 ms delays added in the getter, setter and function.

function slowFunction(min, max) {
  const end = Date.now() + Math.round(min + Math.random() * (max - min));
  while (Date.now() < end) { }
}

class ExampleClass {
  aProperty = 'some property'

  get aGetter() {
    slowFunction(50, 50);
    return 'some getter';
  }

  set aGetter($value) {
    slowFunction(50, 50);
  }

  aFunction() {
    slowFunction(50, 50);
  }
}

Now wrap the ExampleClass using the watch() function, and calling the different properties to see the output.

const exampleObject = ProxyStats.watch(new ExampleClass());
exampleObject.aProperty;
exampleObject.aGetter;
exampleObject.aGetter = '';
exampleObject.aFunction();

Output

The output here is the console output written in the timeEnd() function, it's the following format: KEY TIME ms (TOTAL_TIME ms -- COUNT).

KEY: The key tells what kind of trap is used, and the object property.
TIME: Is the time of the current call.
TOTAL_TIME: Time of all calls for that specific property.
COUNT: The amount of times the property has been called.

get ExampleClass.aProperty 0 ms (0 ms -- 1)
get ExampleClass.aGetter 50 ms (50 ms -- 1)
get ExampleClass.aGetter 50 ms (100 ms -- 2)
set ExampleClass.aGetter 50 ms (50 ms -- 1)
get ExampleClass.aFunction 0 ms (0 ms -- 1)
get ExampleClass.aFunction 0 ms (0 ms -- 2)

Getting a property (get ExampleClass.aProperty) is instant, so this seems fine at 0 ms.

Both the getter (get ExampleClass.aGetter) and setter (set ExampleClass.aGetter) takes 50 ms as expected.

But the function call (get ExampleClass.aFunction) is also instant, which is not correct. The reason it's instant is it only gets the property value, which is a function, it's not executing it.

Getting function timing to work

Browse the code at github (commit #bb97f3f)

To time function calls, the ProxyStats needs to wrap each function in another Proxy that utilizes the apply()^spec trap.

This is done by detecting functions in the get() trap and returning a new Proxy, created by the helper function handleFunction():

handleFunction(target, property, receiver) {
  const me = this;

  return new Proxy(target[property], {
    apply(fnTarget, thisArg, args) {
      const timeKey = me.getTimeKey(target, property) + '()';
      me.time(timeKey);
      const result = Reflect.apply(fnTarget, thisArg, args);
      me.timeEnd(timeKey);

      return result;
    }
  });
}

get(target, property, receiver) {
  if (typeof target[property] === 'function') {
    return this.handleFunction(target, property, receiver);
  }

  const timeKey = 'get ' + this.getTimeKey(target, property);

  this.time(timeKey);
  const result = Reflect.get(target, property, receiver);
  this.timeEnd(timeKey);

  return result;
}

It's a tiny rewrite of get() that returns early if the property is a function. All the functionality is in the handleFunction() function

Note that the new Proxy wraps the actual function target[property], and timing is simple and done the same way as with properties and getters.

Recursive functions

Browse the code at github (commit #c652f33)

The last issue in the POC is recursive functions. When the recursive function calls itself, it resets the timer because the key is identical. Updating the example object will give a clear view of the problem. So a recursive function is added to the ExampleClass.

aRecursiveFunction(depth) {
  slowFunction(50, 50);

  if (--depth > 0) {
    this.aRecursiveFunction(depth);
  }
}

Calling this function with depth 2 exampleObject.aRecursiveFunction(2); will give the following output:

ExampleClass.aRecursiveFunction() 0 ms (0 ms -- 1)
ExampleClass.aRecursiveFunction() 0 ms (0 ms -- 2)
ExampleClass.aRecursiveFunction() 0 ms (0 ms -- 3)

To fix this the timer key is made unique, so it no longer resets every time a function with the same name is called. This is done in the handleFunction() function by adding a random string to the key:

handleFunction(target, property, receiver) {
  const me = this;

  return new Proxy(target[property], {
    apply(fnTarget, thisArg, args) {
      const timeKey = me.getTimeKey(target, property) + '() -- ' + Math.random().toString(36).substring(2);
      me.time(timeKey);
      const result = Reflect.apply(fnTarget, thisArg, args);
      me.timeEnd(timeKey);

      return result;
    }
  });
}

The important part here is the random string suffix added to the timeKey.
Don't get confused about the Math.random().toString(36).substring(2) it's just a clever way of making a random string, try running it a couple of times in the console. This trick is purely cosmetics a Math.random() would've done the job.

This creates a problem with aggregating function calls, and makes it impossible, to sum up totals, check out the output:

ExampleClass.aFunction() -- mq55zfo3g99 50 ms (50 ms -- 1)
ExampleClass.aFunction() -- hw42ikytz5m 50 ms (50 ms -- 1)
ExampleClass.aRecursiveFunction() -- sirt14hqvn 50 ms (50 ms -- 1)
ExampleClass.aRecursiveFunction() -- hfcibln8qjf 100 ms (100 ms -- 1)

To solve this the suffix is removed from the key before calling updateStats() in the timeEnd(). This way the key used in the _timers is unique, but key used in the stats is only the function name without the unique part:

timeEnd(key) {
  const time = Date.now() - this._timers[key];

  key = key.split(' -- ').shift();
  this.updateStats(key, time);

  console.log(key, `${time} ms (${this.stats[key].time} ms -- ${this.stats[key].count})`);
}

This gives a result without the unique part:

ExampleClass.aFunction() 50 ms (50 ms -- 1)
ExampleClass.aFunction() 50 ms (100 ms -- 2)
ExampleClass.aRecursiveFunction() 50 ms (50 ms -- 1)
ExampleClass.aRecursiveFunction() 100 ms (150 ms -- 2)

There's still an issue with the total sum of the recursive function.

Initial call waits 50 ms, then calls itself.
The second call waits 50 ms before logging the time and ending the second call.
Now the initial call has been 100 ms underway, this is logged and initial call ended.
The total sum is calculated as second call + initial call, which is 150 ms even though only 100 ms is actually used in total.

At this time it's good enough for jazz, but this issue will be fixed later on.

Future

So far so good, the proof of concept seems to be working as intended (except for recursive functions).

As I'll be expanding on the ProxyStats class I'll try to create relevant blog posts. The following is a list of possible topics (also functioning as notes for myself, so every bullet might not justify a blog post), in no particular order:

Fix the recursive function issue.
Documenting the class, using JSDoc.
How to use the ProxyStats class.
Testing, with simple unit tests.
Adding more features, filtering calls, smarter watcher functions.
Iterating existing functions and reviewing/rewriting code.
Performance, any obvious performance improvements.