Post Featured Image

TIL Thursday: Troubleshoot JavaScript and SuiteScript Performance with Console Timers

The advice in this blog post applies to all JavaScript and SuiteScript files, but it is SuiteCommerce-centric. The examples are for sites running Vinson or newer as we are modifying service controllers; you can, however, modify them to work with older architecture.

A common performance question I see goes something like this:

"Whenever a user visits [page], there's a long delay in the service before anything happens. I don't know where it's coming from. How can I find out what's happening?"

SuiteCommerce SuiteScript can be tricky to troubleshoot. As sites grow more complicated, additional parts of a NetSuite instance get called, records have to be loaded and saved, and even third-party integrations may get involved.

This blog post won't tell you the specific reason why your service is taking along time — I can't tell you that! — but what I can do is help you track down the culprit. For that, we're going to use a useful tool with you that you might not know about: console timers.

Put simply, what these let you do is start a timer when at an arbitrary point in your JS, and then end it at another. The idea is that when you're trying to figure out what is causing your site bother, you can start a timer, make a call (eg, for records, another service, etc) and then end it when it completes; the time it takes is then returned to the console (or the SSP application log) in milliseconds. Repeat this for various parts of your SuiteScript files and you'll find out where the performance problem is.

I'm going to post an example of how to use it below, troubleshooting three fictional functions I wrote that are called before the get() method is called on my LiveOrder service controller.

Create a Dummy File

To start, we're going to create a SuiteScript file that listens for the before:LiveOrder.ServiceController.get event; in other words: before the get() method in LiveOrder.ServiceController runs, our code will run first.

What we're going to do eventually is use this to block the actual call to the NetSuite system with a synchronous XHR (via nlapiRequestURL) that takes ages to load. We're going to test this on the shopping cart page: the effect is that the user will try to access the cart and get served a blank screen while the system resolves the promise in the backend.

As we're not going to keep this functionality, I'm not going to suggest creating a whole seperate module or anything, just a single file. (Just make sure you delete it and undo your changes afterwards.)

In LiveOrder > SuiteScript, create LiveOrder.Delayer.js with:

define('LiveOrder.Delayer'
, [
    'Application'
  ]
, function
  (
    Application
  )
{
  'use strict';

  console.log('Live Order Delayer loaded -- delaying your live order model');

  Application.on('before:LiveOrder.ServiceController.get', function ()
  {
    console.log(someThing());
    console.log(someOtherThing());
    console.log(someExtraThing());
  });

  function someThing ()
  {
    // does some call
    return 'Some: 200'
  }

  function someOtherThing ()
  {
    // does some call
    return 'Other: 200'
  }

  function someExtraThing ()
  {
    // does some call
    return 'Extra: 200'
  }
});

So we're adding in an event listener for when the service controller is called, which then logs the result of three functions. The returned values of our functions will appear in the SSP application log.

Now, we need to make sure it's added to our compiled code.

Open distro.json and add "LiveOrder.Delayer" to the ssp-libraries object.

After saving all your files, deploy (eg, using gulp deploy --no-backup --source-services, which will just deploy SuiteScript files and not produce a backup) and go test.

Add at least one item to your cart and then head to the shopping cart page. It should work and load normally with no slowness. Then, in NetSuite, go to the application log for your SCA SSP. You should see something like this:

So with everything normal, let's simulate a long records call.

Add in a Delay

I'm sure I could come up with a way of creating a really long and taxing call to NetSuite for records, but we don't actually want to do that, do we? I mean, it would be unnecessary load and I would probably get emails from the operations team. So, what we can do instead is use a service that simulates this instead.

For this, I'm using httpbin(1): a request and response service that is great for testing various HTTP scenarios. In particular, they have a service that will accept a request and then wait a specified amount of time before responding — perfect for us, which we can use to simulate a painfully long call.

In LiveOrder.Delayer.js.v2, replace the code of someOtherThing() with:

function someOtherThing ()
{
  // does some call
  var request = nlapiRequestURL('https://httpbin.org/delay/10')
  , response = 'Other: ' + request.getCode();

  return response
}

One of their APIs is the delayed response service. By specifying /delay/10, we're telling it to send the request after waiting 10 seconds. When we have that, we're plucking out the HTTP response code (which should be a 200) and returning that.

If you deploy and refresh, you should see that your log returns the exact same messages, except that it takes an excruciatingly long 10 seconds longer to do so. But wait... oh no! That means our service is delayed! Our customers are going to be annoyed! What are we going to do!? How ever will we diagnose this problem!?

Console Timers

This is where the superhero of console timers come in to save the day.

Basic notation is something like this:

console.time('myTimer');
// some code runs here
console.timeEnd('myTimer');

What's happening is we're starting our stopwatch, which we've named myTimer, running some code (whatever it is), and then stopping it. The engine will then print in the console the name of the timer along with how long it was running for.

If you want to quickly test it in your browser's console, try something like this:

function delayMe (delay)
{
  xhr = new XMLHttpRequest;  
  xhr.open('GET', 'https://httpbin.org/delay/' + delay, false);
  
  console.time('Delayed for');
  xhr.send();
  console.timeEnd('Delayed for');
}

delayMe(3);

In this case, after three seconds, you should see it print out how long you were delayed for.

Anyway, let's give it a go in our SuiteScript.

In LiveOrder.Delayer.js, replace the event listener code with this:

Application.on('before:LiveOrder.ServiceController.get', function ()
{
  console.time('someThing');
    console.log(someThing());
  console.timeEnd('someThing');

  console.time('someOtherThing');
    console.log(someOtherThing());
  console.timeEnd('someOtherThing');

  console.time('someExtraThing');
    console.log(someExtraThing());
  console.timeEnd('someExtraThing');
});

So we've got our three calls but which one is the problematic one? Which one is causing the blockage? Well, we're going to find out after we deploy!

After deploying and refreshing, inspect your SSP application log again and look at the results. You should see something like this:

Great, now we know which of our calls is causing us problems, we can start to try and figure out why!

Final Thoughts

Of course, I can't tell you why your script is causing you problems, it'll likely be specific to your situation. We do, however, have a lot of guidelines and tips for troubleshooting performance in general, which you can see in our performance checklist. We also have some general tips in the help center.

Don't forget that you get quite granular with how you use console timers — once you've narrowed down the call or script file causing you problems, dig down into that and start using timers around specific lines of code.

Happy hunting and don't forget to remove the file from your site after you're done testing!

See LiveOrder.Delayer.js.zip for my version of the file.