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

Expose OSThreadId and TimeStamp on EventWrittenEventArgs #19002

Merged
merged 13 commits into from
Aug 1, 2018
Merged
Show file tree
Hide file tree
Changes from 1 commit
Commits
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
Prev Previous commit
Next Next commit
Plumb EventPipeSession information into managed code and populate Eve…
…ntWrittenEventArgs.TimeStamp.
  • Loading branch information
brianrob committed Jul 18, 2018
commit 5425b73e2ca285d16cafd0d7be43f6fb133e1ad3
Original file line number Diff line number Diff line change
Expand Up @@ -2043,14 +2043,14 @@ private unsafe void WriteToAllListeners(int eventId, Guid* activityID, Guid* chi
}

// helper for writing to all EventListeners attached the current eventSource.
internal unsafe void WriteToAllListeners(int eventId, uint* osThreadId, Int64* timeStamp, Guid* activityID, Guid* childActivityID, params object[] args)
internal unsafe void WriteToAllListeners(int eventId, uint* osThreadId, DateTime* timeStamp, Guid* activityID, Guid* childActivityID, params object[] args)
{
EventWrittenEventArgs eventCallbackArgs = new EventWrittenEventArgs(this);
eventCallbackArgs.EventId = eventId;
if (osThreadId != null)
eventCallbackArgs.OSThreadId = (int)*osThreadId;
if (timeStamp != null)
eventCallbackArgs.TimeStamp = new DateTime(*timeStamp, DateTimeKind.Local);
eventCallbackArgs.TimeStamp = *timeStamp;
if (activityID != null)
eventCallbackArgs.ActivityId = *activityID;
if (childActivityID != null)
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -16,7 +16,7 @@ internal sealed partial class RuntimeEventSource : EventSource
/// <param name="eventID">The eventID corresponding to the event as defined in the auto-generated portion of the RuntimeEventSource class.</param>
/// <param name="payload">A span pointing to the data payload for the event.</param>
[NonEvent]
internal unsafe void ProcessEvent(uint eventID, uint osThreadID, Int64 timeStamp, Guid activityId, Guid childActivityId, ReadOnlySpan<Byte> payload)
internal unsafe void ProcessEvent(uint eventID, uint osThreadID, DateTime timeStamp, Guid activityId, Guid childActivityId, ReadOnlySpan<Byte> payload)
{
// Make sure the eventID is valid.
if (eventID >= m_eventData.Length)
Expand All @@ -29,7 +29,7 @@ internal unsafe void ProcessEvent(uint eventID, uint osThreadID, Int64 timeStamp
WriteToAllListeners(
eventId: (int)eventID,
osThreadId: &osThreadID,
timeStamp: null,
timeStamp: &timeStamp,
activityID: &activityId,
childActivityID: &childActivityId,
args: decodedPayloadFields);
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,27 @@ internal struct EventPipeEventInstanceData
internal uint PayloadLength;
}

[StructLayout(LayoutKind.Sequential)]
internal struct EventPipeSessionInfo
{
[StructLayout(LayoutKind.Sequential)]
internal struct SystemTime
Copy link

@vancem vancem Jul 18, 2018

Choose a reason for hiding this comment

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

PLease don't use SystemTime. It is inconvinient and unnecessary.
Note that you might not want to even use QueryPerfCounter stufff either. DateTime.UtcNow now uses the Window GetSystemTimePreciseAsFileTime function (or Linux equivalent), so you can probably just use DateTime everywhere (FileTime and DateTime are almost the same (they are both 100ns granularity, and only differ in an offset (See DateTIme.FromFileTimeUtc). This gets rid of a bunch of ugly unit conversions. Just use DateTime everywhere for timestamps, and use the same PAL call we use for DateTime.UtcNow, and all this gets very simple.

{
internal ushort Year;
internal ushort Month;
internal ushort DayOfWeek;
internal ushort Day;
internal ushort Hour;
internal ushort Minute;
internal ushort Second;
internal ushort Milliseconds;
}

internal SystemTime StartTime;
internal Int64 StartTimeStamp;
internal Int64 TimeStampFrequency;
}

[StructLayout(LayoutKind.Sequential)]
internal struct EventPipeProviderConfiguration
{
Expand Down Expand Up @@ -197,6 +218,13 @@ internal static class EventPipeInternal
[DllImport(JitHelpers.QCall, CharSet = CharSet.Unicode)]
internal static extern unsafe void WriteEventData(IntPtr eventHandle, uint eventID, EventProvider.EventData* pEventData, uint dataCount, Guid* activityId, Guid* relatedActivityId);


//
// These PInvokes are used as part of the EventPipeEventDispatcher.
//
[DllImport(JitHelpers.QCall, CharSet = CharSet.Unicode)]
internal static extern unsafe bool GetSessionInfo(UInt64 sessionID, EventPipeSessionInfo* pSessionInfo);

[DllImport(JitHelpers.QCall, CharSet = CharSet.Unicode)]
internal static extern unsafe bool GetNextEvent(EventPipeEventInstanceData* pInstance);
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -27,6 +27,10 @@ internal EventListenerSubscription(EventKeywords matchAnyKeywords, EventLevel le
private IntPtr m_RuntimeProviderID;

private UInt64 m_sessionID = 0;
private DateTime m_syncTimeUtc;
private Int64 m_syncTimeQPC;
private Int64 m_timeQPCFrequency;

private bool m_stopDispatchTask;
private Task m_dispatchTask = null;
private object m_dispatchControlLock = new object();
Expand Down Expand Up @@ -90,7 +94,7 @@ private void CommitDispatchConfiguration()
return;
}

// Start collecting events.
// Determine the keywords and level that should be used based on the set of enabled EventListeners.
EventKeywords aggregatedKeywords = EventKeywords.None;
EventLevel highestLevel = EventLevel.LogAlways;

Expand All @@ -100,12 +104,37 @@ private void CommitDispatchConfiguration()
highestLevel = (subscription.Level > highestLevel) ? subscription.Level : highestLevel;
}

// Enable the EventPipe session.
EventPipeProviderConfiguration[] providerConfiguration = new EventPipeProviderConfiguration[]
{
new EventPipeProviderConfiguration(RuntimeEventSource.EventSourceName, (ulong) aggregatedKeywords, (uint) highestLevel)
};

m_sessionID = EventPipeInternal.Enable(null, 1024, 1, providerConfiguration, 1);
Debug.Assert(m_sessionID != 0);

// Get the session information that is required to properly dispatch events.
EventPipeSessionInfo sessionInfo;
unsafe
{
if (!EventPipeInternal.GetSessionInfo(m_sessionID, &sessionInfo))
{
Debug.Assert(false, "GetSessionInfo returned false.");
}
}

m_syncTimeUtc = new DateTime(
year: sessionInfo.StartTime.Year,
month: sessionInfo.StartTime.Month,
day: sessionInfo.StartTime.Day,
hour: sessionInfo.StartTime.Hour,
minute: sessionInfo.StartTime.Minute,
second: sessionInfo.StartTime.Second,
millisecond: sessionInfo.StartTime.Milliseconds,
kind: DateTimeKind.Utc);

m_syncTimeQPC = sessionInfo.StartTimeStamp;
m_timeQPCFrequency = sessionInfo.TimeStampFrequency;

// Start the dispatch task.
StartDispatchTask();
Expand Down Expand Up @@ -149,7 +178,8 @@ private unsafe void DispatchEventsToEventListeners()
{
// Dispatch the event.
ReadOnlySpan<Byte> payload = new ReadOnlySpan<byte>((void*)instanceData.Payload, (int)instanceData.PayloadLength);
RuntimeEventSource.Log.ProcessEvent(instanceData.EventID, instanceData.ThreadID, instanceData.TimeStamp, instanceData.ActivityId, instanceData.ChildActivityId, payload);
DateTime dateTimeStamp = TimeStampToDateTime(instanceData.TimeStamp);
RuntimeEventSource.Log.ProcessEvent(instanceData.EventID, instanceData.ThreadID, dateTimeStamp, instanceData.ActivityId, instanceData.ChildActivityId, payload);
}
}

Expand All @@ -160,6 +190,23 @@ private unsafe void DispatchEventsToEventListeners()
}
}
}

