Use nodejs-dashboard event loop delay

[00:00] On my screen you can see JMeter. I've set it up to hit the root in-point of the node application server that we have running, instead of manually doing it from the console. The benefit of this is that I can simulate multiple users with JMeter.

[00:16] Let's say we ramp it up to 20 users, and we're going to ramp those users up over a three second period. Each user is going to hit the in-point 10 times. That's going to generate much more traffic than I can using just my upper O and inner key.

[00:34] I've moved that off the screen so you can see the node JS dashboard. Whenever I execute the JMeter task, you can see the incoming requests in the CPU pane. There's a little bit of CPU activity and a little bit of memory allocation but not much else.

[00:50] Let's see if we can change our code up a little bit and impact the event loop. I'm going to add the file system or FS module. I'm also going to generate a random number between 1 and 1,000. I'm going to change my search term to generate that number of lorem words. Basically, lorem is some text.

[01:13] I'll create an array out of each of those words. For each word in that array I'm going to do a synchronous file write. This is not the most efficient way to write this code. What it's going to do is, it's going to create a lot of activity, generate a lot of traffic, and then do a synchronous file write one file at a time.

[01:41] I've returned to the node JS dashboard, and I'm going to kick off my JMeter test. Now you can see that as it's doing those file system writes, it's really, really driving up that event loop delay, because writing to the disk is a very slow and expensive operation. Since I did it synchronously, that's impacting our event loop.

[02:01] Now we've got a scenario where we have a performance issue with our Node JS server. We're able to see that in our development mode using our Node JS dashboard. What can we do from here to try and identify the source of that problem? Let's take a look at that next.

[02:16] I'm going to create a function and I'll call it Clock. It's going to accept one parameter called Start. The first thing we'll do is check to see if that parameter exists. If it doesn't, we're going to return process, start, HR time. We're going to use this as our timing mechanism to time how long our functions take.

[02:41] I'm using the process.HR time to do that. You may be tempted to create just a standard JavaScript date, or use one of the other time-based functions within Node JS, but the reason you want to use HR time is because it's not affected by drifts in the system clock.

[03:01] If you just create a standard date object, it's got the precision that you need. But in the event that that clock drifts or gets adjusted to match the current time based on the time servers, which is going to happen, it's going to skew your results because your results will account for that drift in the clock.

[03:19] If the clock goes backwards, you're going to end up with negative timing results that makes it really hard to troubleshoot. Process.HR time simply records the amount of time, or simply tracks the amount of time that the process has been running independent of any system time that's available.

[03:39] Our function here accepts a parameter of start. If it doesn't have that parameter, it's going to return the HR time object, which is in microseconds. If it does exist, then it's going to get the difference between the start time and the current time of whenever you call that clock function.

[03:59] I'll instrument that down here in our router get endpoint. We'll define start as our start time as the time indicated by the clock. Then at the end of our function when everything is complete, we'll call our clock function again, this time passing in the time we got back when the function started.

[04:19] Now we can write out to the error screen or the error pane the duration that our function call took. Let's see what that looks like as we operate it. Return to the Node JS dashboard. Whenever I launch the JMeter test you can see that each time that function gets called, it's recording the duration.

[04:41] Our code that we've got here is pretty simple and we know what the source of the event loop delay is. But if we needed to dig a step further we can further instrument our function. Let me show you what that looks like real quick.

[04:55] Just before I do the file system write, I'm going to create another timer object. I'll call this one FS Start. We'll get a new time from the clock. After the write is completed, I'll get the duration. In the console error message I can append that out, returning once again to the Node JS dashboard whenever I kick off the JMeter test.

[05:22] I now get the link the time that the total router get call, or router get function took, as well as the length of time that the file system write operation took. We can see in the log output here that that file system write is the majority of the time that our function call took.

[05:41] For troubleshooting purposes, that would be the area we would want to focus on.