Add JIT timestamp and thread info to tracelog

diff --git a/src/info/baseinfo.h b/src/info/baseinfo.h
index 3c49ce33faa8df7c92afa0aa755ab336625cddd9..438ba283a4b5d74c1d24d3413662ab7f4a4ed91c 100644 (file)
--- a/src/info/baseinfo.h
+++ b/src/info/baseinfo.h
@@ -23,6 +23,10 @@
 struct InternalID
 {
     size_t id;
+
+    InternalID() = default;
+
+    InternalID(size_t id) : id(id) {}
 };
 
 struct BaseInfo

diff --git a/src/info/functioninfo.h b/src/info/functioninfo.h
index 2ec9a1055d1aae34e45bd896c01181c2ba83c7ce..e2a2b42ed0c6937260c6dffed5348e3be3f34bde 100644 (file)
--- a/src/info/functioninfo.h
+++ b/src/info/functioninfo.h
@@ -43,7 +43,7 @@ struct FunctionInfo : public MappedInfo<FunctionID>
     std::vector<COR_PRF_CODE_INFO> codeInfo;
     std::vector<COR_DEBUG_IL_TO_NATIVE_MAP> ILToNativeMapping;
     ModuleID    moduleId;
-    ModuleID    classId;
+    ClassID     classId;
     mdMethodDef funcToken = mdMethodDefNil;
     ClassInfo*  ownerClass;
     std::vector<ClassInfo*> typeArgs;
@@ -52,7 +52,7 @@ struct FunctionInfo : public MappedInfo<FunctionID>
     String      returnType;
     String      signature;
     bool        isInitialized;
