windows: generate ETW events to track v8 compiled code positions

Patch by Henry Rawas and Scott Blomquist.

src/node_win32_etw_provider-inl.h

@@ -42,6 +42,20 @@ extern int events_enabled;
 #define ETW_WRITE_INT32_DATA(data_descriptor, data)  \
   EventDataDescCreate(data_descriptor, data, sizeof(int32_t));
 
+#define ETW_WRITE_INT64_DATA(data_descriptor, data)  \
+  EventDataDescCreate(data_descriptor, data, sizeof(int64_t));
+
+#define ETW_WRITE_ADDRESS_DATA(data_descriptor, data)  \
+  EventDataDescCreate(data_descriptor, data, sizeof(intptr_t));
+
+#define ETW_WRITE_INT16_DATA(data_descriptor, data)  \
+  EventDataDescCreate(data_descriptor, data, sizeof(int16_t));
+
+#define ETW_WRITE_WSTRING_DATA_LENGTH(data_descriptor, data, data_len_bytes)  \
+  EventDataDescCreate(data_descriptor,                                        \
+                      data,                                                   \
+                      data_len_bytes);
+
 #define ETW_WRITE_NET_CONNECTION(descriptors, conn)                           \
   ETW_WRITE_INT32_DATA(descriptors, &conn->fd);                               \
   ETW_WRITE_INT32_DATA(descriptors + 1, &conn->port);                         \
@@ -61,6 +75,34 @@ extern int events_enabled;
   ETW_WRITE_INT32_DATA(descriptors, &type);                                   \
   ETW_WRITE_INT32_DATA(descriptors + 1, &flags);
 
+#define ETW_WRITE_V8ADDRESSCHANGE(descriptors, addr1, addr2)                  \
+    ETW_WRITE_ADDRESS_DATA(descriptors, &addr1);                              \
+    ETW_WRITE_ADDRESS_DATA(descriptors + 1, &addr2);
+
+#define ETW_WRITE_JSMETHOD_LOADUNLOAD(descriptors,                            \
+                                      context,                                \
+                                      startAddr,                              \
+                                      size,                                   \
+                                      id,                                     \
+                                      flags,                                  \
+                                      rangeId,                                \
+                                      sourceId,                               \
+                                      line,                                   \
+                                      col,                                    \
+                                      name,                                   \
+                                      name_len_bytes)                         \
+    ETW_WRITE_ADDRESS_DATA(descriptors, &context);                            \
+    ETW_WRITE_ADDRESS_DATA(descriptors + 1, &startAddr);                      \
+    ETW_WRITE_INT64_DATA(descriptors + 2, &size);                             \
+    ETW_WRITE_INT32_DATA(descriptors + 3, &id);                               \
+    ETW_WRITE_INT16_DATA(descriptors + 4, &flags);                            \
+    ETW_WRITE_INT16_DATA(descriptors + 5, &rangeId);                          \
+    ETW_WRITE_INT64_DATA(descriptors + 6, &sourceId);                         \
+    ETW_WRITE_INT32_DATA(descriptors + 7, &line);                             \
+    ETW_WRITE_INT32_DATA(descriptors + 8, &col);                              \
+    ETW_WRITE_WSTRING_DATA_LENGTH(descriptors + 9, name, name_len_bytes);
+
+
 #define ETW_WRITE_EVENT(eventDescriptor, dataDescriptors)                     \
   DWORD status = event_write(node_provider,                                   \
                              &eventDescriptor,                                \
@@ -133,6 +175,83 @@ void NODE_GC_DONE(GCType type, GCCallbackFlags flags) {
 }
 
 
+void NODE_V8SYMBOL_REMOVE(const void* addr1, const void* addr2) {
+  if (events_enabled > 0) {
+    EVENT_DATA_DESCRIPTOR descriptors[2];
+    ETW_WRITE_V8ADDRESSCHANGE(descriptors, addr1, addr2);
+    ETW_WRITE_EVENT(NODE_V8SYMBOL_REMOVE_EVENT, descriptors);
+  }
+}
+
+
+void NODE_V8SYMBOL_MOVE(const void* addr1, const void* addr2) {
+  if (events_enabled > 0) {
+    EVENT_DATA_DESCRIPTOR descriptors[2];
+    ETW_WRITE_V8ADDRESSCHANGE(descriptors, addr1, addr2);
+    ETW_WRITE_EVENT(NODE_V8SYMBOL_MOVE_EVENT, descriptors);
+  }
+}
+
+
+void NODE_V8SYMBOL_RESET() {
+  if (events_enabled > 0) {
+    int val = 0;
+    EVENT_DATA_DESCRIPTOR descriptors[1];
+    ETW_WRITE_INT32_DATA(descriptors, &val);
+    ETW_WRITE_EVENT(NODE_V8SYMBOL_RESET_EVENT, descriptors);
+  }
+}
+
+#define SETSYMBUF(s)  \
+  wcscpy(symbuf, s);  \
+  symbol_len = ARRAY_SIZE(s) - 1;
+
+void NODE_V8SYMBOL_ADD(LPCSTR symbol,
+                       int symbol_len,
+                       const void* addr1,
+                       int len) {
+  if (events_enabled > 0) {
+    wchar_t symbuf[128];
+    if (symbol == NULL) {
+      SETSYMBUF(L"NULL");
+    } else {
+      symbol_len = MultiByteToWideChar(CP_ACP, 0, symbol, symbol_len, symbuf, 128);
+      if (symbol_len == 0) {
+        SETSYMBUF(L"Invalid");
+      } else {
+        if (symbol_len > 127) {
+          symbol_len = 127;
+        }
+        symbuf[symbol_len] = L'\0';
+      }
+    }
+    void* context = NULL;
+    INT64 size = (INT64)len;
+    INT32 id = (INT32)addr1;
+    INT16 flags = 0;
+    INT16 rangeid = 1;
+    INT32 col = 1;
+    INT32 line = 1;
+    INT64 sourceid = 0;
+    EVENT_DATA_DESCRIPTOR descriptors[10];
+    ETW_WRITE_JSMETHOD_LOADUNLOAD(descriptors,
+                                  context,
+                                  addr1,
+                                  size,
+                                  id,
+                                  flags,
+                                  rangeid,
+                                  sourceid,
+                                  line,
+                                  col,
+                                  symbuf,
+                                  symbol_len * sizeof(symbuf[0]));
+    ETW_WRITE_EVENT(MethodLoad, descriptors);
+  }
+}
+#undef SETSYMBUF
+
+
 bool NODE_HTTP_SERVER_REQUEST_ENABLED() { return events_enabled > 0; }
 bool NODE_HTTP_SERVER_RESPONSE_ENABLED() { return events_enabled > 0; }
 bool NODE_HTTP_CLIENT_REQUEST_ENABLED() { return events_enabled > 0; }
@@ -141,5 +260,6 @@ bool NODE_NET_SERVER_CONNECTION_ENABLED() { return events_enabled > 0; }
 bool NODE_NET_STREAM_END_ENABLED() { return events_enabled > 0; }
 bool NODE_NET_SOCKET_READ_ENABLED() { return events_enabled > 0; }
 bool NODE_NET_SOCKET_WRITE_ENABLED() { return events_enabled > 0; }
+bool NODE_V8SYMBOL_ENABLED() { return events_enabled > 0; }
 }
 #endif  // SRC_ETW_INL_H_

