From ceffee000bddf9ab846abc2120fff36b6e48c34c Mon Sep 17 00:00:00 2001 From: Aleksei Vereshchagin Date: Mon, 9 Apr 2018 22:14:55 +0300 Subject: [PATCH] Refactoring of TraceLog class --- doc/tracelog-format.md | 16 +- src/CMakeLists.txt | 3 +- src/trace/executiontrace.cpp | 8 +- src/tracelog.cpp | 527 ---------------------------------- src/tracelog/tracefmt.h | 403 ++++++++++++++++++++++++++ src/tracelog/tracelog.cpp | 413 ++++++++++++++++++++++++++ src/{ => tracelog}/tracelog.h | 131 +++++---- 7 files changed, 913 insertions(+), 588 deletions(-) delete mode 100644 src/tracelog.cpp create mode 100644 src/tracelog/tracefmt.h create mode 100644 src/tracelog/tracelog.cpp rename src/{ => tracelog}/tracelog.h (82%) diff --git a/doc/tracelog-format.md b/doc/tracelog-format.md index e20b558..5d91e6a 100644 --- a/doc/tracelog-format.md +++ b/doc/tracelog-format.md @@ -16,7 +16,7 @@ This document describes format of the performance data dumped by CoreProfiler. - [Thread records](#thread-records) - [Thread Created: `thr crt`](#thread-created-thr-crt) - [Thread Assigned To OS Thread: `thr aos`](#thread-assigned-to-os-thread-thr-aos) - - [Thread Destroyed: `thr crt`](#thread-destroyed-thr-crt) + - [Thread Destroyed: `thr dst`](#thread-destroyed-thr-dst) - [Thread CPU Usage: `thr cpu`](#thread-cpu-usage-thr-cpu) - [Execution Engine records](#execution-engine-records) - [Module Load Finished: `mod ldf`](#module-load-finished-mod-ldf) @@ -58,12 +58,12 @@ click) used in tables to avoid parser problems. --> | Item | Format | Description | | -------------- | ------------------------------------------------------ | --------------------------------------------------------------------------------- | +| `` | `%s` | Text string | +| `` | `"%s"` | Quoted text string | | `` | `%d` | Decimal number | | `` | `0x%x` | Hexadecimal number | | `` | `0x%08X` | 32-bit hexadecimal number | | `` | `0x%016X` | 64-bit hexadecimal number | -| `` | `%s` | Text string | -| `` | `"%s"` | Quoted text string | | `` | `%Y-%m-%d %H:%M:%S.%03f` | System time in format of year, month, day, hour, minute, seconds and milliseconds | | `` | `` | Time (in milliseconds) | | `` | `` | Time (in microseconds) | @@ -71,14 +71,14 @@ click) used in tables to avoid parser problems. --> | `` | `` | System process identifier | | `` | `∣?` | Instruction pointer, `?` if undefined | | `
` | `` | HRESULT | +| `` | `` | .NET Metadata Token | | `` | `` | Profiling API ID | | `` | `∣?` | Internal CoreProfiler ID, `?` if undefined | -| `` | `` | .NET Metadata Token | | `` | `:` | Item of Code Info table | | `` | `::` | Item of IL mapping table | -| `` | `::` | Item of GC allocation table | +| `` | `::` | Item of GC allocation table | | `` | `[:]` | Call stack frame | -| `` | `::[:]` | Item of memory sample | +| `` | `::[:]` | Item of memory sample | Many records have special attribute named 'Internal ID'. The internal ID can be used as link to such objects as threads, classes, functions, etc. @@ -163,10 +163,10 @@ system thread. * `threadIid` - the Internal ID of the managed thread. * `osThreadId` - the PID of the operating system thread. -### Thread Destroyed: `thr crt` +### Thread Destroyed: `thr dst` ``` -thr crt +thr dst ``` Notifies that a thread has been destroyed. diff --git a/src/CMakeLists.txt b/src/CMakeLists.txt index c92db8f..d36b09e 100644 --- a/src/CMakeLists.txt +++ b/src/CMakeLists.txt @@ -7,6 +7,7 @@ include_directories( storage sync trace + tracelog ) add_library(coreprof @@ -36,7 +37,7 @@ add_library(coreprof trace/cputrace.cpp trace/executiontrace.cpp trace/memorytrace.cpp - tracelog.cpp + tracelog/tracelog.cpp arch/${ARCH_SOURCES_DIR}/asmhelpers.S arch/${ARCH_SOURCES_DIR}/archhelpers.cpp ) diff --git a/src/trace/executiontrace.cpp b/src/trace/executiontrace.cpp index f4e6f8a..3cd2feb 100644 --- a/src/trace/executiontrace.cpp +++ b/src/trace/executiontrace.cpp @@ -108,8 +108,8 @@ void ExecutionTrace::ProcessConfig(ProfilerConfig &config) // Announce names of the special functions. // - TRACE().DumpJITFunctionName(*m_pUnmanagedFunctionInfo); - TRACE().DumpJITFunctionName(*m_pJitFunctionInfo); + TRACE().DumpFunctionName(*m_pUnmanagedFunctionInfo); + TRACE().DumpFunctionName(*m_pJitFunctionInfo); // // Event Mask calculation. @@ -479,8 +479,8 @@ HRESULT ExecutionTrace::JITFinished( if (!funcInfo.isInfoPrinted) { - TRACE().DumpJITFunctionInfo(funcInfo); - TRACE().DumpJITFunctionName(funcInfo); + TRACE().DumpFunctionInfo(funcInfo); + TRACE().DumpFunctionName(funcInfo); funcInfo.isInfoPrinted = true; } diff --git a/src/tracelog.cpp b/src/tracelog.cpp deleted file mode 100644 index ae64a32..0000000 --- a/src/tracelog.cpp +++ /dev/null @@ -1,527 +0,0 @@ -/* - * Copyright (c) 2017 Samsung Electronics Co., Ltd All Rights Reserved - * - * Licensed under the Apache License, Version 2.0 (the License); - * you may not use this file except in compliance with the License. - * You may obtain a copy of the License at - * - * http://www.apache.org/licenses/LICENSE-2.0 - * - * Unless required by applicable law or agreed to in writing, software - * distributed under the License is distributed on an AS IS BASIS, - * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. - * See the License for the specific language governing permissions and - * limitations under the License. - */ - -#include -#include -#include - -#include - -#include - -#include "commonconfigconversions.h" -#include "profilerconfigconversions.h" -#include "tracelog.h" - -class TraceLog final : public ITraceLog -{ -public: - TraceLog(StdOutStream_t) - : m_pStream(PAL_stdout) - , m_bIsOwner(false) - {} - - TraceLog(StdErrStream_t) - : m_pStream(PAL_stderr) - , m_bIsOwner(false) - {} - - TraceLog(FileStream_t, const std::string &filename) - { - m_pStream = PAL_fopen(filename.c_str(), "w"); - if (m_pStream == nullptr) - { - throw std::system_error(errno, std::system_category(), - "can't create TraceLog object"); - } - m_bIsOwner = true; - } - - virtual ~TraceLog() - { - if (m_bIsOwner) - PAL_fclose(m_pStream); - } - - virtual void DumpStartTime( - const SYSTEMTIME &systime) override - { - std::lock_guard streamLock(m_mStream); - PAL_fprintf( - m_pStream, "prf stm %04hu-%02hu-%02hu %02hu:%02hu:%02hu.%03hu\n", - systime.wYear, systime.wMonth, systime.wDay, - systime.wHour, systime.wMinute, systime.wSecond, - systime.wMilliseconds - ); - } - - virtual void DumpProfilerConfig( - const ProfilerConfig &config) override - { - std::lock_guard streamLock(m_mStream); - PAL_fprintf( - m_pStream, "prf cfg CollectionMethod %s\n", - convert(config.CollectionMethod) - ); - PAL_fprintf( - m_pStream, "prf cfg SamplingTimeoutMs %lu\n", - config.SamplingTimeoutMs - ); - PAL_fprintf( - m_pStream, "prf cfg HighGranularityEnabled %s\n", - convert(config.HighGranularityEnabled) - ); - PAL_fprintf( - m_pStream, "prf cfg TracingSuspendedOnStart %s\n", - convert(config.TracingSuspendedOnStart) - ); - PAL_fprintf( - m_pStream, "prf cfg LineTraceEnabled %s\n", - convert(config.LineTraceEnabled) - ); - PAL_fprintf( - m_pStream, "prf cfg CpuTraceProcessEnabled %s\n", - convert(config.CpuTraceProcessEnabled) - ); - PAL_fprintf( - m_pStream, "prf cfg CpuTraceThreadEnabled %s\n", - convert(config.CpuTraceThreadEnabled) - ); - PAL_fprintf( - m_pStream, "prf cfg CpuTraceTimeoutMs %lu\n", - config.CpuTraceTimeoutMs - ); - PAL_fprintf( - m_pStream, "prf cfg ExecutionTraceEnabled %s\n", - convert(config.ExecutionTraceEnabled) - ); - PAL_fprintf( - m_pStream, "prf cfg MemoryTraceEnabled %s\n", - convert(config.MemoryTraceEnabled) - ); - PAL_fprintf( - m_pStream, "prf cfg StackTrackingEnabled %s\n", - convert(config.StackTrackingEnabled) - ); - } - - virtual void DumpProfilerTracingPause( - DWORD ticks) override - { - std::lock_guard streamLock(m_mStream); - PAL_fprintf(m_pStream, "prf tps %d\n", ticks); - } - - virtual void DumpProfilerTracingResume( - DWORD ticks) override - { - std::lock_guard streamLock(m_mStream); - PAL_fprintf(m_pStream, "prf trs %d\n", ticks); - } - - virtual void DumpProcessTimes( - DWORD ticksFromStart, - DWORD64 userTime) override - { - std::lock_guard streamLock(m_mStream); - PAL_fprintf(m_pStream, "prc cpu %d %I64u\n", - ticksFromStart, userTime); - } - - virtual void DumpAppDomainCreationFinished( - AppDomainID appDomainId, - LPCWCH appDomainName, - ProcessID processId, - HRESULT hrStatus) override - { - if (appDomainName == nullptr) - appDomainName = W("UNKNOWN"); - - std::lock_guard streamLock(m_mStream); - PAL_fprintf( - m_pStream, "apd crf 0x%p 0x%p 0x%08x \"%S\"\n", - appDomainId, processId, hrStatus, appDomainName - ); - } - - virtual void DumpAssemblyLoadFinished( - AssemblyID assemblyId, - LPCWCH assemblyName, - AppDomainID appDomainId, - ModuleID moduleId, - HRESULT hrStatus) override - { - if (assemblyName == nullptr) - assemblyName = W("UNKNOWN"); - - std::lock_guard streamLock(m_mStream); - PAL_fprintf( - m_pStream, "asm ldf 0x%p 0x%p 0x%p 0x%08x \"%S\"\n", - assemblyId, appDomainId, moduleId, hrStatus, assemblyName - ); - } - - virtual void DumpModuleLoadFinished( - ModuleID moduleId, - LPCBYTE baseLoadAddress, - LPCWCH moduleName, - AssemblyID assemblyId, - HRESULT hrStatus) override - { - if (moduleName == nullptr) - moduleName = W("UNKNOWN"); - - std::lock_guard streamLock(m_mStream); - PAL_fprintf( - m_pStream, "mod ldf 0x%p 0x%p 0x%p 0x%08x \"%S\"\n", - moduleId, baseLoadAddress, assemblyId, hrStatus, moduleName - ); - } - - virtual void DumpModuleAttachedToAssembly( - ModuleID moduleId, - AssemblyID assemblyId) override - { - std::lock_guard streamLock(m_mStream); - PAL_fprintf( - m_pStream, "mod ata 0x%p 0x%p\n", moduleId, assemblyId - ); - } - - virtual void DumpClassLoadFinished( - const ClassInfo &info, - HRESULT hrStatus) override - { - std::lock_guard streamLock(m_mStream); - PAL_fprintf( - m_pStream, "cls ldf 0x%p 0x%08x 0x%p 0x%08x 0x%08x\n", - info.id, info.internalId.id, info.moduleId, info.classToken, - hrStatus - ); - } - - virtual void DumpClassName( - const ClassInfo &info) override - { - std::lock_guard streamLock(m_mStream); - PAL_fprintf( - m_pStream, "cls nam 0x%08x \"%S\"\n", - info.internalId.id, info.fullName.c_str() - ); - } - - 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( - InternalID threadIid, - DWORD ticksFromStart, - FunctionID functionId, - HRESULT hrStatus) override - { - std::lock_guard streamLock(m_mStream); - 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 inf 0x%08x 0x%p 0x%p 0x%p 0x%08x", - info.internalId.id, info.id, info.classId, info.moduleId, - info.funcToken - ); - 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"); - } - - virtual void DumpJITFunctionName( - const FunctionInfo &info) override - { - std::lock_guard streamLock(m_mStream); - PAL_fprintf( - m_pStream, "fun nam 0x%08x \"%S\" \"%S\" \"%S\"\n", - info.internalId.id, info.fullName.c_str(), - info.returnType.c_str(), info.signature.c_str() - ); - } - - virtual void DumpThreadCreated( - ThreadID threadId, - InternalID threadIid) override - { - std::lock_guard streamLock(m_mStream); - PAL_fprintf(m_pStream, "thr crt 0x%p 0x%08x\n", threadId, threadIid.id); - } - - virtual void DumpThreadDestroyed( - InternalID threadIid) override - { - std::lock_guard streamLock(m_mStream); - PAL_fprintf(m_pStream, "thr dst 0x%08x\n", threadIid.id); - } - - virtual void DumpThreadAssignedToOSThread( - InternalID managedThreadIid, - DWORD osThreadId) override - { - std::lock_guard streamLock(m_mStream); - PAL_fprintf( - m_pStream, "thr aos 0x%08x %d\n", managedThreadIid.id, osThreadId - ); - } - - virtual void DumpThreadTimes( - InternalID threadIid, - DWORD ticksFromStart, - DWORD64 userTime) override - { - std::lock_guard streamLock(m_mStream); - PAL_fprintf(m_pStream, "thr cpu 0x%08x %d %I64u\n", - threadIid.id, ticksFromStart, userTime); - } - - virtual void DumpSample( - InternalID threadIid, - const EventSummary &summary) override - { - std::lock_guard streamLock(m_mStream); - - if (summary.HasStackSample()) - { - PAL_fprintf( - m_pStream, "sam str 0x%08x %d %lu", - threadIid.id, summary.ticks, summary.count - ); - PAL_fprintf(m_pStream, " %d:%d", - summary.matchPrefixSize, summary.stackSize); - if (summary.ipIsChanged) - { - PAL_fprintf(m_pStream, summary.ip != 0 ? ":%p" : ":?", summary.ip); - } - for (const auto &frame : summary.newFrames) - { - PAL_fprintf(m_pStream, frame.ip != 0 ? " 0x%x:%p" : " 0x%x", - frame.pFuncInfo->internalId.id, frame.ip); - } - PAL_fprintf(m_pStream, "\n"); - } - - if (summary.HasAllocSample()) - { - PAL_fprintf( - m_pStream, "sam mem 0x%08x %d", threadIid.id, summary.ticks - ); - for (const auto &classIidIpAllocInfo : summary.allocIpTable) - { - for (const auto &IpAllocInfo : classIidIpAllocInfo.second) - { - PAL_fprintf( - m_pStream, - IpAllocInfo.first != 0 ? - " 0x%x:%Iu:%Iu:%p" : " 0x%x:%Iu:%Iu", - classIidIpAllocInfo.first, - IpAllocInfo.second.allocCount, - IpAllocInfo.second.memSize, - IpAllocInfo.first - ); - } - } - PAL_fprintf(m_pStream, "\n"); - } - } - - virtual void DumpGarbageCollectionStarted( - InternalID threadIid, - DWORD ticksFromStart, - int cGenerations, - BOOL generationCollected[], - COR_PRF_GC_REASON reason) override - { - std::lock_guard streamLock(m_mStream); - if (threadIid.id == -1) - { - PAL_fprintf(m_pStream, "gch gcs ? %d", ticksFromStart); - } - else - { - PAL_fprintf(m_pStream, "gch gcs 0x%08x %d", threadIid.id, - ticksFromStart); - } - switch (reason) - { - case COR_PRF_GC_INDUCED: - PAL_fprintf(m_pStream, " induced"); - break; - default: - PAL_fprintf(m_pStream, " ?"); - break; - } - PAL_fprintf(m_pStream, cGenerations > 0 ? " " : ""); - for (int i = 0; i < cGenerations; ++i) - { - PAL_fprintf(m_pStream, generationCollected[i] ? "t" : "f"); - } - PAL_fprintf(m_pStream, "\n"); - } - - virtual void DumpGarbageCollectionFinished( - InternalID threadIid, - DWORD ticksFromStart) override - { - std::lock_guard streamLock(m_mStream); - if (threadIid.id == -1) - { - PAL_fprintf(m_pStream, "gch gcf ? %d", ticksFromStart); - } - else - { - PAL_fprintf(m_pStream, "gch gcf 0x%08x %d", threadIid.id, - ticksFromStart); - } - PAL_fprintf(m_pStream, "\n"); - } - - virtual void DumpGcHeapAllocTable( - DWORD ticksFromStart, - const AllocTable &allocInfoByTypes) override - { - std::lock_guard streamLock(m_mStream); - - PAL_fprintf(m_pStream, "gch alt %d", ticksFromStart); - for (const auto &classIidAllocInfo : allocInfoByTypes) - { - PAL_fprintf( - m_pStream, - " 0x%x:%Iu:%Iu", - classIidAllocInfo.first, - classIidAllocInfo.second.allocCount, - classIidAllocInfo.second.memSize - ); - } - PAL_fprintf(m_pStream, "\n"); - } - -private: - PAL_FILE *m_pStream; - std::mutex m_mStream; - bool m_bIsOwner; -}; - -// static -ITraceLog *ITraceLog::Create(StdOutStream_t StdOutStream) -{ - return new TraceLog(StdOutStream); -} - -// static -ITraceLog *ITraceLog::Create(StdErrStream_t StdErrStream) -{ - return new TraceLog(StdErrStream); -} - -// static -ITraceLog *ITraceLog::Create( - FileStream_t FileStream, const std::string &filename) -{ - return new TraceLog(FileStream, filename); -} diff --git a/src/tracelog/tracefmt.h b/src/tracelog/tracefmt.h new file mode 100644 index 0000000..21c9c56 --- /dev/null +++ b/src/tracelog/tracefmt.h @@ -0,0 +1,403 @@ +/* + * Copyright (c) 2017 Samsung Electronics Co., Ltd All Rights Reserved + * + * Licensed under the Apache License, Version 2.0 (the License); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an AS IS BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#ifndef _TRACE_FMT_H_ +#define _TRACE_FMT_H_ + +#include +#include +#include +#include +#include +#include +#include + +#include + +#include +#include +#include + +#include "baseinfo.h" +#include "commonconfigconversions.h" +#include "profilerconfigconversions.h" + +#include "eventchannel.h" + +namespace +{ + +template +struct wrap +{ + T value; + + wrap(T value) : value(value) {} + + operator T() const { return value; } +}; + + +struct hexnum32 : wrap { using wrap::wrap; }; +struct hexnum64 : wrap { using wrap::wrap; }; +struct hexnum : wrap { using wrap::wrap; }; + +std::ostream& operator<<(std::ostream& os, hexnum32 value) +{ + char fill = os.fill('0'); + auto flags = os.flags(); + os << std::hex << std::uppercase << std::noshowbase + << "0x" << std::setw(8) << value.value; + os.flags(flags); + os.fill(fill); + return os; +} + +std::ostream& operator<<(std::ostream& os, hexnum64 value) +{ + char fill = os.fill('0'); + auto flags = os.flags(); + os << std::hex << std::uppercase << std::noshowbase + << "0x" << std::setw(16) << value.value; + os.flags(flags); + os.fill(fill); + return os; +} + +std::ostream& operator<<(std::ostream& os, hexnum value) +{ + auto flags = os.flags(); + os << std::hex << std::nouppercase << std::noshowbase + << "0x" << value.value; + os.flags(flags); + return os; +} + +std::ostream& operator<<(std::ostream& os, LPCWCH str) +{ + std::wstring_convert, WCHAR> cvt; + return os << cvt.to_bytes(str); +} + +std::ostream& operator<<(std::ostream& os, std::basic_string str) +{ + return os << str.c_str(); +} + +std::ostream& operator<<(std::ostream& os, InternalID id) +{ + if (id) + { + // FIXME: unchecked overflow possible. + return os << hexnum32(id.id); + } + else + { + return os << '?'; + } +} + +class tracefmt +{ +private: + class record + { + private: + struct deleter + { + void operator()(std::ostream *stream) + { + *stream << std::endl; + } + }; + + public: + record(const char *str, std::ostream *stream, std::mutex &mutex) + : m_lock(mutex) + , m_stream(stream) + { + *m_stream << str; + } + + template + record& str(T&& value) + { + sep(); + *m_stream << std::forward(value); + return *this; + } + + record& str(COR_PRF_GC_REASON reason) + { + switch (reason) + { + case COR_PRF_GC_INDUCED: + return str("induced"); + default: + return str('?'); + } + } + + template + record& qtn(T&& value) + { + sep(); + *m_stream << '"' << std::forward(value) << '"'; + return *this; + } + + template + record& num(T&& value) + { + return str(std::forward(value)); + } + + record& hex(DWORD64 value) + { + sep(); + *m_stream << hexnum(value); + return *this; + } + + record& hex32(DWORD value) + { + sep(); + *m_stream << hexnum32(value); + return *this; + } + + record& hex64(DWORD64 value) + { + sep(); + *m_stream << hexnum64(value); + return *this; + } + + record& systime(const SYSTEMTIME& systime) + { + char fill = m_stream->fill('0'); + sep(); + *m_stream + << std::setw(4) << systime.wYear + << '-' << std::setw(2) << systime.wMonth + << '-' << std::setw(2) << systime.wDay + << ' ' << std::setw(2) << systime.wHour + << ':' << std::setw(2) << systime.wMinute + << ':' << std::setw(2) << systime.wSecond + << '.' << std::setw(3) << systime.wMilliseconds; + m_stream->fill(fill); + return *this; + } + + template + record& config(T&& value) + { + sep(); + *m_stream << convert(std::forward(value)); + return *this; + } + + record& config(unsigned long value) + { + return num(value); + } + + record& ms(DWORD ms) + { + return num(ms); + } + + record& us(DWORD64 us) + { + return num(us); + } + + record& ptr(UINT_PTR p) + { + return hex64(p); + } + + record& ptr(const void *p) + { + return ptr(reinterpret_cast(p)); + } + + record& pid(DWORD pid) + { + return num(pid); + } + + record& ip(UINT_PTR ip) + { + if (ip == 0) + { + sep(); + *m_stream << '?'; + return *this; + } + else + { + return ptr(ip); + } + } + + record& hr(HRESULT hr) + { + return hex32(hr); + } + + record& token(mdToken token) + { + return hex32(token); + } + + record& id(UINT_PTR id) + { + return hex64(id); + } + + record& id(InternalID id) + { + sep(); + *m_stream << id; + return *this; + } + + record& code_info(const COR_PRF_CODE_INFO& ci) + { + return grps(':').hex64(ci.startAddress).hex(ci.size).grpe(); + } + + record& il_map(const COR_DEBUG_IL_TO_NATIVE_MAP& m) + { + grps(':'); + hex(m.ilOffset).hex(m.nativeStartOffset).hex(m.nativeEndOffset); + grpe(); + return *this; + } + + record& alt_item(InternalID classIid, AllocInfo allocInfo) + { + grps(':'); + hex(classIid).num(allocInfo.allocCount).num(allocInfo.memSize); + grpe(); + return *this; + } + + record& frame(Frame f) + { + grps(':'); + hex(f.pFuncInfo->internalId); + if (f.ip != 0) + { + ip(f.ip); + } + grpe(); + return *this; + } + + record& alloc_item( + InternalID classIid, AllocInfo allocInfo, UINT_PTR ip = 0) + { + grps(':'); + hex(classIid).num(allocInfo.allocCount).num(allocInfo.memSize); + if (ip != 0) + { + this->ip(ip); + } + grpe(); + return *this; + } + + record& grps() + { + m_sep = -1; + m_grp_state = grp_state::FIRST_IN_GROUP; + return *this; + } + + record& grps(char sep) + { + m_sep = sep; + m_grp_state = grp_state::FIRST_IN_GROUP; + return *this; + } + + record& grpe() + { + m_sep = -1; + m_grp_state = grp_state::NOT_IN_GROUP; + return *this; + } + + record& sep() + { + switch (m_grp_state) + { + case grp_state::NOT_IN_GROUP: + *m_stream << ' '; + break; + case grp_state::FIRST_IN_GROUP: + m_grp_state = grp_state::IN_GROUP; + *m_stream << ' '; + break; + case grp_state::IN_GROUP: + if (m_sep != -1) + { + *m_stream << static_cast(m_sep); + } + break; + } + return *this; + } + + private: + std::unique_lock m_lock; + std::unique_ptr m_stream; + + enum class grp_state { + NOT_IN_GROUP, + FIRST_IN_GROUP, + IN_GROUP + }; + grp_state m_grp_state = grp_state::NOT_IN_GROUP; + int m_sep = -1; + }; + +public: + explicit tracefmt(std::ostream& stream) + : m_stream(&stream) + {} + + tracefmt() : tracefmt(std::cout) {} + + tracefmt(const tracefmt&) = delete; + + tracefmt &operator=(const tracefmt&) = delete; + + record log(const char *str) + { + return record(str, m_stream, m_mutex); + } + +private: + std::ostream *m_stream; + std::mutex m_mutex; +}; + +} + +#endif // _TRACE_FMT_H_ diff --git a/src/tracelog/tracelog.cpp b/src/tracelog/tracelog.cpp new file mode 100644 index 0000000..bb70391 --- /dev/null +++ b/src/tracelog/tracelog.cpp @@ -0,0 +1,413 @@ +/* + * Copyright (c) 2017 Samsung Electronics Co., Ltd All Rights Reserved + * + * Licensed under the Apache License, Version 2.0 (the License); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an AS IS BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#include +#include +#include + +#include "tracefmt.h" +#include "tracelog.h" + +class TraceLog final : public ITraceLog +{ +public: + TraceLog(StdOutStream_t) + : m_stream(std::cout) + , m_stream_owner(false) + , m_tracefmt(m_stream) + {} + + TraceLog(StdErrStream_t) + : m_stream(std::cerr) + , m_stream_owner(false) + , m_tracefmt(m_stream) + {} + + TraceLog(FileStream_t, const std::string &filename) + : m_stream(*new std::ofstream()) + , m_stream_owner(true) + , m_tracefmt(m_stream) + { + try + { + m_stream.exceptions(m_stream.exceptions() | std::ios::failbit); + static_cast(m_stream).open(filename); + m_stream.exceptions(std::ios::goodbit); + } + catch (...) + { + delete &m_stream; + if (errno) + { + throw std::system_error( + errno, std::system_category(), + "TraceLog::TraceLog(): Can't create trace file" + ); + } + else + { + throw; + } + } + } + + virtual ~TraceLog() + { + if (m_stream_owner) + { + delete &m_stream; + } + } + + // + // Profiler records + // + + virtual void DumpStartTime( + const SYSTEMTIME &systime) override + { + m_tracefmt.log("prf stm").systime(systime); + } + + virtual void DumpProfilerConfig( + const ProfilerConfig &config) override + { + m_tracefmt.log("prf cfg").str("CollectionMethod") + .config(config.CollectionMethod); + m_tracefmt.log("prf cfg").str("SamplingTimeoutMs") + .config(config.SamplingTimeoutMs); + m_tracefmt.log("prf cfg").str("HighGranularityEnabled") + .config(config.HighGranularityEnabled); + m_tracefmt.log("prf cfg").str("TracingSuspendedOnStart") + .config(config.TracingSuspendedOnStart); + m_tracefmt.log("prf cfg").str("LineTraceEnabled") + .config(config.LineTraceEnabled); + m_tracefmt.log("prf cfg").str("CpuTraceProcessEnabled") + .config(config.CpuTraceProcessEnabled); + m_tracefmt.log("prf cfg").str("CpuTraceThreadEnabled") + .config(config.CpuTraceThreadEnabled); + m_tracefmt.log("prf cfg").str("CpuTraceTimeoutMs") + .config(config.CpuTraceTimeoutMs); + m_tracefmt.log("prf cfg").str("ExecutionTraceEnabled") + .config(config.ExecutionTraceEnabled); + m_tracefmt.log("prf cfg").str("MemoryTraceEnabled") + .config(config.MemoryTraceEnabled); + m_tracefmt.log("prf cfg").str("StackTrackingEnabled") + .config(config.StackTrackingEnabled); + m_tracefmt.log("prf cfg").str("GcAllocTableTraceEnabled") + .config(config.GcAllocTableTraceEnabled); + } + + virtual void DumpProfilerTracingPause( + DWORD ticks) override + { + m_tracefmt.log("prf tps").ms(ticks); + } + + virtual void DumpProfilerTracingResume( + DWORD ticks) override + { + m_tracefmt.log("prf trs").ms(ticks); + } + + // + // Process records + // + + virtual void DumpProcessTimes( + DWORD timestamp, + DWORD64 usage) override + { + m_tracefmt.log("prc cpu").ms(timestamp).us(usage); + } + + // + // Thread records + // + + virtual void DumpThreadCreated( + ThreadID threadId, + InternalID threadIid) override + { + m_tracefmt.log("thr crt").id(threadId).id(threadIid); + } + + virtual void DumpThreadAssignedToOSThread( + InternalID managedThreadIid, + DWORD osThreadId) override + { + m_tracefmt.log("thr aos").id(managedThreadIid).pid(osThreadId); + } + + virtual void DumpThreadDestroyed( + InternalID threadIid) override + { + m_tracefmt.log("thr dst").id(threadIid); + } + + virtual void DumpThreadTimes( + InternalID threadIid, + DWORD timestamp, + DWORD64 usage) override + { + m_tracefmt.log("thr cpu").id(threadIid).ms(timestamp).us(usage); + } + + // + // Execution Engine records + // + + virtual void DumpModuleLoadFinished( + ModuleID moduleId, + LPCBYTE baseLoadAddress, + LPCWCH moduleName, + AssemblyID assemblyId, + HRESULT hrStatus) override + { + if (moduleName == nullptr) + moduleName = W("UNKNOWN"); + + m_tracefmt.log("mod ldf") + .id(moduleId).ptr(baseLoadAddress).id(assemblyId).hr(hrStatus) + .qtn(moduleName); + } + + virtual void DumpModuleAttachedToAssembly( + ModuleID moduleId, + AssemblyID assemblyId) override + { + m_tracefmt.log("mod ata").id(moduleId).id(assemblyId); + } + + virtual void DumpAssemblyLoadFinished( + AssemblyID assemblyId, + LPCWCH assemblyName, + AppDomainID appDomainId, + ModuleID moduleId, + HRESULT hrStatus) override + { + if (assemblyName == nullptr) + assemblyName = W("UNKNOWN"); + + m_tracefmt.log("asm ldf") + .id(assemblyId).id(appDomainId).id(moduleId).hr(hrStatus) + .qtn(assemblyName); + } + + virtual void DumpAppDomainCreationFinished( + AppDomainID appDomainId, + LPCWCH appDomainName, + ProcessID processId, + HRESULT hrStatus) override + { + if (appDomainName == nullptr) + appDomainName = W("UNKNOWN"); + + m_tracefmt.log("apd crf") + .id(appDomainId).id(processId).hr(hrStatus).qtn(appDomainName); + } + + // + // Class records + // + + virtual void DumpClassLoadFinished( + const ClassInfo &info, + HRESULT hrStatus) override + { + m_tracefmt.log("cls ldf") + .id(info.id).id(info.internalId).id(info.moduleId) + .token(info.classToken).hr(hrStatus); + } + + virtual void DumpClassName( + const ClassInfo &info) override + { + m_tracefmt.log("cls nam").id(info.internalId).qtn(info.fullName); + } + + // + // Function records + // + + virtual void DumpFunctionInfo( + const FunctionInfo &info) override + { + auto log = m_tracefmt.log("fun inf"); + log.id(info.internalId).id(info.id).id(info.classId).id(info.moduleId) + .token(info.funcToken); + for (const auto& ci : info.codeInfo) + { + log.code_info(ci); + } + for (const auto& m : info.ILToNativeMapping) + { + log.il_map(m); + } + } + + virtual void DumpFunctionName( + const FunctionInfo &info) override + { + m_tracefmt.log("fun nam").id(info.internalId) + .qtn(info.fullName).qtn(info.returnType).qtn(info.signature); + } + + // + // JIT records + // + + virtual void DumpJITCompilationStarted( + InternalID threadIid, + DWORD timestamp, + FunctionID functionId) override + { + m_tracefmt.log("jit cms").id(threadIid).ms(timestamp) + .id(functionId); + } + + virtual void DumpJITCompilationFinished( + InternalID threadIid, + DWORD timestamp, + FunctionID functionId, + HRESULT hrStatus) override + { + m_tracefmt.log("jit cmf").id(threadIid).ms(timestamp) + .id(functionId).hr(hrStatus); + } + + virtual void DumpJITCachedFunctionSearchStarted( + InternalID threadIid, + DWORD timestamp, + FunctionID functionId) override + { + m_tracefmt.log("jit css").id(threadIid).ms(timestamp) + .id(functionId); + } + + virtual void DumpJITCachedFunctionSearchFinished( + InternalID threadIid, + DWORD timestamp, + FunctionID functionId) override + { + m_tracefmt.log("jit csf").id(threadIid).ms(timestamp) + .id(functionId); + } + + // + // GC records + // + + virtual void DumpGarbageCollectionStarted( + InternalID threadIid, + 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.grps(); + for (int i = 0; i < cGenerations; ++i) + { + log.str(generationCollected[i] ? 't' : 'f'); + } + log.grpe(); + } + + virtual void DumpGarbageCollectionFinished( + InternalID threadIid, + DWORD timestamp) override + { + m_tracefmt.log("gch gcf").id(threadIid).ms(timestamp); + } + + virtual void DumpGcHeapAllocTable( + DWORD timestamp, + const AllocTable &allocInfoByTypes) override + { + auto log = m_tracefmt.log("gch alt"); + log.ms(timestamp); + for (const auto &classIidAllocInfo : allocInfoByTypes) + { + log.alt_item(classIidAllocInfo.first, classIidAllocInfo.second); + } + } + + // + // Sample records + // + + virtual void DumpSample( + InternalID threadIid, + const EventSummary &summary) override + { + if (summary.HasStackSample()) + { + auto log = m_tracefmt.log("sam str"); + log.id(threadIid).ms(summary.ticks).num(summary.count); + log.grps(':'); + log.num(summary.matchPrefixSize).num(summary.stackSize); + if (summary.ipIsChanged) + { + log.ip(summary.ip); + } + log.grpe(); + for (const auto &frame : summary.newFrames) + { + log.frame(frame); + } + } + + if (summary.HasAllocSample()) + { + auto log = m_tracefmt.log("sam mem"); + log.id(threadIid).ms(summary.ticks); + for (const auto &classIidIpAllocInfo : summary.allocIpTable) + { + for (const auto &IpAllocInfo : classIidIpAllocInfo.second) + { + log.alloc_item(classIidIpAllocInfo.first, + IpAllocInfo.second, IpAllocInfo.first); + } + } + } + } + +private: + std::ostream& m_stream; + bool m_stream_owner; + tracefmt m_tracefmt; +}; + +// static +ITraceLog *ITraceLog::Create(StdOutStream_t StdOutStream) +{ + return new TraceLog(StdOutStream); +} + +// static +ITraceLog *ITraceLog::Create(StdErrStream_t StdErrStream) +{ + return new TraceLog(StdErrStream); +} + +// static +ITraceLog *ITraceLog::Create( + FileStream_t FileStream, const std::string &filename) +{ + return new TraceLog(FileStream, filename); +} diff --git a/src/tracelog.h b/src/tracelog/tracelog.h similarity index 82% rename from src/tracelog.h rename to src/tracelog/tracelog.h index f83c06c..cad2429 100644 --- a/src/tracelog.h +++ b/src/tracelog/tracelog.h @@ -24,6 +24,7 @@ #include #include "profilerconfig.h" +#include "baseinfo.h" #include "functioninfo.h" #include "classinfo.h" #include "eventchannel.h" @@ -58,7 +59,9 @@ public: static ITraceLog *Create(FileStream_t, const std::string &filename); - // TODO: different methods to dump information. + // + // Profiler records + // virtual void DumpStartTime( const SYSTEMTIME &systime) = 0; @@ -67,27 +70,42 @@ public: const ProfilerConfig &config) = 0; virtual void DumpProfilerTracingPause( - DWORD ticks) = 0; + DWORD timestamp) = 0; virtual void DumpProfilerTracingResume( - DWORD ticks) = 0; + DWORD timestamp) = 0; + + // + // Process records + // virtual void DumpProcessTimes( - DWORD ticksFromStart, - DWORD64 userTime) = 0; + DWORD timestamp, + DWORD64 usage) = 0; - virtual void DumpAppDomainCreationFinished( - AppDomainID appDomainId, - LPCWCH appDomainName, - ProcessID processId, - HRESULT hrStatus) = 0; + // + // Thread records + // - virtual void DumpAssemblyLoadFinished( - AssemblyID assemblyId, - LPCWCH assemblyName, - AppDomainID appDomainId, - ModuleID moduleId, - HRESULT hrStatus) = 0; + virtual void DumpThreadCreated( + ThreadID threadId, + InternalID threadIid) = 0; + + virtual void DumpThreadAssignedToOSThread( + InternalID managedThreadIid, + DWORD osThreadId) = 0; + + virtual void DumpThreadDestroyed( + InternalID threadIid) = 0; + + virtual void DumpThreadTimes( + InternalID threadIid, + DWORD timestamp, + DWORD64 usage) = 0; + + // + // Execution Engine records + // virtual void DumpModuleLoadFinished( ModuleID moduleId, @@ -100,6 +118,23 @@ public: ModuleID moduleId, AssemblyID assemblyId) = 0; + virtual void DumpAssemblyLoadFinished( + AssemblyID assemblyId, + LPCWCH assemblyName, + AppDomainID appDomainId, + ModuleID moduleId, + HRESULT hrStatus) = 0; + + virtual void DumpAppDomainCreationFinished( + AppDomainID appDomainId, + LPCWCH appDomainName, + ProcessID processId, + HRESULT hrStatus) = 0; + + // + // Class records + // + virtual void DumpClassLoadFinished( const ClassInfo &info, HRESULT hrStatus) = 0; @@ -107,67 +142,67 @@ public: virtual void DumpClassName( const ClassInfo &info) = 0; + // + // Function records + // + + virtual void DumpFunctionInfo( + const FunctionInfo &info) = 0; + + virtual void DumpFunctionName( + const FunctionInfo &info) = 0; + + // + // JIT records + // + virtual void DumpJITCompilationStarted( InternalID threadIid, - DWORD ticksFromStart, + DWORD timestamp, FunctionID functionId) = 0; virtual void DumpJITCompilationFinished( InternalID threadIid, - DWORD ticksFromStart, + DWORD timestamp, FunctionID functionId, HRESULT hrStatus) = 0; virtual void DumpJITCachedFunctionSearchStarted( InternalID threadIid, - DWORD ticksFromStart, + DWORD timestamp, FunctionID functionId) = 0; virtual void DumpJITCachedFunctionSearchFinished( InternalID threadIid, - DWORD ticksFromStart, + DWORD timestamp, FunctionID functionId) = 0; - virtual void DumpJITFunctionInfo( - const FunctionInfo &info) = 0; - - virtual void DumpJITFunctionName( - const FunctionInfo &info) = 0; - - virtual void DumpThreadCreated( - ThreadID threadId, - InternalID threadIid) = 0; - - virtual void DumpThreadDestroyed( - InternalID threadIid) = 0; - - virtual void DumpThreadAssignedToOSThread( - InternalID managedThreadIid, - DWORD osThreadId) = 0; - - virtual void DumpThreadTimes( - InternalID threadIid, - DWORD ticksFromStart, - DWORD64 userTime) = 0; - - virtual void DumpSample( - InternalID threadIid, - const EventSummary &summary) = 0; + // + // GC records + // virtual void DumpGarbageCollectionStarted( InternalID threadIid, - DWORD ticksFromStart, + DWORD timestamp, int cGenerations, BOOL generationCollected[], COR_PRF_GC_REASON reason) = 0; virtual void DumpGarbageCollectionFinished( InternalID threadIid, - DWORD ticksFromStart) = 0; + DWORD timestamp) = 0; virtual void DumpGcHeapAllocTable( - DWORD ticksFromStart, + DWORD timestamp, const AllocTable &allocInfoByTypes) = 0; + + // + // Sample records + // + + virtual void DumpSample( + InternalID threadIid, + const EventSummary &summary) = 0; }; #endif // _TRACE_LOG_H_ -- 2.34.1