From 66f64ae072271ef36e9f684a965f1fc410d86ebc Mon Sep 17 00:00:00 2001 From: Scott Blomquist Date: Wed, 5 Sep 2012 12:44:15 -0700 Subject: [PATCH] windows: generate ETW events to track v8 compiled code positions Patch by Henry Rawas and Scott Blomquist. --- src/node_win32_etw_provider-inl.h | 120 ++++++++++++++++++++++++++++++ src/node_win32_etw_provider.cc | 114 ++++++++++++++++++++++++++++ src/node_win32_etw_provider.h | 8 ++ src/res/node_etw_provider.man | 77 +++++++++++++++---- 4 files changed, 306 insertions(+), 13 deletions(-) diff --git a/src/node_win32_etw_provider-inl.h b/src/node_win32_etw_provider-inl.h index 9d3f4e546fe2d2..db59eea5713f00 100644 --- a/src/node_win32_etw_provider-inl.h +++ b/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_ \ No newline at end of file diff --git a/src/node_win32_etw_provider.cc b/src/node_win32_etw_provider.cc index 78f465c466924e..26769b0e5ac708 100644 --- a/src/node_win32_etw_provider.cc +++ b/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); diff --git a/src/node_win32_etw_provider.h b/src/node_win32_etw_provider.h index adfff37e568226..cfc2c8658e6fcd 100644 --- a/src/node_win32_etw_provider.h +++ b/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) diff --git a/src/res/node_etw_provider.man b/src/res/node_etw_provider.man index 2d96a20c31ad0a..efdc26d3dee722 100644 --- a/src/res/node_etw_provider.man +++ b/src/res/node_etw_provider.man @@ -1,15 +1,25 @@ - + + + + + + + + @@ -19,6 +29,9 @@ + + + @@ -52,49 +65,87 @@ + + + + - - - - - - - - + + + +