From: Aleksei Vereshchagin Date: Tue, 10 Apr 2018 21:25:53 +0000 (+0300) Subject: Add description of TraceLog text format X-Git-Tag: submit/tizen/20180619.075036^2~6 X-Git-Url: http://review.tizen.org/git/?a=commitdiff_plain;h=8eb399211c4e2787b01f268abb80c40508a6e252;p=sdk%2Ftools%2Fcoreprofiler.git Add description of TraceLog text format --- diff --git a/doc/tracelog-format.md b/doc/tracelog-format.md new file mode 100644 index 0000000..e20b558 --- /dev/null +++ b/doc/tracelog-format.md @@ -0,0 +1,466 @@ +# Format description of trace data file + +This document describes format of the performance data dumped by CoreProfiler. + +## Table of Contents + + +- [Table of Contents](#table-of-contents) +- [Format rules](#format-rules) +- [Profiler records](#profiler-records) + - [Profiler Start Time: `prf stm`](#profiler-start-time-prf-stm) + - [Profiler Configuration: `prf cfg`](#profiler-configuration-prf-cfg) + - [Profiler Pause/Resume: `prf tps`/`prf tps`](#profiler-pauseresume-prf-tpsprf-tps) +- [Process records](#process-records) + - [Process CPU Usage: `prc cpu`](#process-cpu-usage-prc-cpu) +- [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 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) + - [Module Attached To Assembly: `mod ata`](#module-attached-to-assembly-mod-ata) + - [Assembly Load Finished: `asm ldf`](#assembly-load-finished-asm-ldf) + - [Application Domain Creation Finished: `apd crf`](#application-domain-creation-finished-apd-crf) +- [Class records](#class-records) + - [Class Load Finished: `cls ldf`](#class-load-finished-cls-ldf) + - [Class Name: `cls nam`](#class-name-cls-nam) +- [Function records](#function-records) + - [Function info: `fun inf`](#function-info-fun-inf) + - [Function name: `fun nam`](#function-name-fun-nam) +- [JIT records](#jit-records) + - [JIT Compilation Started: `jit cms`](#jit-compilation-started-jit-cms) + - [JIT Compilation Finished: `jit cmf`](#jit-compilation-finished-jit-cmf) + - [JIT Cached Function Search Started: `jit css`](#jit-cached-function-search-started-jit-css) + - [JIT Cached Function Search Finished: `jit csf`](#jit-cached-function-search-finished-jit-csf) +- [GC records](#gc-records) + - [Garbage Collection Started: `gch gcs`](#garbage-collection-started-gch-gcs) + - [Garbage Collection Finished: `gch gcf`](#garbage-collection-finished-gch-gcf) + - [GC Heap Allocation Table: `gch alt`](#gc-heap-allocation-table-gch-alt) +- [Sample records](#sample-records) + - [Stack Trace Sample: `sam str`](#stack-trace-sample-sam-str) + - [Memory Sample: `sam mem`](#memory-sample-sam-mem) + + + +## Format rules + +Each dump record is one text line prefixed with ` `, +where `` is the record type and `` is the record sub-type. +All other data on the line depends on the pair of type and sub-type. + +Different item types can be described by the dump format. This table enumerates +this types, its format and description. + + + +| Item | Format | Description | +| -------------- | ------------------------------------------------------ | --------------------------------------------------------------------------------- | +| `` | `%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) | +| `` | `` | Memory pointer | +| `` | `` | System process identifier | +| `` | `∣?` | Instruction pointer, `?` if undefined | +| `
` | `` | HRESULT | +| `` | `` | 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 | +| `` | `[:]` | Call stack frame | +| `` | `::[:]` | 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. +All objects of one type have unique Internal ID within data log. Current +implementation uses incremental counters for Internal ID started from zero. +This distinguishes Internal ID from CoreCLR ID, whose values can be reused +after end of object lifetime, and, in fact, represented by memory pointers. + +## Profiler records + +### Profiler Start Time: `prf stm` + +``` +prf stm +``` + +Local time of the profiling session start-up. + +### Profiler Configuration: `prf cfg` + +``` +prf cfg +``` + +Used to dump profiler configuration. First string is the configuration parameter +name. Second string is the configuration parameter value. `` format is used +for numbers. `T|F` is used for Boolean values. + +### Profiler Pause/Resume: `prf tps`/`prf tps` + +``` +prf tps +prf trs +``` + +Dumped to trace log when profiling is paused (`tps`) or resumed (`trs`). +Followed by the event timestamp in milliseconds from the start of profiling. + +## Process records + +### Process CPU Usage: `prc cpu` + +``` +prc cpu +``` + +Used to dump process CPU usage. + +* `timestamp` - the event timestamp in milliseconds from the start of profiling. +* `usage` - the CPU usage time in microseconds from last timestamp. + +For the first record `CpuTraceTimeoutMs` value from the configuration should +be used as measurement interval duration. In the pause mode CPU usage is still +counted and will be dumped after resume event relatively to the last timestamp +before pause. + +Process CPU usage in general is total CPU usage of process threads +(so for parallel case it can be greater than measurement interval duration). + +## Thread records + +### Thread Created: `thr crt` + +``` +thr crt +``` + +Notifies that a thread has been created. + +* `threadId` - the ID of the thread that has been created. +* `threadIid` - the Internal ID of the thread that has been created. + +### Thread Assigned To OS Thread: `thr aos` + +``` +thr aos +``` + +Notifies that a managed thread is being implemented using a particular operating +system thread. + +* `threadIid` - the Internal ID of the managed thread. +* `osThreadId` - the PID of the operating system thread. + +### Thread Destroyed: `thr crt` + +``` +thr crt +``` + +Notifies that a thread has been destroyed. + +* `threadIid` - the Internal ID of the thread that has been destroyed. + +### Thread CPU Usage: `thr cpu` + +``` +thr cpu +``` + +Used to dump CPU usage of managed thread. + +* `threadIid` - the thread Internal ID. +* `timestamp` - the event timestamp in milliseconds from the start of profiling. +* `usage` - the CPU usage time in microseconds from last timestamp. + +For the first record `CpuTraceTimeoutMs` value from the configuration should +be used as measurement interval duration. In the pause mode CPU usage is still +counted and will be dumped after resume event relatively to the last timestamp +before pause. + +## Execution Engine records + +### Module Load Finished: `mod ldf` + +``` +mod ldf +``` + +Notifies that a module has finished loading. + +* `moduleId` - the ID of the module that has finished loading. +* `baseLoadAddress` - the base address at which the module is loaded. +* `assemblyId` - the ID of the module's parent assembly. +* `status` - an HRESULT that indicates whether the module was loaded + successfully. +* `moduleName` - the file name of the module. + +### Module Attached To Assembly: `mod ata` + +``` +mod ata +``` + +Notifies that a module is being attached to its parent assembly. + +* `moduleId` - the ID of the module that is being attached. +* `assemblyId` - the ID of the parent assembly to which the module is attached. + +### Assembly Load Finished: `asm ldf` + +``` +asm ldf +``` + +Notifies that an assembly has finished loading. + +* `assemblyId` - the ID of the assembly that was loaded. +* `appDomainId` - the ID of the application domain that contains the assembly. +* `moduleId` - the ID of the assembly's manifest module. +* `status` - an HRESULT that indicates whether the assembly finished loading + successfully. +* `assemblyName` - the assembly's name. + +### Application Domain Creation Finished: `apd crf` + +``` +apd crf +``` + +Notifies that an application domain has been created. + +* `appDomainId` - the ID of the application domain which has been created. +* `processId` - the ID of the process that contains the application domain. +* `status` - an HRESULT that indicates whether creation of the application + domain completed successfully. +* `appDomainName` - the full or partial application domain name. + +## Class records + +### Class Load Finished: `cls ldf` + +``` +cls ldf +``` + +Notifies that a class has finished loading. + +* `classId` - the ID of the class that was loaded. +* `classIid` - the Internal ID of the class that was loaded. +* `moduleId` - the ID of the parent module of the class. +* `classToken` - the metadata token for the class. +* `status` - an HRESULT that indicates whether the class loaded successfully. + +### Class Name: `cls nam` + +``` +cls nam +``` + +Dump class name. + +## Function records + +### Function info: `fun inf` + +``` +fun inf ... ... +``` + +Describes function information. + +* `internalId` - the Internal ID of the function. +* `functionId` - the ID of the function. +* `classId` - the ID of the parent class of the function. +* `moduleId` - the ID of the module in which the function's parent class + is defined. +* `funcToken` - the metadata token for the function. +* `code_info` - zero or more contiguous block of native code stored in memory. + * `start_addr` - the starting address of the contiguous block of code. + * `size` - the size of the block. +* `il_map` - zero or more MSIL to native code map items. + * `ilOffset` - the offset of the MSIL code. + * `nativeStart` - the offset of the start of the native code. + * `nativeEnd` - the offset of the end of the native code. + +### Function name: `fun nam` + +``` +fun nam +``` + +Dump function name, return type and signature. + +## JIT records + +### JIT Compilation Started: `jit cms` + +``` +jit cms +``` + +Notifies that the JIT compiler has started to compile a function. + +* `threadIid` - the Internal ID of the 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 +``` + +Notifies that the JIT compiler has finished compiling a function. + +* `threadIid` - the Internal ID of the 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. + +### JIT Cached Function Search Started: `jit css` + +``` +jit css +``` + +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. +* `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 +``` + +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. +* `timestamp` - the event timestamp in milliseconds from the start of profiling. +* `functionId` - the ID of the function for which the search was performed. + + + +## GC records + +### Garbage Collection Started: `gch gcs` + +``` +gch gcs ... +``` + +Notifies that garbage collection has started. + +* `threadIid` - the Internal ID of the thread running JIT. +* `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. + * `?` - the reason is unspecified. +* `gen_collect` - an array of Boolean values, which are true (`t`) + if the generation that corresponds to the array index is being collected + by this garbage collection; otherwise, false (`f`). + * `[0]` - generation 0; + * `[1]` - generation 1; + * `[2]` - generation 2; + * `[3]` - large-object heap. + +### Garbage Collection Finished: `gch gcf` + +``` +gch gcf +``` + +Notifies that garbage collection has completed. + +* `threadIid` - the Internal ID of the thread running JIT. +* `timestamp` - the event timestamp in milliseconds from the start of profiling. + +### GC Heap Allocation Table: `gch alt` + +``` +gch alt ... +``` + +Used to dump the GC allocation table, that describes how many objects of +different classes remaining in the heap after a garbage collection has completed +and how many memory is used by them. + +* `timestamp` - the event timestamp in milliseconds from the start of profiling. +* `alt_item` - zero of more allocation table items. + * `classIid` - the Internal ID of the some class, which instances remaining + in the heap. + * `allocCount` - the number of instances of the class remaining in the heap. + * `memSize` - memory volume (in bytes) used by instances of the class + remaining in the heap. + + + +## Sample records + +### Stack Trace Sample: `sam str` + +``` +sam str :[:] ... +``` + +This record describes stack changes occured from the last known stack state +(it is considered, that empty stack precedes the first stack trace sample +record). + +* `threadIid` - the Internal ID of the thread that owns stack. +* `timestamp` - the event timestamp in milliseconds from the start of profiling. +* `count` - the number of sampling ticks (with rate, corresponding to the + `PROF_SAMPLING_TIMEOUT`) that has been generated before sample was dumped. + For the `PROF_HIGH_GRAN=1` mode this is generally `1`. + For the `Instrumentaion` mode this is `0`. +* `matchPrefixSize` - the number of stack frames (from the bottom of the stack) + that was not changed. +* `stackSize` - the number of stack frames in the previous stack state. +* `ip` - if 'call point' of last matched frame was changed, new instruction + pointer will be dumped (`?` for undefined). 'Call point' is an instruction + pointer which from the next stack frame was called. For the top frame this is + current instruction pointer. +* `frame` - zero of more new frames added to stack. + * `functionIid:iid` - the Internal ID of the called function. + * `ip` - 'call point' of the frame. Undefined values is not printed. + +`ip` is printed only for `PROF_LINE_TRACE=1` mode. + +### Memory Sample: `sam mem` + +``` +sam mem ... +``` + +This record describes memory allocations occured from the previos memory sample +(or from start of programm for the first sample record). + +* `threadIid` - the Internal ID of the thread that owns stack. +* `timestamp` - the event timestamp in milliseconds from the start of profiling. +* `alloc_item`- zero or more allocation items. + * `classIid` - the Internal ID of the some class, which instances has been + allocated. + * `allocCount` - the number of instances of the class, + that has been allocated. + * `memSize` - memory volume (in bytes) used by instances of the class, that + has been allocated. + * `ip` - the instruction pointer of corresponding allocation operations. + +`ip` is printed only for `PROF_LINE_TRACE=1` mode.