-    bool        isNamePrinted;
+    bool        isInfoPrinted;
 
 private:
     static void ParseElementType(

diff --git a/src/trace/executiontrace.cpp b/src/trace/executiontrace.cpp
index f1acf1e9bed0171398955cdea010aa5e34eb1ae9..fabd3c4a5425fe8f4bedc9d7447d3dfa5768dcce 100644 (file)
--- a/src/trace/executiontrace.cpp
+++ b/src/trace/executiontrace.cpp
@@ -440,56 +440,48 @@ __forceinline void ExecutionTrace::Tailcall(
 }
 
 HRESULT ExecutionTrace::JITStarted(
-    FunctionID functionId) noexcept
+    FunctionID functionId)
 {
-    HRESULT hr = S_OK;
-    try
+    m_functionStorage.lock()->Place(functionId);
+
+    if (m_profiler.GetConfig().LineTraceEnabled)
     {
-        if (m_profiler.GetConfig().LineTraceEnabled)
-        {
-            this->UpdateCallStackPush(*m_pJitFunctionInfo, 0);
-        }
-        else
-        {
-            this->UpdateCallStackPush(*m_pJitFunctionInfo);
-        }
-        m_functionStorage.lock()->Place(functionId);
+        this->UpdateCallStackPush(*m_pJitFunctionInfo, 0);
     }
-    catch (const std::exception &e)
+    else
     {
-        hr = m_profiler.HandleException(e);
+        this->UpdateCallStackPush(*m_pJitFunctionInfo);
     }
 
-    return hr;
+    return S_OK;
 }
 
 HRESULT ExecutionTrace::JITFinished(
     FunctionID functionId,
-    std::function<JITDumpFunction> dumpFunction) noexcept
+    bool succeeded)
 {
-    HRESULT hr = S_OK;
-    try
+    this->UpdateCallStackPop();
+
+    if (!succeeded)
     {
-        auto storage_lock = m_functionStorage.lock();
-        FunctionInfo &funcInfo = storage_lock->Get(functionId);
+        return S_OK;
+    }
 
-        {
-            auto storage_lock = m_profiler.GetCommonTrace().GetClassStorage();
-            hr = funcInfo.Initialize(m_profiler, *storage_lock);
-        }
+    HRESULT hr = S_OK;
 
-        dumpFunction(funcInfo);
-        if (!funcInfo.isNamePrinted)
-        {
-            TRACE().DumpJITFunctionName(funcInfo);
-            funcInfo.isNamePrinted = true;
-        }
+    auto storage_lock = m_functionStorage.lock();
+    FunctionInfo &funcInfo = storage_lock->Get(functionId);
 
-        this->UpdateCallStackPop();
+    {
+        auto storage_lock = m_profiler.GetCommonTrace().GetClassStorage();
+        hr = funcInfo.Initialize(m_profiler, *storage_lock);
     }
-    catch (const std::exception &e)
+
+    if (!funcInfo.isInfoPrinted)
     {
-        hr = m_profiler.HandleException(e);
+        TRACE().DumpJITFunctionInfo(funcInfo);
+        TRACE().DumpJITFunctionName(funcInfo);
+        funcInfo.isInfoPrinted = true;
     }
 
     return hr;
@@ -521,7 +513,23 @@ HRESULT ExecutionTrace::JITCompilationStarted(
     if (m_disabled)
         return S_OK;
 
-    return this->JITStarted(functionId);
+    HRESULT hr = S_OK;
+    try
+    {
+        ThreadInfo *pThreadInfo = m_profiler.GetCommonTrace().GetThreadInfo();
+        TRACE().DumpJITCompilationStarted(
+            pThreadInfo == nullptr ? -1 : pThreadInfo->internalId,
+            m_profiler.GetTickCountFromInit(),
+            functionId
+        );
+        hr = this->JITStarted(functionId);
+    }
+    catch (const std::exception &e)
+    {
+        hr = m_profiler.HandleException(e);
+    }
+
+    return hr;
 }
 
 HRESULT ExecutionTrace::JITCompilationFinished(
@@ -531,13 +539,23 @@ HRESULT ExecutionTrace::JITCompilationFinished(
     if (m_disabled)
         return S_OK;
 
-    return this->JITFinished(
-        functionId,
-        [this, hrStatus](const FunctionInfo &funcInfo)
-        {
-            TRACE().DumpJITCompilationFinished(funcInfo, hrStatus);
-        }
-    );
+    HRESULT hr = S_OK;
+    try
+    {
+        hr = this->JITFinished(functionId);
+        ThreadInfo *pThreadInfo = m_profiler.GetCommonTrace().GetThreadInfo();
+        TRACE().DumpJITCompilationFinished(
+            pThreadInfo == nullptr ? -1 : pThreadInfo->internalId,
+            m_profiler.GetTickCountFromInit(),
+            functionId, hrStatus
+        );
+    }
+    catch (const std::exception &e)
+    {
+        hr = m_profiler.HandleException(e);
+    }
+
+    return hr;
 }
 
 HRESULT ExecutionTrace::JITCachedFunctionSearchStarted(
@@ -548,7 +566,24 @@ HRESULT ExecutionTrace::JITCachedFunctionSearchStarted(
         return S_OK;
 
     *pbUseCachedFunction = TRUE;
-    return this->JITStarted(functionId);
+
+    HRESULT hr = S_OK;
+    try
+    {
+        ThreadInfo *pThreadInfo = m_profiler.GetCommonTrace().GetThreadInfo();
+        TRACE().DumpJITCachedFunctionSearchStarted(
+            pThreadInfo == nullptr ? -1 : pThreadInfo->internalId,
+            m_profiler.GetTickCountFromInit(),
+            functionId
+        );
+        hr = this->JITStarted(functionId);
+    }
+    catch (const std::exception &e)
+    {
+        hr = m_profiler.HandleException(e);
+    }
+
+    return hr;
 }
 
 HRESULT ExecutionTrace::JITCachedFunctionSearchFinished(
@@ -558,18 +593,24 @@ HRESULT ExecutionTrace::JITCachedFunctionSearchFinished(
     if (m_disabled)
         return S_OK;
 
-    if (result != COR_PRF_CACHED_FUNCTION_FOUND)
+    HRESULT hr = S_OK;
+    try
     {
-        return S_OK;
+        hr = this->JITFinished(functionId,
+            result == COR_PRF_CACHED_FUNCTION_FOUND);
+        ThreadInfo *pThreadInfo = m_profiler.GetCommonTrace().GetThreadInfo();
+        TRACE().DumpJITCachedFunctionSearchFinished(
+            pThreadInfo == nullptr ? -1 : pThreadInfo->internalId,
+            m_profiler.GetTickCountFromInit(),
+            functionId
+        );
+    }
+    catch (const std::exception &e)
+    {
+        hr = m_profiler.HandleException(e);
     }
 
-    return this->JITFinished(
-        functionId,
-        [this](const FunctionInfo &funcInfo)
-        {
-            TRACE().DumpJITCachedFunctionSearchFinished(funcInfo);
-        }
-    );
+    return hr;
 }
 
 HRESULT ExecutionTrace::UnmanagedToManagedTransition(

diff --git a/src/trace/executiontrace.h b/src/trace/executiontrace.h
index 4aee248cd9ca0fc9852d7ab643649f34375b47ae..a6151b391143c0a78a3c02c9c2efa6031a482bf7 100644 (file)
--- a/src/trace/executiontrace.h
+++ b/src/trace/executiontrace.h
@@ -100,14 +100,13 @@ private:
     // Events helpers.
     //
 
-    typedef void JITDumpFunction(const FunctionInfo &funcInfo);
-
     HRESULT JITStarted(
-        FunctionID functionId) noexcept;
+        FunctionID functionId);
 
     HRESULT JITFinished(
         FunctionID functionId,
-        std::function<JITDumpFunction> dumpFunction) noexcept;
+        bool succeeded = true);
+
 public:
     //
     // Events.

diff --git a/src/tracelog.cpp b/src/tracelog.cpp
index 631217e21c5436b15eb6bfcb6a80f550328f5d57..070bba177f620ec45487be418a8be952d2ef7b65 100644 (file)
--- a/src/tracelog.cpp
+++ b/src/tracelog.cpp
@@ -223,30 +223,114 @@ public:
         );
     }
 
+    virtual void DumpJITCompilationStarted(
+        InternalID  threadIid,
+        DWORD       ticksFromStart,
+        FunctionID  functionId) override
+    {
+        std::lock_guard<std::mutex> streamLock(m_mStream);
+        if (threadIid.id == -1)
+        {
+            PAL_fprintf(
+                m_pStream, "jit cms ? %d 0x%p\n",
+                ticksFromStart, functionId
+            );
+        }
+        else
+        {
+            PAL_fprintf(
+                m_pStream, "jit cms 0x%08x %d 0x%p\n",
+                threadIid.id, ticksFromStart, functionId
+            );
+        }
+    }
+
     virtual void DumpJITCompilationFinished(
-        const FunctionInfo &info,
+        InternalID  threadIid,
+        DWORD       ticksFromStart,
+        FunctionID  functionId,
         HRESULT     hrStatus) override
     {
         std::lock_guard<std::mutex> streamLock(m_mStream);
-        PAL_fprintf(
-            m_pStream, "fun cmf 0x%p 0x%08x 0x%p 0x%p 0x%08x 0x%08x",
-            info.id, info.internalId.id, info.classId, info.moduleId,
-            info.funcToken, hrStatus
-        );
-        DumpFunctionInfo(info);
-        PAL_fprintf(m_pStream, "\n");
+        if (threadIid.id == -1)
+        {
+            PAL_fprintf(
+                m_pStream, "jit cmf ? %d 0x%p 0x%08x\n",
+                ticksFromStart, functionId, hrStatus
+            );
+        }
+        else
+        {
+            PAL_fprintf(
+                m_pStream, "jit cmf 0x%08x %d 0x%p 0x%08x\n",
+                threadIid.id, ticksFromStart, functionId, hrStatus
+            );
+        }
+    }
+
+    virtual void DumpJITCachedFunctionSearchStarted(
+        InternalID  threadIid,
+        DWORD       ticksFromStart,
+        FunctionID  functionId) override
+    {
+        std::lock_guard<std::mutex> streamLock(m_mStream);
+        if (threadIid.id == -1)
+        {
+            PAL_fprintf(
+                m_pStream, "jit css ? %d 0x%p\n",
+                ticksFromStart, functionId
+            );
+        }
+        else
+        {
+            PAL_fprintf(
+                m_pStream, "jit css 0x%08x %d 0x%p\n",
+                threadIid.id, ticksFromStart, functionId
+            );
+        }
     }
 
     virtual void DumpJITCachedFunctionSearchFinished(
+        InternalID  threadIid,
+        DWORD       ticksFromStart,
+        FunctionID  functionId) override
+    {
+        std::lock_guard<std::mutex> streamLock(m_mStream);
+        if (threadIid.id == -1)
+        {
+            PAL_fprintf(
+                m_pStream, "jit csf ? %d 0x%p\n",
+                ticksFromStart, functionId
+            );
+        }
+        else
+        {
+            PAL_fprintf(
+                m_pStream, "jit csf 0x%08x %d 0x%p\n",
+                threadIid.id, ticksFromStart, functionId
+            );
+        }
+    }
+
+    virtual void DumpJITFunctionInfo(
         const FunctionInfo &info) override
     {
         std::lock_guard<std::mutex> streamLock(m_mStream);
         PAL_fprintf(
-            m_pStream, "fun csf 0x%p 0x%08x 0x%p 0x%p 0x%08x",
-            info.id, info.internalId.id, info.classId, info.moduleId,
+            m_pStream, "fun inf 0x%08x 0x%p 0x%p 0x%p 0x%08x",
+            info.internalId.id, info.id, info.classId, info.moduleId,
             info.funcToken
         );
-        DumpFunctionInfo(info);
+        for (const auto &ci : info.codeInfo)
+        {
+            PAL_fprintf(m_pStream, " 0x%p:0x%x",
+                ci.startAddress, ci.size);
+        }
+        for (const auto &m : info.ILToNativeMapping)
+        {
+            PAL_fprintf(m_pStream, " 0x%x:0x%x:0x%x",
+                m.ilOffset, m.nativeStartOffset, m.nativeEndOffset);
+        }
         PAL_fprintf(m_pStream, "\n");
     }
 
@@ -370,21 +454,6 @@ private:
     PAL_FILE  *m_pStream;
     std::mutex m_mStream;
     bool       m_bIsOwner;
-
-    void DumpFunctionInfo(const FunctionInfo &info)
-    {
-        for (const auto &ci : info.codeInfo)
-        {
-            PAL_fprintf(m_pStream, " 0x%p:0x%x",
-                ci.startAddress, ci.size);
-        }
-
-        for (const auto &m : info.ILToNativeMapping)
-        {
-            PAL_fprintf(m_pStream, " 0x%x:0x%x:0x%x",
-                m.ilOffset, m.nativeStartOffset, m.nativeEndOffset);
-        }
-    }
 };
 
 // static