private DateTime TimeStampToDateTime(Int64 timeStamp)
{
if (timeStamp == Int64.MaxValue)
{
return DateTime.MaxValue;
}

Debug.Assert((m_syncTimeUtc.Ticks != 0) && (m_syncTimeQPC != 0) && (m_timeQPCFrequency != 0));
Int64 inTicks = (Int64)((timeStamp - m_syncTimeQPC) * 10000000.0 / m_timeQPCFrequency) + m_syncTimeUtc.Ticks;
if((inTicks < 0)|| (DateTime.MaxTicks < inTicks))
{
inTicks = DateTime.MaxTicks;
}

return new DateTime(inTicks, DateTimeKind.Utc);
}
}
#endif // FEATURE_PERFTRACING
}
1 change: 1 addition & 0 deletions src/vm/ecalllist.h
Original file line number Diff line number Diff line change
Expand Up @@ -1178,6 +1178,7 @@ FCFuncEnd()
FCFuncStart(gEventPipeInternalFuncs)
QCFuncElement("Enable", EventPipeInternal::Enable)
QCFuncElement("Disable", EventPipeInternal::Disable)
QCFuncElement("GetSessionInfo", EventPipeInternal::GetSessionInfo)
QCFuncElement("CreateProvider", EventPipeInternal::CreateProvider)
QCFuncElement("DefineEvent", EventPipeInternal::DefineEvent)
QCFuncElement("DeleteProvider", EventPipeInternal::DeleteProvider)
Expand Down
39 changes: 37 additions & 2 deletions src/vm/eventpipe.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -370,7 +370,7 @@ EventPipeSessionID EventPipe::Enable(LPCWSTR strOutputPath, EventPipeSession *pS
return (EventPipeSessionID)s_pSession;
}

