Switch JIT/GC records from 'threadIid' to 'osThreadId' and prevent creation of thread...
authorAleksei Vereshchagin <avereschagin@dev.rtsoft.ru>
Tue, 24 Apr 2018 13:38:51 +0000 (16:38 +0300)
committerAleksei Vereshchagin <avereschagin@dev.rtsoft.ru>
Fri, 27 Apr 2018 15:10:57 +0000 (18:10 +0300)
doc/tracelog-format.md
src/trace/commontrace.cpp
src/trace/executiontrace.cpp
src/tracelog/tracelog.cpp
src/tracelog/tracelog.h

index 5d91e6a907866fbfeeb06170971b244cc8f6c32e..8e4a4225d033e3df5a6487d84d68bf9d1d228cf3 100644 (file)
@@ -308,24 +308,24 @@ Dump function name, return type and signature.
 ### JIT Compilation Started: `jit cms`
 
 ```
-jit cms <threadIid:iid> <timestamp:ms> <functionId:id>
+jit cms <osThreadId:pid> <timestamp:ms> <functionId:id>
 ```
 
 Notifies that the JIT compiler has started to compile a function.
 
-* `threadIid` - the Internal ID of the thread running JIT.
+* `osThreadId` - the PID of the operating system thread running JIT.
 * `timestamp` - the event timestamp in milliseconds from the start of profiling.
 * `functionId` - the ID of the function for which the compilation is starting.
 
 ### JIT Compilation Finished: `jit cmf`
 
 ```
-jit cmf <threadIid:iid> <timestamp:ms> <functionId:id> <status:hr>
+jit cmf <osThreadId:pid> <timestamp:ms> <functionId:id> <status:hr>
 ```
 
 Notifies that the JIT compiler has finished compiling a function.
 
-* `threadIid` - the Internal ID of the thread running JIT.
+* `osThreadId` - the PID of the operating system thread running JIT.
 * `timestamp` - the event timestamp in milliseconds from the start of profiling.
 * `functionId` - the ID of the function that was compiled.
 * `status` - an HRESULT that indicates whether compilation was successful.
@@ -333,26 +333,26 @@ Notifies that the JIT compiler has finished compiling a function.
 ### JIT Cached Function Search Started: `jit css`
 
 ```
-jit css <threadIid:iid> <timestamp:ms> <functionId:id>
+jit css <osThreadId:pid> <timestamp:ms> <functionId:id>
 ```
 
 Notifies that a search has started for a function that was compiled previously
 using the Native Image Generator (NGen).
 
-* `threadIid` - the Internal ID of the thread running JIT.
+* `osThreadId` - the PID of the operating system thread running JIT.
 * `timestamp` - the event timestamp in milliseconds from the start of profiling.
 * `functionId` - the ID of the function for which the search is being performed.
 
 ### JIT Cached Function Search Finished: `jit csf`
 
 ```
-jit csf <threadIid:iid> <timestamp:ms> <functionId:id>
+jit csf <osThreadId:pid> <timestamp:ms> <functionId:id>
 ```
 
 Notifies that a search has finished for a function that was compiled previously
 using the Native Image Generator (NGen).
 
-* `threadIid` - the Internal ID of the thread running JIT.
+* `osThreadId` - the PID of the operating system thread running JIT.
 * `timestamp` - the event timestamp in milliseconds from the start of profiling.
 * `functionId` - the ID of the function for which the search was performed.
 
@@ -363,12 +363,12 @@ using the Native Image Generator (NGen).
 ### Garbage Collection Started: `gch gcs`
 
 ```
-gch gcs <threadIid:iid> <timestamp:ms> <reason:str> <gen_collect:t|f>...
+gch gcs <osThreadId:pid> <timestamp:ms> <reason:str> <gen_collect:t|f>...
 ```
 
 Notifies that garbage collection has started.
 
-* `threadIid` - the Internal ID of the thread running JIT.
+* `osThreadId` - the PID of the operating system thread running GC.
 * `timestamp` - the event timestamp in milliseconds from the start of profiling.
 * `reason` - the reason the garbage collection was induced.
   * `induced` - the garbage collection was induced by a Collect method.
@@ -384,12 +384,12 @@ Notifies that garbage collection has started.
 ### Garbage Collection Finished: `gch gcf`
 
 ```
-gch gcf <threadIid:iid> <timestamp:ms>
+gch gcf <osThreadId:pid> <timestamp:ms>
 ```
 
 Notifies that garbage collection has completed.
 
-* `threadIid` - the Internal ID of the thread running JIT.
+* `osThreadId` - the PID of the operating system thread running GC.
 * `timestamp` - the event timestamp in milliseconds from the start of profiling.
 
 ### GC Heap Allocation Table: `gch alt`