diff --git a/src/tracelog.h b/src/tracelog.h
index 41705e7785ab1897171722a9971ef93132da930d..4c9a87b2e69e5afbe360dfd59af8ff2715239464 100644 (file)
--- a/src/tracelog.h
+++ b/src/tracelog.h
@@ -107,11 +107,28 @@ public:
     virtual void DumpClassName(
         const ClassInfo &info) = 0;
 
+    virtual void DumpJITCompilationStarted(
+        InternalID  threadIid,
+        DWORD       ticksFromStart,
+        FunctionID  functionId) = 0;
+
     virtual void DumpJITCompilationFinished(
-        const FunctionInfo &info,
+        InternalID  threadIid,
+        DWORD       ticksFromStart,
+        FunctionID  functionId,
         HRESULT     hrStatus) = 0;
 
+    virtual void DumpJITCachedFunctionSearchStarted(
+        InternalID  threadIid,
+        DWORD       ticksFromStart,
+        FunctionID  functionId) = 0;
+
     virtual void DumpJITCachedFunctionSearchFinished(
+        InternalID  threadIid,
+        DWORD       ticksFromStart,
+        FunctionID  functionId) = 0;
+
+    virtual void DumpJITFunctionInfo(
         const FunctionInfo &info) = 0;
 
     virtual void DumpJITFunctionName(