src/node_win32_etw_provider.cc

@@ -22,6 +22,7 @@
 #include "node_dtrace.h"
 #include "node_win32_etw_provider.h"
 #include "node_etw_provider.h"
+#include "node_win32_etw_provider-inl.h"
 
 namespace node {
 
@@ -33,10 +34,110 @@ EventRegisterFunc event_register;
 EventUnregisterFunc event_unregister;
 EventWriteFunc event_write;
 int events_enabled;
+static uv_async_t dispatch_etw_events_change_async;
+
+struct v8tags {
+  char prefix[32 - sizeof(size_t)];
+  size_t prelen;
+};
+
+// The v8 CODE_ADDED event name has a prefix indicating the type of event.
+// Many of these are internal to v8.
+// The trace_codes array specifies which types are written.
+struct v8tags trace_codes[] = {
+#define MAKE_V8TAG(s) { s, sizeof(s) - 1 }
+  MAKE_V8TAG("LazyCompile:"),
+  MAKE_V8TAG("Script:"),
+  MAKE_V8TAG("Function:"),
+  MAKE_V8TAG("RegExp:"),
+  MAKE_V8TAG("Eval:")
+#undef MAKE_V8TAG
+};
+
+/* Below are some code prefixes which are not being written.
+ *    "Builtin:"
+ *    "Stub:"
+ *    "CallIC:"
+ *    "LoadIC:"
+ *    "KeyedLoadIC:"
+ *    "StoreIC:"
+ *    "KeyedStoreIC:"
+ *    "CallPreMonomorphic:"
+ *    "CallInitialize:"
+ *    "CallMiss:"
+ *    "CallMegamorphic:"
+ */
+
+// v8 sometimes puts a '*' or '~' in front of the name.
+#define V8_MARKER1 '*'
+#define V8_MARKER2 '~'
+
+
+// If prefix is not in filtered list return -1,
+// else return length of prefix and marker.
+int FilterCodeEvents(const char* name, size_t len) {
+  for (int i = 0; i < ARRAY_SIZE(trace_codes); i++) {
+    size_t prelen = trace_codes[i].prelen;
+    if (prelen < len) {
+      if (strncmp(name, trace_codes[i].prefix, prelen) == 0) {
+        if (name[prelen] == V8_MARKER1 || name[prelen] == V8_MARKER2)
+          prelen++;
+        return prelen;
+      }
+    }
+  }
+  return -1;
+}
+
+
+// callback from V8 module passes symbol and address info for stack walk
+void CodeAddressNotification(const JitCodeEvent* jevent) {
+  int pre_offset = 0;
+  if (NODE_V8SYMBOL_ENABLED()) {
+    switch (jevent->type) {
+    case JitCodeEvent::CODE_ADDED:
+      pre_offset = FilterCodeEvents(jevent->name.str, jevent->name.len);
+      if (pre_offset >= 0) {
+        // skip over prefix and marker
+        NODE_V8SYMBOL_ADD(jevent->name.str + pre_offset,
+                          jevent->name.len - pre_offset,
+                          jevent->code_start,
+                          jevent->code_len);
+      }
+      break;
+    case JitCodeEvent::CODE_REMOVED:
+      NODE_V8SYMBOL_REMOVE(jevent->code_start, 0);
+      break;
+    case JitCodeEvent::CODE_MOVED:
+      NODE_V8SYMBOL_MOVE(jevent->code_start, jevent->new_code_start);
+      break;
+    default:
+      break;
+    }
+  }
+}
+
+
+// Call v8 to enable or disable code event callbacks.
+// Must be on default thread to do this.
+// Note: It is possible to call v8 from ETW thread, but then
+//       event callbacks are received in the same thread. Attempts
+//       to write ETW events in this thread will fail.
+void etw_events_change_async(uv_async_t* handle, int status) {
+  if (events_enabled > 0) {
+    NODE_V8SYMBOL_RESET();
+    V8::SetJitCodeEventHandler(v8::kJitCodeEventEnumExisting,
+                               CodeAddressNotification);
+  } else {
+    V8::SetJitCodeEventHandler(v8::kJitCodeEventDefault, NULL);
+  }
+}
+
 
 // This callback is called by ETW when consumers of our provider
 // are enabled or disabled.
 // The callback is dispatched on ETW thread.
+// Before calling into V8 to enable code events, switch to default thread.
 void NTAPI etw_events_enable_callback(
   LPCGUID SourceId,
   ULONG IsEnabled,
@@ -47,8 +148,14 @@ void NTAPI etw_events_enable_callback(
   PVOID CallbackContext) {
   if (IsEnabled) {
     events_enabled++;
+    if (events_enabled == 1) {
+      uv_async_send(&dispatch_etw_events_change_async);
+    }
   } else {
     events_enabled--;
+    if (events_enabled == 0) {
+      uv_async_send(&dispatch_etw_events_change_async);
+    }
   }
 }
 
@@ -64,6 +171,12 @@ void init_etw() {
       GetProcAddress(advapi, "EventUnregister");
     event_write = (EventWriteFunc)GetProcAddress(advapi, "EventWrite");
 
+    // create async object used to invoke main thread from callback
+    uv_async_init(uv_default_loop(),
+                &dispatch_etw_events_change_async,
+                etw_events_change_async);
+    uv_unref((uv_handle_t*) &dispatch_etw_events_change_async);
+
     if (event_register) {    
       DWORD status = event_register(&NODE_ETW_PROVIDER,
                                     etw_events_enable_callback,
@@ -82,6 +195,7 @@ void shutdown_etw() {
   }
 
   events_enabled = 0;
+  V8::SetJitCodeEventHandler(v8::kJitCodeEventDefault, NULL);
 
   if (advapi) {
     FreeLibrary(advapi);

src/node_win32_etw_provider.h

@@ -66,6 +66,13 @@ INLINE void NODE_NET_SERVER_CONNECTION(node_dtrace_connection_t* conn);
 INLINE void NODE_NET_STREAM_END(node_dtrace_connection_t* conn);
 INLINE void NODE_GC_START(GCType type, GCCallbackFlags flags);
 INLINE void NODE_GC_DONE(GCType type, GCCallbackFlags flags);
+INLINE void NODE_V8SYMBOL_REMOVE(const void* addr1, const void* addr2);
+INLINE void NODE_V8SYMBOL_MOVE(const void* addr1, const void* addr2);
+INLINE void NODE_V8SYMBOL_RESET();
+INLINE void NODE_V8SYMBOL_ADD(LPCSTR symbol,
+                              int symbol_len,
+                              const void* addr1,
+                              int len);
 
 INLINE bool NODE_HTTP_SERVER_REQUEST_ENABLED();
 INLINE bool NODE_HTTP_SERVER_RESPONSE_ENABLED();
@@ -75,6 +82,7 @@ INLINE bool NODE_NET_SERVER_CONNECTION_ENABLED();
 INLINE bool NODE_NET_STREAM_END_ENABLED();
 INLINE bool NODE_NET_SOCKET_READ_ENABLED();
 INLINE bool NODE_NET_SOCKET_WRITE_ENABLED();
+INLINE bool NODE_V8SYMBOL_ENABLED();
 
 #define NODE_NET_SOCKET_READ(arg0, arg1)
 #define NODE_NET_SOCKET_WRITE(arg0, arg1)

src/res/node_etw_provider.man

@@ -10,6 +10,16 @@
                 resourceFileName="node.exe"
                 messageFileName="node.exe">
 
+                <tasks>
+                  <task name="MethodRuntime" value="1"
+                      symbol="JSCRIPT_METHOD_RUNTIME_TASK">
+                    <opcodes>
+                      <opcode name="MethodLoad" value="10"
+                          symbol="JSCRIPT_METHOD_METHODLOAD_OPCODE"/>
+                    </opcodes>
+                  </task>
+                </tasks>
+
                 <opcodes>
                     <opcode name="NODE_HTTP_SERVER_REQUEST" value="10"/>
                     <opcode name="NODE_HTTP_SERVER_RESPONSE" value="11"/>
@@ -19,6 +29,9 @@
                     <opcode name="NODE_NET_STREAM_END" value="15"/>
                     <opcode name="NODE_GC_START" value="16"/>
                     <opcode name="NODE_GC_DONE" value="17"/>
+                    <opcode name="NODE_V8SYMBOL_REMOVE" value="21"/>
+                    <opcode name="NODE_V8SYMBOL_MOVE" value="22"/>
+                    <opcode name="NODE_V8SYMBOL_RESET" value="23"/>
                 </opcodes>
 
                 <templates>
@@ -52,6 +65,24 @@
                         <data name="gctype" inType="win:UInt32" />
                         <data name="gccallbackflags" inType="win:UInt32" />
                     </template>
+
+                    <template tid="V8AddressChange">
+                        <data name="addr1" inType="win:Pointer" outType="win:HexInt64"/>
+                        <data name="addr2" inType="win:Pointer" outType="win:HexInt64"/>
+                    </template>
+
+                    <template tid="MethodLoadUnload">
+                        <data name="ScriptContextID" inType="win:Pointer" outType="win:HexInt64"/>
+                        <data name="MethodStartAddress" inType="win:Pointer" outType="win:HexInt64" />
+                        <data name="MethodSize" inType="win:UInt64" />
+                        <data name="MethodID" inType="win:UInt32" />
+                        <data name="MethodFlags" inType="win:UInt16" />
+                        <data name="MethodAddressRangeID" inType="win:UInt16" />
+                        <data name="SourceID" inType="win:UInt64" />
+                        <data name="Line" inType="win:UInt32" outType="xs:unsignedInt" />
+                        <data name="Column" inType="win:UInt32" outType="xs:unsignedInt" />
+                        <data name="MethodName" inType="win:UnicodeString" outType="xs:string" />
+                    </template>
                 </templates>
 
                 <events>
@@ -95,6 +126,26 @@
                         template="node_gc"
                         symbol="NODE_GC_DONE_EVENT"
                         level="win:Informational"/>
+                    <event value="9"
+                        level="win:Informational"
+                        opcode="MethodLoad"
+                        symbol="MethodLoad"
+                        task="MethodRuntime"
+                        template="MethodLoadUnload"/>
+                    <event value="21"
+                        opcode="NODE_V8SYMBOL_REMOVE"
+                        template="V8AddressChange"
+                        symbol="NODE_V8SYMBOL_REMOVE_EVENT"
+                        level="win:Informational" />
+                    <event value="22"
+                        opcode="NODE_V8SYMBOL_MOVE"
+                        template="V8AddressChange"
+                        symbol="NODE_V8SYMBOL_MOVE_EVENT"
+                        level="win:Informational" />
+                    <event value="23"
+                        opcode="NODE_V8SYMBOL_RESET"
+                        symbol="NODE_V8SYMBOL_RESET_EVENT"
+                        level="win:Informational" />
                 </events>
             </provider>
         </events>