index b330902713076f7487a1fc808655591a4b2a744e..66e4e07c3ea9ffde2d7823a1657ef5605a50da1c 100644 (file)
@@ -1188,14 +1188,9 @@ HRESULT CommonTrace::GarbageCollectionStarted(
     HRESULT hr = S_OK;
     try
     {
-        ThreadInfo *pThreadInfo = m_profiler.GetCommonTrace().GetThreadInfo();
         TRACE().DumpGarbageCollectionStarted(
-            pThreadInfo == nullptr ? InternalID() : pThreadInfo->internalId,
-            m_profiler.GetTickCountFromInit(),
-            cGenerations,
-            generationCollected,
-            reason
-        );
+            GetCurrentThreadId(), m_profiler.GetTickCountFromInit(),
+            cGenerations, generationCollected, reason);
     }
     catch (const std::exception &e)
     {
@@ -1213,11 +1208,8 @@ HRESULT CommonTrace::GarbageCollectionFinished() noexcept
     HRESULT hr = S_OK;
     try
     {
-        ThreadInfo *pThreadInfo = m_profiler.GetCommonTrace().GetThreadInfo();
         TRACE().DumpGarbageCollectionFinished(
-            pThreadInfo == nullptr ? InternalID() : pThreadInfo->internalId,
-            m_profiler.GetTickCountFromInit()
-        );
+            GetCurrentThreadId(), m_profiler.GetTickCountFromInit());
     }
     catch (const std::exception &e)
     {
index 3cd2febd806edb9626e1ec296a9bb02d34e94e6b..85187c5121b164bff3e91d63f2e9c0cced5c8635 100644 (file)
@@ -444,13 +444,19 @@ HRESULT ExecutionTrace::JITStarted(
 {
     m_functionStorage.lock()->Place(functionId);
 
-    if (m_profiler.GetConfig().LineTraceEnabled)
-    {
-        this->UpdateCallStackPush(*m_pJitFunctionInfo, 0);
-    }
-    else
+    // We should not update stack with JIT pseudo-function for not anounced
+    // threads.
+    ThreadInfo *pThreadInfo = m_profiler.GetCommonTrace().GetThreadInfoR();
+    if (pThreadInfo != nullptr)
     {
-        this->UpdateCallStackPush(*m_pJitFunctionInfo);
+        if (m_profiler.GetConfig().LineTraceEnabled)
+        {
+            this->UpdateCallStackPush(*m_pJitFunctionInfo, 0);
+        }
+        else
+        {
+            this->UpdateCallStackPush(*m_pJitFunctionInfo);
+        }
     }
 
     return S_OK;
@@ -460,7 +466,14 @@ HRESULT ExecutionTrace::JITFinished(
     FunctionID functionId,
     bool succeeded)
 {
-    this->UpdateCallStackPop();
+    // We should not update stack with JIT pseudo-function for not anounced
+    // threads.
+    ThreadInfo *pThreadInfo = m_profiler.GetCommonTrace().GetThreadInfoR();
+    if (pThreadInfo != nullptr)
+    {
+        this->UpdateCallStackPop();
+    }
+
 
     if (!succeeded)
     {
@@ -516,12 +529,9 @@ HRESULT ExecutionTrace::JITCompilationStarted(
     HRESULT hr = S_OK;
     try
     {
-        ThreadInfo *pThreadInfo = m_profiler.GetCommonTrace().GetThreadInfo();
         TRACE().DumpJITCompilationStarted(
-            pThreadInfo == nullptr ? InternalID() : pThreadInfo->internalId,
-            m_profiler.GetTickCountFromInit(),
-            functionId
-        );
+            GetCurrentThreadId(), m_profiler.GetTickCountFromInit(),
+            functionId);
         hr = this->JITStarted(functionId);
     }
     catch (const std::exception &e)
@@ -543,12 +553,9 @@ HRESULT ExecutionTrace::JITCompilationFinished(
     try
     {
         hr = this->JITFinished(functionId);
-        ThreadInfo *pThreadInfo = m_profiler.GetCommonTrace().GetThreadInfo();
         TRACE().DumpJITCompilationFinished(
-            pThreadInfo == nullptr ? InternalID() : pThreadInfo->internalId,
-            m_profiler.GetTickCountFromInit(),
-            functionId, hrStatus
-        );
+            GetCurrentThreadId(), m_profiler.GetTickCountFromInit(),
+            functionId, hrStatus);
     }
     catch (const std::exception &e)
     {
@@ -570,12 +577,9 @@ HRESULT ExecutionTrace::JITCachedFunctionSearchStarted(
     HRESULT hr = S_OK;
     try
     {
-        ThreadInfo *pThreadInfo = m_profiler.GetCommonTrace().GetThreadInfo();
         TRACE().DumpJITCachedFunctionSearchStarted(
-            pThreadInfo == nullptr ? InternalID() : pThreadInfo->internalId,
-            m_profiler.GetTickCountFromInit(),
-            functionId
-        );
+            GetCurrentThreadId(), m_profiler.GetTickCountFromInit(),
+            functionId);
         hr = this->JITStarted(functionId);
     }
     catch (const std::exception &e)
@@ -598,12 +602,9 @@ HRESULT ExecutionTrace::JITCachedFunctionSearchFinished(
     {
         hr = this->JITFinished(functionId,
             result == COR_PRF_CACHED_FUNCTION_FOUND);
-        ThreadInfo *pThreadInfo = m_profiler.GetCommonTrace().GetThreadInfo();
         TRACE().DumpJITCachedFunctionSearchFinished(
-            pThreadInfo == nullptr ? InternalID() : pThreadInfo->internalId,
-            m_profiler.GetTickCountFromInit(),
-            functionId
-        );
+            GetCurrentThreadId(), m_profiler.GetTickCountFromInit(),
+            functionId);
     }
     catch (const std::exception &e)
     {
index bb703917f917bc0185beda230f97bff883d003ca..f7373f9c04b4d60018c5bc8b0942a5ee96aef35a 100644 (file)
@@ -271,39 +271,39 @@ public:
     //
 
     virtual void DumpJITCompilationStarted(
-        InternalID  threadIid,
+        DWORD       osThreadId,
         DWORD       timestamp,
         FunctionID  functionId) override
     {
-        m_tracefmt.log("jit cms").id(threadIid).ms(timestamp)
+        m_tracefmt.log("jit cms").pid(osThreadId).ms(timestamp)
             .id(functionId);
     }
 
     virtual void DumpJITCompilationFinished(
-        InternalID  threadIid,
+        DWORD       osThreadId,
         DWORD       timestamp,
         FunctionID  functionId,
         HRESULT     hrStatus) override
     {
-        m_tracefmt.log("jit cmf").id(threadIid).ms(timestamp)
+        m_tracefmt.log("jit cmf").pid(osThreadId).ms(timestamp)
             .id(functionId).hr(hrStatus);
     }
 
     virtual void DumpJITCachedFunctionSearchStarted(
-        InternalID  threadIid,
+        DWORD       osThreadId,
         DWORD       timestamp,
         FunctionID  functionId) override
     {
-        m_tracefmt.log("jit css").id(threadIid).ms(timestamp)
+        m_tracefmt.log("jit css").pid(osThreadId).ms(timestamp)
             .id(functionId);
     }
 
     virtual void DumpJITCachedFunctionSearchFinished(
-        InternalID  threadIid,
+        DWORD       osThreadId,
         DWORD       timestamp,
         FunctionID  functionId) override
     {
-        m_tracefmt.log("jit csf").id(threadIid).ms(timestamp)
+        m_tracefmt.log("jit csf").pid(osThreadId).ms(timestamp)
             .id(functionId);
     }
 
@@ -312,14 +312,14 @@ public:
     //
 
     virtual void DumpGarbageCollectionStarted(
-        InternalID  threadIid,
+        DWORD       osThreadId,
         DWORD       timestamp,
         int         cGenerations,
         BOOL        generationCollected[],
         COR_PRF_GC_REASON     reason) override
     {
         auto log = m_tracefmt.log("gch gcs");
-        log.id(threadIid).ms(timestamp).str(reason);
+        log.pid(osThreadId).ms(timestamp).str(reason);
         log.grps();
         for (int i = 0; i < cGenerations; ++i)
         {
@@ -329,10 +329,10 @@ public:
     }
 
     virtual void DumpGarbageCollectionFinished(
-        InternalID  threadIid,
+        DWORD       osThreadId,
         DWORD       timestamp) override
     {
-        m_tracefmt.log("gch gcf").id(threadIid).ms(timestamp);
+        m_tracefmt.log("gch gcf").pid(osThreadId).ms(timestamp);
     }
 
     virtual void DumpGcHeapAllocTable(
index cad24294462a7894648ae3668d032fc08bd5127d..517390e9b1048a45b51bbeeaa36fbdd6a49785f9 100644 (file)
@@ -157,23 +157,23 @@ public:
     //
 
     virtual void DumpJITCompilationStarted(
-        InternalID  threadIid,
+        DWORD       osThreadId,
         DWORD       timestamp,
         FunctionID  functionId) = 0;
 
     virtual void DumpJITCompilationFinished(
-        InternalID  threadIid,
+        DWORD       osThreadId,
         DWORD       timestamp,
         FunctionID  functionId,
         HRESULT     hrStatus) = 0;
 
     virtual void DumpJITCachedFunctionSearchStarted(
-        InternalID  threadIid,
+        DWORD       osThreadId,
         DWORD       timestamp,
         FunctionID  functionId) = 0;
 
     virtual void DumpJITCachedFunctionSearchFinished(
-        InternalID  threadIid,
+        DWORD       osThreadId,
         DWORD       timestamp,
         FunctionID  functionId) = 0;
 
@@ -182,14 +182,14 @@ public:
     //
 
     virtual void DumpGarbageCollectionStarted(
-        InternalID  threadIid,
+        DWORD       osThreadId,
         DWORD       timestamp,
         int         cGenerations,
         BOOL        generationCollected[],
         COR_PRF_GC_REASON     reason) = 0;
 
     virtual void DumpGarbageCollectionFinished(
-        InternalID  threadIid,
+        DWORD       osThreadId,
         DWORD       timestamp) = 0;
 
     virtual void DumpGcHeapAllocTable(