From: Aleksei Vereshchagin Date: Mon, 2 Apr 2018 19:57:29 +0000 (+0300) Subject: Add JIT timestamp and thread info to tracelog X-Git-Tag: submit/tizen/20180619.075036^2~9 X-Git-Url: http://review.tizen.org/git/?a=commitdiff_plain;h=db08834cb4ca99d222b99f572740ee340c50fffc;p=sdk%2Ftools%2Fcoreprofiler.git Add JIT timestamp and thread info to tracelog --- diff --git a/src/info/baseinfo.h b/src/info/baseinfo.h index 3c49ce3..438ba28 100644 --- 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 2ec9a10..e2a2b42 100644 --- a/src/info/functioninfo.h +++ b/src/info/functioninfo.h @@ -43,7 +43,7 @@ struct FunctionInfo : public MappedInfo std::vector codeInfo; std::vector ILToNativeMapping; ModuleID moduleId; - ModuleID classId; + ClassID classId; mdMethodDef funcToken = mdMethodDefNil; ClassInfo* ownerClass; std::vector typeArgs; @@ -52,7 +52,7 @@ struct FunctionInfo : public MappedInfo 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 f1acf1e..fabd3c4 100644 --- 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 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 4aee248..a6151b3 100644 --- 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 dumpFunction) noexcept; + bool succeeded = true); + public: // // Events. diff --git a/src/tracelog.cpp b/src/tracelog.cpp index 631217e..070bba1 100644 --- 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 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 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 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 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 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 41705e7..4c9a87b 100644 --- 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(