Skip to main content

CodeSpy - A Server-Side Script Profiler for ServiceNow

WARNING
#

This tool is dangerous and should only be used in sandbox instances.

Patching over an important system function improperly can fully brick an instance. For instance, the global GlideRecord prototype is used by a number of critical system functions, so if you incorrectly patch it, you brick your instance until Rhino either restarts or crashes. You can’t restart a PDI on demand, so you are pretty much screwed (unless you figure out how to crash Rhino) and asking/waiting on ServiceNow to restart an dev instance because you randomly patched over a system function is a bad look.

Usage
#

You must run CodeSpy from the global scope, I recommend a global background script.

CodeSpy allows you to profile server side scripts, capturing things like call trees, execution times and more. It’s a great way to identify bottlenecks and optimize your scripts.

The safest (and only way you should be using this tool), is to use the CodeSpy class, it’s a wrapper around the profiler that catches errors in the profiled code, so if anything goes wrong, it will clean up after itself. Otherwise you risk not cleaning up your spies, if you accidentally comment out a line of code, or forget to try/catch which is how you get into trouble.

CodeSpy.profileFunc() expects to be passed a function that contains the code you want to profile, this function should accept a single parameter for a instance of the ServerSideProfiler. You are in charge of setting up the function spies within the passed function and calling profiler.enable().

Enabling and Disabling
#

To enable the profiler, you can call ServerSideProfiler.enable() and to disable it, you can call ServerSideProfiler.disable(). Don’t enable until you have setup your spies and done any setup. Using disable is optional CodeSpy will do it for you after executing the passed function.

Spying on Functions, Classes and Prototypes
#

You can spy on a function by calling profiler.spyOnFunction(object, methodName). You can spy on all methods on an object or class by using profiler.spyOnAllFunctions(object).

Until the profiler is enabled, these spied on functions will call through and not be profiled. The original function is stored as a property of the spy object, and each spy object has a restore() method that allows us to restore the original function. You cannot spy on a function that is already being spied on.

Only javascript functions can be spied on, Java objects and non-functions cannot and will just fail silently.

To spy on a prototype, you simply use the object.prototype syntax to target the prototype you want to spy on. This means that any instances of the object will have the spy applied.

Example Usage
#

var codeSpy = new CodeSpy();
  var sandboxFunc = function(profiler) {
    var testScript = new TestScriptInclude();
  
    //Setup spies on the Script Include and GlideRecord prototype
    profiler.spyOnAllFunctions(testScript);
    profiler.spyOnAllFunctions(GlideRecord.prototype);
    profiler.enable();
    
    //Do the actual work
    testScript.getAllIncidentAssigneesSlow();
    testScript.getAllIncidentAssigneesFast();
    testScript.getAllIncidentAssigneesGlacial();
  }
  
  //CodeSpy returns a ProfilerResults object
  var results = codeSpy.profileFunc(sandboxFunc);
  gs.info(results)

Getting the Results
#

Once profiling is complete, you can get the results by just printing out the result object. The toString version of the results is a profile report, showing the call tree, execution times and more. There is also toJSONString to get a JSON object representing the raw call tree.

Example Output
#

============================Performance Profile============================
  
                              Aggregated Functions                            
  -----------------------------------------------------------------------------
             Function            | Total Duration | Calls | Average Duration
  -----------------------------------------------------------------------------
  root                           | 265ms          | 1     | 265.00ms        
  getAllIncidentAssigneesGlacial | 133ms          | 1     | 133.00ms        
  next                           | 78ms           | 219   | 0.36ms          
  getAllIncidentAssigneesSlow    | 64ms           | 1     | 64.00ms         
  get                            | 63ms           | 72    | 0.88ms          
  getAllIncidentAssigneesFast    | 55ms           | 1     | 55.00ms         
  getDisplayValue                | 24ms           | 72    | 0.33ms          
  query                          | 16ms           | 3     | 5.33ms          
  getValue                       | 7ms            | 48    | 0.15ms          
  getUniqueValue                 | 1ms            | 97    | 0.01ms          
  
                                   Call Tree
  ---------------------------------------------------------------------------
  root - 265ms - 100%
  |  getAllIncidentAssigneesSlow - 64ms - 24%
  |  |  query - 13ms - 20%
  |  |  next - 14ms - 22%
  |  |  getUniqueValue - 0ms - 0%
  |  |  next - 2ms - 3%
  |  |  next - 0ms - 0%
  |  |  next - 0ms - 0%
  |  |  getUniqueValue - 0ms - 0
  cont..

Technical Details
#

How does it work?
#

Premature optimization causes more problems than it solves, but when it comes to optimize, being able to measure rather than just guessing where the bottlenecks are is a must. ServiceNow provides us GlideStopWatch that allows us to measure performance, but setting up logging statements and timing sections across a script is a huge pain.

I started by trying to build a wrapper around GlideStopWatch that would improve the experience of using it, but I quickly realized that I could take it a step further and build a full profiler.

The profiler functionality is based around how spies are implemented in testing tools like Jest. Essentially, we wrap any function we want to profile in a wrapper that times the execution and allows us to capture things like call trees, execution times and more. We can even spy on a prototype, so we can profile methods on objects before they are instantiated, without having to modify the original code.

Function Spies
#

To apply a function spy, we essentially override the function with a new function, the new function still calls through to our existing function and returns the result. However it also does some additional leg work, logging start and end of the call, as well as any arguments passed in and returned.

sequenceDiagram
    participant Caller
    participant MonkeyPatch as Spy Function
    participant OriginalFunction
    participant Logger

    Caller->>MonkeyPatch: Call function
    MonkeyPatch->>Logger: Log function call
    MonkeyPatch->>OriginalFunction: Pass through call
    OriginalFunction-->>MonkeyPatch: Return result
    MonkeyPatch->>Logger: Call complete
    MonkeyPatch-->>Caller: Return result
    
    note over MonkeyPatch: Wraps original function,
adds logging behavior

CallTree via Nodes
#

Since our code is running synchronously, we can build a call tree like a stack, every time we return from a function we know the item at the top of the stack is the most recent function ending. If we enter a new function, that just becomes the top item on the stack. In code we represent each function call as a node, with a parent of its calling function or the root node and the functions it calls, as its children.

Source Code
#

7 files
var CodeSpy = Class.create();
  CodeSpy.prototype = {
    /**
     * Runs the profiler against the passed function, cleaning up
     * the spies and returning the resulting ProfilerResult object.
     * You are responsible for setting up the spies, this will complete
     * the profiler for you don't.
     *
     * @param {Function} func The function to profile
     * @returns {ProfilerResult} The profiler result
     */
    profileFunc: function (func) {
      var profiler = new ServerSideProfiler();
      try {
        func(profiler);
      } catch (e) {
        gs.error(e);
        profiler.addError(e);
      } finally {
        profiler.complete();
      }
  
      return profiler.getResult();
    },
    type: "CodeSpy",
  };
var CallTree = Class.create();
  CallTree.prototype = {
      initialize: function () {
          this.root = new CallTreeNode('root', 'root');
          this.root.incrementCount();
      },
  
      type: 'CallTree'
  };

Crashing Rhino
#

If you are using this tool and find yourself in a pickle, it is possible to crash Rhino, or at least forcing Rhino to recompile the globals that you screwed up. If you can restart a node, I’d do that, but in a PDI you can’t. I just run the following script in a global background script and it pretty quickly crashes Rhino and seems to restart the PDI.

var test = "CRASH RHINO";
var arr = [];
while(true){
  arr.push(test.repeat(1000000));
}
Thomas Walker
Author
Thomas Walker