Skip to content
This repository has been archived by the owner on Apr 22, 2023. It is now read-only.

windows: emit ETW events with v8 stack trace information #4219

Closed
wants to merge 5 commits into from
Closed

windows: emit ETW events with v8 stack trace information #4219

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
4e3ed92
ETW using v8 code event callback
HenryRawas Sep 5, 2012
bd37891
windows: incorporate review feedback
sblom Oct 31, 2012
816ce08
windows: be a little DRYer
sblom Oct 31, 2012
39820ee
windows: reduce redundant strlen/wcslen calls
sblom Oct 31, 2012
86be7ad
windows: more review feedback
sblom Nov 1, 2012
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
114 changes: 114 additions & 0 deletions src/node_win32_etw_provider-inl.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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(data_descriptor, data) \
EventDataDescCreate(data_descriptor, \
data, \
(wcslen(data) + 1) * sizeof(wchar_t));
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is there a performance impact associated with doing wcslen() all the time? We always know the length of string, right?


#define ETW_WRITE_NET_CONNECTION(descriptors, conn) \
ETW_WRITE_INT32_DATA(descriptors, &conn->fd); \
ETW_WRITE_INT32_DATA(descriptors + 1, &conn->port); \
Expand All @@ -61,6 +75,33 @@ 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) \
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(descriptors + 9, name);


#define ETW_WRITE_EVENT(eventDescriptor, dataDescriptors) \
DWORD status = event_write(node_provider, \
&eventDescriptor, \
Expand Down Expand Up @@ -133,6 +174,78 @@ 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);
}
}


void NODE_V8SYMBOL_ADD(LPCSTR symbol,
int symbol_len,
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

style: use proper alignment

const void* addr1,
int len) {
if (events_enabled > 0) {
wchar_t symbuf[128];
if (symbol == NULL) {
wcscpy(symbuf, L"NULL");
} else {
symbol_len = MultiByteToWideChar(CP_ACP, 0, symbol, symbol_len, symbuf, 128);
if (symbol_len == 0) {
wcscpy(symbuf, L"Invalid");
} else {
if (symbol_len > 127) {
symbol_len = 127;
}
symbuf[symbol_len] = L'\0';
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Always do this. If symbol_len does not include the terminating null, you might end up with an unterminated string.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@piscisaureus, thanks for flagging this--I did find one problem in this neighborhood that I introduced when I got rid of the wcslen call. Namely that symbol_len isn't getting set in the case of "NULL" or "Invalid". Fixed in latest commit. Please re-review.

}
}
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);
ETW_WRITE_EVENT(MethodLoad, descriptors);
}
}


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; }
Expand All @@ -141,5 +254,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_
112 changes: 112 additions & 0 deletions src/node_win32_etw_provider.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 {

Expand All @@ -33,10 +34,108 @@ EventRegisterFunc event_register;
EventUnregisterFunc event_unregister;
EventWriteFunc event_write;
int events_enabled;
static uv_async_t dispatch_etw_events_change_async;

struct v8tags {
const char *prefix;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Style police: 2 spaces, not 4, and const char* instead of const char *

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh, another thing - since this data structure will be read often, do it like this:

struct v8tags {
  char prefix[32 - sizeof(size_t)];
  size_t prelen;
};

Avoids a level of indirection and makes it fit in a single cache line. Presumably prelen doesn't have to be a size_t because it's never going to be very large.

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[] = {
{ "LazyCompile:", sizeof("LazyCompile:") - 1 },
{ "Script:", sizeof("Script:") - 1 },
{ "Function:", sizeof("Function:") - 1 },
{ "RegExp:", sizeof("RegExp:") - 1 },
{ "Eval:", sizeof("Eval:") - 1 }
};

/* 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 < (sizeof(trace_codes) / sizeof(trace_codes[0])); i++) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ARRAY_SIZE(trace_codes)

int 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++;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Indent error.

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);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Needs to line up with arg 1.

} 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,
Expand All @@ -47,8 +146,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);
}
}
}

Expand All @@ -64,6 +169,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,
Expand All @@ -82,6 +193,7 @@ void shutdown_etw() {
}

events_enabled = 0;
V8::SetJitCodeEventHandler(v8::kJitCodeEventDefault, NULL);

if (advapi) {
FreeLibrary(advapi);
Expand Down
8 changes: 8 additions & 0 deletions src/node_win32_etw_provider.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Indent error.

const void* addr1,
int len);

INLINE bool NODE_HTTP_SERVER_REQUEST_ENABLED();
INLINE bool NODE_HTTP_SERVER_RESPONSE_ENABLED();
Expand All @@ -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)
Expand Down
Loading