Thursday, September 29, 2011

Using Event Tracing for Windows to track and diagnose node.js applications hosted in IIS/iisnode

In my recent posts I talked a lot about iisnode which allows hosting node.js applications in IIS on Windows. In this post I will describe ways to track and diagnose failures in node.js apps deployed in IIS using Event Tracing for Windows (ETW) just integrated into v0.1.8 of iisnode. ETW is only available on Windows Vista and up and Windows 2008 Server and up.

What it is

Event Tracing for Windows (ETW) is a kernel mode logging feature in Windows with minimal performance overhead. ETW can be turned on or off at any time, even when the application is already running, using a set of tools included in Windows. You can read more about ETW and various ways of using here.

How to use ETW with iisnode

During installation of iisnode for IIS 7.x or IIS Express 7.x you will get a new script file that helps with capturing ETW traces for iisnode and generating viewable reports from them. The script is located next to iisnode.dll – in the IIS 7.x installation it is at %programfiles%\iisnode.

Consider calling ‘iisreset’ first to start capturing ETW traces starting from a clean slate. However, you can also perform the procedure when the IIS worker process, iisnode, and node.exe are already running in the system.

Start by running the etw.bar script from an administrative command prompt:

image

Then run your test scenarios you intend to capture ETW traces for. For example, navigate to the helloworld sample that ships with iisnode:

image

When you are done with your test scenario, go back to the command line running the etw.bat script and stop capturing ETW traces by pressing a key:

image

The script created the *.etl file with captured traces that can be post-processed with ETW tools. It also generated an XML report that contains human readable trace log. Press a key one more time and the XML file should open in your default application associated with the *.xml file extension (most likely your browser):

image

What is being traced

iisnode currently generates following ETW traces at three verbosity levels:

  1. Error
    • iisnode has failed to initialize the application manager
    • iisnode failed to create a new node.js application
    • iisnode failed to initialize a new node.js application
    • iisnode failed to initialize a new node.exe process
  2. Information
    • iisnode has initialized the application manager
    • iisnode initialized a new node.js application
    • iisnode initialized a new node.exe process
    • iisnode received a new http request
    • iisnode failed to process a new http reques
    • iisnode detected termination of node.exe process
  3. Verbose
    • iisnode found an existing node.js application to dispatch the http request to
    • iisnode has flushed standard handles of the node.exe process
    • iisnode dequeued a request for processing from the pending request queue
    • iisnode attempted to dequeue a request for processing from the pending request queue but the queue is empty
    • iisnode request processing failed
    • iisnode request processing succeeded

Under the hood

If you prefer using ETW tools on your own over invoking the included etw.bat file, you will need the iisnode ETW provider id, which is {1040DFC4-61DB-484A-9530-584B2735F7F7}.

Enjoy!

No comments:

Post a Comment

My Photo
My name is Tomasz Janczuk. I am currently working on my own venture - Mobile Chapters (http://mobilechapters.com). Formerly at Microsoft (12 years), focusing on node.js, JavaScript, Windows Azure, and .NET Framework.