Skip to content

Commit

Permalink
Add timetrace2txt tool for simple ftime-trace workflow. (#4335)
Browse files Browse the repository at this point in the history
  • Loading branch information
JohanEngelen authored Mar 3, 2023
1 parent 981c58e commit e85a543
Show file tree
Hide file tree
Showing 10 changed files with 314 additions and 2 deletions.
2 changes: 1 addition & 1 deletion .github/actions/3-build-cross/action.yml
Original file line number Diff line number Diff line change
Expand Up @@ -145,4 +145,4 @@ runs:
${{ inputs.cmake_flags }}
${{ inputs.with_pgo == 'true' && '-DDFLAGS_LDC=-fprofile-use=../pgo-ldc/merged.profdata' || '' }}
${{ env.CROSS_CMAKE_FLAGS }}
build_targets: ldc2 ldmd2 ldc-build-runtime ldc-profdata ldc-prune-cache
build_targets: ldc2 ldmd2 ldc-build-runtime ldc-profdata ldc-prune-cache timetrace2txt
2 changes: 1 addition & 1 deletion .github/actions/5-install/action.yml
Original file line number Diff line number Diff line change
Expand Up @@ -21,7 +21,7 @@ runs:
cd ..
else
mkdir -p install/bin
cp build-cross/bin/{ldc2,ldmd2,ldc-build-runtime,ldc-profdata,ldc-prune-cache} install/bin/
cp build-cross/bin/{ldc2,ldmd2,ldc-build-runtime,ldc-profdata,ldc-prune-cache,timetrace2txt} install/bin/
cp -R build-cross-libs/lib install/
cp build-cross/lib/{libldc_rt.*,libLTO-ldc.dylib,LLVMgold-ldc.so} install/lib/ || true
mkdir install/etc
Expand Down
1 change: 1 addition & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@
- LLVM for prebuilt packages bumped to v15.0.7. (#4311)
- Linker-level dead code elimination is enabled by default for Apple, wasm and *all* ELF targets too now. (#4320)
- Vector comparisons (==, !=, <, <=, >, >=) now yield a vector mask. Identity comparisons (`is`, `!is`) still yield a scalar `bool`. (3a59ee81)
- New `timetrace2txt` tool for easier inspection of `--ftime-trace` output. (#4335)

#### Platform support
- Supports LLVM 9.0 - 15.0.
Expand Down
1 change: 1 addition & 0 deletions tests/CMakeLists.txt
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
set( LDC2_BIN ${PROJECT_BINARY_DIR}/bin/${LDC_EXE} )
set( LDCPROFDATA_BIN ${PROJECT_BINARY_DIR}/bin/ldc-profdata )
set( LDCPRUNECACHE_BIN ${PROJECT_BINARY_DIR}/bin/${LDCPRUNECACHE_EXE} )
set( TIMETRACE2TXT_BIN ${PROJECT_BINARY_DIR}/bin/${TIMETRACE2TXT_EXE} )
set( LLVM_TOOLS_DIR ${LLVM_ROOT_DIR}/bin )
set( LDC2_BIN_DIR ${PROJECT_BINARY_DIR}/bin )
set( LDC2_LIB_DIR ${PROJECT_BINARY_DIR}/lib${LIB_SUFFIX} )
Expand Down
2 changes: 2 additions & 0 deletions tests/lit.site.cfg.in
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,7 @@ OFF = False
config.ldc2_bin = "@LDC2_BIN@"
config.ldcprofdata_bin = "@LDCPROFDATA_BIN@"
config.ldcprunecache_bin = "@LDCPRUNECACHE_BIN@"
config.timetrace2txt_bin = "@TIMETRACE2TXT_BIN@"
config.ldc2_bin_dir = "@LDC2_BIN_DIR@"
config.ldc2_lib_dir = "@LDC2_LIB_DIR@"
config.ldc2_runtime_dir = "@RUNTIME_DIR@"
Expand Down Expand Up @@ -155,6 +156,7 @@ config.substitutions.append( ('%ldc', config.ldc2_bin) )
config.substitutions.append( ('%gnu_make', config.gnu_make_bin) )
config.substitutions.append( ('%profdata', config.ldcprofdata_bin) )
config.substitutions.append( ('%prunecache', config.ldcprunecache_bin) )
config.substitutions.append( ('%timetrace2txt', config.timetrace2txt_bin) )
config.substitutions.append( ('%llvm-spirv', os.path.join(config.llvm_tools_dir, 'llvm-spirv')) )
config.substitutions.append( ('%llc', os.path.join(config.llvm_tools_dir, 'llc')) )
config.substitutions.append( ('%runtimedir', config.ldc2_runtime_dir ) )
Expand Down
16 changes: 16 additions & 0 deletions tests/tools/timetrace2txt_1.d
Original file line number Diff line number Diff line change
@@ -0,0 +1,16 @@
// Test timetrace2txt tool basic functionality

// RUN: %ldc -c -o- --ftime-trace --ftime-trace-file=%t.timetrace --ftime-trace-granularity=1 %s

// RUN: %timetrace2txt %t.timetrace -o %t.txt && FileCheck %s < %t.txt
// RUN: %timetrace2txt %t.timetrace -o - | FileCheck %s

// CHECK: Timetrace
// CHECK: main

void foo();

void main()
{
foo();
}
15 changes: 15 additions & 0 deletions tests/tools/timetrace2txt_tsv.d
Original file line number Diff line number Diff line change
@@ -0,0 +1,15 @@
// Test timetrace2txt tool basic TSV functionality

// RUN: %ldc -c -o- --ftime-trace --ftime-trace-file=%t.timetrace --ftime-trace-granularity=1 %s

// RUN: %timetrace2txt %t.timetrace -o %t.txt --tsv %t.tsv && FileCheck %s < %t.tsv
// RUN: %timetrace2txt %t.timetrace -o %t.txt --tsv - | FileCheck %s

// CHECK: Duration Text Line Number Name Location Detail

void foo();

void main()
{
foo();
}
21 changes: 21 additions & 0 deletions tools/CMakeLists.txt
Original file line number Diff line number Diff line change
Expand Up @@ -39,3 +39,24 @@ if (EXISTS ${CMAKE_CURRENT_SOURCE_DIR}/${LDCPROFDATA_SRC})
else()
message(WARNING "ldc-profdata source (${LDCPROFDATA_SRC}) not found")
endif()

#############################################################################
# Build timetrace2txt
set(TIMETRACE2TXT_EXE timetrace2txt)
set(TIMETRACE2TXT_EXE ${TIMETRACE2TXT_EXE} PARENT_SCOPE) # needed for correctly populating lit.site.cfg.in
set(TIMETRACE2TXT_EXE_NAME ${PROGRAM_PREFIX}${TIMETRACE2TXT_EXE}${PROGRAM_SUFFIX})
set(TIMETRACE2TXT_EXE_FULL ${PROJECT_BINARY_DIR}/bin/${TIMETRACE2TXT_EXE_NAME}${CMAKE_EXECUTABLE_SUFFIX})
set(TIMETRACE2TXT_D_SRC
${PROJECT_SOURCE_DIR}/tools/timetrace2txt.d
)
build_d_executable(
"${TIMETRACE2TXT_EXE}"
"${TIMETRACE2TXT_EXE_FULL}"
"${TIMETRACE2TXT_D_SRC}"
"${DFLAGS_BUILD_TYPE}"
""
""
""
${COMPILE_D_MODULES_SEPARATELY}
)
install(PROGRAMS ${TIMETRACE2TXT_EXE_FULL} DESTINATION ${CMAKE_INSTALL_PREFIX}/bin)
2 changes: 2 additions & 0 deletions tools/README.md
Original file line number Diff line number Diff line change
Expand Up @@ -6,3 +6,5 @@ The `/tools` directory contains user tools that accompany LDC and that should be
`ldc-prune-cache` helps keeping the size of LDC's object file cache (`-cache`) in check. See [the original PR](https://github.com/ldc-developers/ldc/pull/1753) for more details.

`ldc-profdata` converts raw profiling data to a profile data format that can be used by LDC. The source is copied from LLVM (`llvm-profdata`), and is versioned for each LLVM version that we support because the version has to match exactly with LDC's LLVM version.

`timetrace2txt` converts the .timetrace output of `--ftime-trace` (which is in [Chromium's trace event JSON format](https://www.chromium.org/developers/how-tos/trace-event-profiling-tool/)) to a text file that is easier for humans to read.
254 changes: 254 additions & 0 deletions tools/timetrace2txt.d
Original file line number Diff line number Diff line change
@@ -0,0 +1,254 @@
//===-- tools/timetrace2txt.d -------------------------------------*- D -*-===//
//
// LDC – the LLVM D compiler
//
// This file is distributed under the BSD-style LDC license. See the LICENSE
// file for details.
//
//===----------------------------------------------------------------------===//
//
// Converts --ftime-trace output to a text file.
//
//===----------------------------------------------------------------------===//

import core.stdc.stdlib : exit;
import std.stdio;
import std.file;
import std.json;
import std.range;
import std.conv;
import std.algorithm;


struct Config {
string input_filename;
string output_filename = "timetrace.txt";
string output_TSV_filename;
}
Config config;

File outputTextFile;
static string duration_format_string = "%13.3f ";

JSONValue sourceFile;
JSONValue[] metadata; // "M"
JSONValue[] counterdata; // "C"
JSONValue[] processes; // "X"

ulong lineNumberCounter = 1;

void parseCommandLine(string[] args) {
import std.getopt : arraySep, getopt, defaultGetoptPrinter;

try {
arraySep = ";";
auto helpInformation = getopt(
args,
"o", "Output filename (default: '" ~ config.output_filename.init ~ "'). Specify '-' to redirect output to stdout.", &config.output_filename,
"tsv", "Also output to this file in duration-sorted Tab-Separated Values (TSV) format", &config.output_TSV_filename,
);

if (args.length != 2) {
helpInformation.helpWanted = true;
writeln("No input file given!\n");
} else {
config.input_filename = args[1];
if (!exists(config.input_filename) || !isFile(config.input_filename)) {
writefln("Input file '%s' does not exist or is not a file.\n", config.input_filename);
helpInformation.helpWanted = true;
}
}

if (helpInformation.helpWanted) {
defaultGetoptPrinter(
"Converts --ftime-trace output to text.\n" ~
"Usage: timetrace2txt [input file] [options]\n",
helpInformation.options
);
exit(1);
}

}
catch (Exception e) {
writefln("Error processing command line arguments: %s", e.msg);
writeln("Use '--help' for help.");
exit(1);
}
}

int main(string[] args)
{
parseCommandLine(args);

outputTextFile = (config.output_filename == "-") ? stdout : File(config.output_filename, "w");

auto input_json = read(config.input_filename).to!string;
sourceFile = parseJSON(input_json);
processInputJSON();
constructTree();
constructList();

{
outputTextFile.writeln("Timetrace: ", args[1]);
lineNumberCounter++;

outputTextFile.writeln("Metadata:");
lineNumberCounter++;

foreach (node; metadata)
{
outputTextFile.write(" ");
outputTextFile.writeln(node);
lineNumberCounter++;
}

outputTextFile.writeln("Duration (ms)");
lineNumberCounter++;
}

wchar[] indentstring;
foreach (i, ref child; Node.root.children)
child.print(indentstring, false);

if (config.output_TSV_filename.length != 0) {
File outputTSVFile = (config.output_TSV_filename == "-") ? stdout : File(config.output_TSV_filename, "w");
outputTSVFile.writeln("Duration\tText Line Number\tName\tLocation\tDetail");
foreach (node; Node.all)
outputTSVFile.writeln(node.duration, "\t", node.lineNumber, "\t",
node.name, "\t", node.location, "\t", node.detail);
}

return 0;
}

void processInputJSON()
{
auto beginningOfTime = sourceFile["beginningOfTime"].integer;
auto traceEvents = sourceFile["traceEvents"].array;

// Read meta data
foreach (value; traceEvents)
{
switch (value["ph"].str)
{
case "M":
metadata ~= value;
break;
case "C":
counterdata ~= value;
break;
case "X":
processes ~= value;
break;
default: //drop
}
}

// process node = {"ph":"X","name": "Sema1: Module object","ts":26825,"dur":1477,"loc":"<no file>","args":{"detail": "","loc":"<no file>"},"pid":101,"tid":101},
// Sort time processes
multiSort!(q{a["ts"].integer < b["ts"].integer}, q{a["dur"].integer > b["dur"].integer})(processes);
}

// Build tree (to get nicer looking structure lines)
void constructTree()
{
Node.root = Node(new JSONValue("Tree root"), long.max, true);
Node.count++;
Node*[] parent_stack = [&Node.root]; // each stack item represents the first uncompleted note of that level in the tree

foreach (ref process; processes)
{
auto last_ts = process["ts"].integer + process["dur"].integer;
size_t parent_idx = 0; // index in parent_stack to which this item should be added.

foreach (i; 0 .. parent_stack.length)
{
if (last_ts > parent_stack[i].last_ts)
{
// The current process outlasts stack item i. Stop traversing, parent is i-1;
parent_idx = i - 1;
parent_stack.length = i;
break;
}

parent_idx = i;
}

parent_stack[parent_idx].children ~= Node(&process, last_ts);
parent_stack ~= &parent_stack[parent_idx].children[$ - 1];
Node.count++;
}
}

void constructList()
{
size_t offset;

Node.all.length = Node.count - 1;

void handle(Node* root)
{
Node.all[offset++] = root;

foreach (ref child; root.children)
handle(&child);
}

foreach (ref child; Node.root.children)
handle(&child);

Node.all.sort!((a, b) => a.duration > b.duration);
}

struct Node
{
Node[] children;
JSONValue* json;
long last_ts; // represents the last timestamp of this node (i.e. ts + dur)
ulong lineNumber;

string name;
long duration; // microseconds
string location;
string detail;

static Node root;
static Node*[] all;
static size_t count = 0;

this(JSONValue* json, long last_ts, bool root = false)
{
this.json = json;
this.last_ts = last_ts;

if (!root)
{
this.duration = (*json)["dur"].integer;
this.name = (*json)["name"].str;
this.location = (*json)["args"]["loc"].str;
this.detail = (*json)["args"]["detail"].str;
}
}

void print(wchar[] indentstring, bool last_child) {
this.lineNumber = lineNumberCounter;
lineNumberCounter++;

// Output in milliseconds.
outputTextFile.writef(duration_format_string, cast(double)(this.duration) / 1000);

if (last_child)
indentstring[$-1] = '';
outputTextFile.write(indentstring);
outputTextFile.write("- ", this.name);
outputTextFile.write(", ", this.detail);
outputTextFile.writeln(", ", this.location);
if (last_child)
indentstring[$-1] = ' ';

wchar[] child_indentstring = indentstring ~ " |";
foreach (i, ref child; this.children) {
child.print(child_indentstring, i == this.children.length-1);
}
}
}

0 comments on commit e85a543

Please sign in to comment.