Diagnosing Slow node builds on Win2016

In a move a from a Windows 2012 R2 build server to a Windows 2016 build server, the nodejs build step nearly doubled in it’s execution time. This seemed odd, since everything else was pretty much the same on the new server. So, what could the difference be?

Fortunately, a coworker point me towards the Windows Performance Recorder from Microsoft’s Assessment and Deployment Kit (Windows ADK). This worked really well in troubleshooting the issue, and I just wanted to drop in some screen grabs to show it’s visualizations.

The build was on-premise, so I did have access to install the kit** and control the execution of the Windows Performance Recorder to coincide with the execution of the problematic step. This would have been much more difficult on a hosted build server.

Getting the visualization comes by way of a two-step process.

• First Windows Performance Recorder is used to track analysis information from all over your system while the issue is occurring. You can track different profiles, or record more detailed information in particular areas through manual configuration.
  
• Once the problem has been recorded, the analysis information can then be pulled up in Windows Performance Analyzer. Which has a pretty nice interface.

First, here’s a screenshot of Windows Performance Analyzer from the “dotnet publish” (ie. npm init/build) step on the older Windows 2012 R2 server. In the screenshot, the step started by running node.exe and performing the init command. Which would copy over the npm packages from the local npm-cache. This would take about 60 seconds to complete.

However, when performing the same build/same step on the new Windows Server 2016 instance, node.exe wasn’t the dominant process during npm’s init phase. Instead another process was dominant (greyed out in the screenshot), which ran for nearly the same length of time as node.exe and seemed to mirror the process. Because the other process was competing for CPU time with node.exe, the node process took nearly 200 seconds to complete (up from 60 seconds).

So, what was the other process?

MsMpEng.exe, aka. Windows Defender, the classic anti-virus software. On the Windows Server 2016 image I was using, Windows Defender was pre-installed and doing it’s job.

I didn’t take a screenshot of it, but using the Disk IO dashboard I was able to drill into what files MsMpEng.exe was reading and something struck me as odd. It almost looked as if Windows Defender was virus checking the file before it was read before the copy, and read again at the destination after the copy. I’m not sure if that’s the case, but it did seem odd.

For the resolution, I added some Path Exclusion rules to the realtime file scanning capability of Windows Defender. These were specific paths used by the build system and we know those files should be coming from trusted sources. I still left on realtime process scanning and also ensured the scheduled scans were setup, which would look through all the files.

The final result of adding the excluded paths reduced the overall time for the npm init section down to 80s (down from 200s, but also up from 60s on the old, not bad); and MsMpEng.exe was still reporting that is was performing realtime virus scans on the process itself.

A quick sidenote: The offline installer is kind of odd. To do the offline installer, you run the online installer and direct it to download it’s files/resources to the same directory where the online installer’s adksetup.exe is at. The next time you run adksetup.exe, it will detect the the files have already been downloaded and present a different set of options when it runs.