void EventPipe::Disable(EventPipeSessionID sessionID)
void EventPipe::Disable(EventPipeSessionID id)
{
CONTRACTL
{
Expand All @@ -382,7 +382,7 @@ void EventPipe::Disable(EventPipeSessionID sessionID)

// Only perform the disable operation if the session ID
// matches the current active session.
if(sessionID != (EventPipeSessionID)s_pSession)
if(id != (EventPipeSessionID)s_pSession)
{
return;
}
Expand Down Expand Up @@ -473,6 +473,18 @@ void EventPipe::Disable(EventPipeSessionID sessionID)
}
}

EventPipeSession* EventPipe::GetSession(EventPipeSessionID id)
{
LIMITED_METHOD_CONTRACT;

EventPipeSession *pSession = NULL;
if((EventPipeSessionID)s_pSession == id)
{
pSession = s_pSession;
}
return pSession;
}

bool EventPipe::Enabled()
{
LIMITED_METHOD_CONTRACT;
Expand Down Expand Up @@ -1064,6 +1076,29 @@ void QCALLTYPE EventPipeInternal::Disable(UINT64 sessionID)
END_QCALL;
}

bool QCALLTYPE EventPipeInternal::GetSessionInfo(UINT64 sessionID, EventPipeSessionInfo *pSessionInfo)
{
QCALL_CONTRACT;

bool retVal = false;
BEGIN_QCALL;

if(pSessionInfo != NULL)
{
EventPipeSession *pSession = EventPipe::GetSession(sessionID);
if(pSession != NULL)
{
pSessionInfo->StartTime = pSession->GetStartTime();
pSessionInfo->StartTimeStamp.QuadPart = pSession->GetStartTimeStamp().QuadPart;
QueryPerformanceFrequency(&pSessionInfo->TimeStampFrequency);
retVal = true;
}
}

END_QCALL;
return retVal;
}

INT_PTR QCALLTYPE EventPipeInternal::CreateProvider(
__in_z LPCWSTR providerName,
EventPipeCallback pCallbackFunc)
Expand Down
15 changes: 14 additions & 1 deletion src/vm/eventpipe.h
Original file line number Diff line number Diff line change
Expand Up @@ -245,7 +245,10 @@ class EventPipe
int numProviders);

// Disable tracing via the event pipe.
static void Disable(EventPipeSessionID sessionID);
static void Disable(EventPipeSessionID id);

// Get the session for the specified session ID.
static EventPipeSession* GetSession(EventPipeSessionID id);

// Specifies whether or not the event pipe is enabled.
static bool Enabled();
Expand Down Expand Up @@ -395,6 +398,14 @@ class EventPipeInternal
unsigned int PayloadLength;
};

struct EventPipeSessionInfo
{
public:
SYSTEMTIME StartTime;
LARGE_INTEGER StartTimeStamp;
LARGE_INTEGER TimeStampFrequency;
};

public:

static UINT64 QCALLTYPE Enable(
Expand All @@ -406,6 +417,8 @@ class EventPipeInternal

static void QCALLTYPE Disable(UINT64 sessionID);

static bool QCALLTYPE GetSessionInfo(UINT64 sessionID, EventPipeSessionInfo *pSessionInfo);

static INT_PTR QCALLTYPE CreateProvider(
__in_z LPCWSTR providerName,
EventPipeCallback pCallbackFunc);
Expand Down
2 changes: 2 additions & 0 deletions src/vm/eventpipesession.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -29,6 +29,8 @@ EventPipeSession::EventPipeSession(
m_pProviderList = new EventPipeSessionProviderList(
pProviders,
numProviders);
GetSystemTime(&m_sessionStartTime);
QueryPerformanceCounter(&m_sessionStartTimeStamp);
}

EventPipeSession::~EventPipeSession()
Expand Down
20 changes: 20 additions & 0 deletions src/vm/eventpipesession.h
Original file line number Diff line number Diff line change
Expand Up @@ -34,6 +34,12 @@ class EventPipeSession
// This determines behavior within the system (e.g. policies around which events to drop, etc.)
EventPipeSessionType m_sessionType;

// Start date and time.
SYSTEMTIME m_sessionStartTime;

// Start timestamp.
LARGE_INTEGER m_sessionStartTimeStamp;

public:

// TODO: This needs to be exposed via EventPipe::CreateSession() and EventPipe::DeleteSession() to avoid memory ownership issues.
Expand Down Expand Up @@ -76,6 +82,20 @@ class EventPipeSession
m_rundownEnabled = value;
}

// Get the session start time.
SYSTEMTIME GetStartTime() const
{
LIMITED_METHOD_CONTRACT;
return m_sessionStartTime;
}

// Get the session start timestamp.
LARGE_INTEGER GetStartTimeStamp() const
{
LIMITED_METHOD_CONTRACT;
return m_sessionStartTimeStamp;
}

// Enable all events.
// This is used for testing and is controlled via COMPLUS_EnableEventPipe.
void EnableAllEvents();
Expand Down