1 /// DMD trace.log parser 2 module dlangide.tools.d.dmdtrace; 3 4 /* 5 Based on d-profile-viewer: https://bitbucket.org/andrewtrotman/d-profile-viewer 6 7 Copyright (c) 2015-2016 eBay Software Foundation 8 Written by Andrew Trotman 9 Licensed under the 3-clause BSD license (see here:https://en.wikipedia.org/wiki/BSD_licenses) 10 11 */ 12 13 14 import dlangui.core.logger; 15 //import core.stdc.stdlib; 16 import std.file; 17 import std.stdio; 18 import std..string; 19 //import dlangide.tools.d.demangle; 20 import core.runtime; 21 import std.conv; 22 import std.algorithm; 23 import std.exception; 24 //import std.demangle; 25 import dlangide.ui.outputpanel; 26 import dlangide.builders.extprocess; 27 import dlangui.widgets.appframe; 28 import core.thread; 29 30 enum TraceSortOrder { 31 BY_FUNCTION_TIME, 32 BY_TOTAL_TIME, 33 BY_CALL_COUNT, 34 BY_NAME, 35 } 36 37 void sortFunctionNodes(FunctionNode[] nodes, TraceSortOrder sortOrder) { 38 import std.algorithm.sorting : sort; 39 final switch(sortOrder) { 40 case TraceSortOrder.BY_FUNCTION_TIME: 41 sort!((a,b) => a.function_time > b.function_time)(nodes); 42 break; 43 case TraceSortOrder.BY_TOTAL_TIME: 44 sort!((a,b) => a.function_and_descendant_time > b.function_and_descendant_time)(nodes); 45 break; 46 case TraceSortOrder.BY_CALL_COUNT: 47 sort!((a,b) => a.number_of_calls > b.number_of_calls)(nodes); 48 break; 49 case TraceSortOrder.BY_NAME: 50 sort!((a,b) => a.name < b.name)(nodes); 51 break; 52 } 53 } 54 55 class DMDTraceLogParser { 56 private string filename; 57 private string content; 58 private string[] lines; 59 private bool _cancelRequested; 60 61 FunctionNode[string] nodes; 62 FunctionNode[] nodesByFunctionTime; 63 FunctionNode[] nodesByTotalTime; 64 FunctionNode[] nodesByCallCount; 65 FunctionNode[] nodesByName; 66 //FunctionEdge[string] caller_graph; 67 //FunctionEdge[string] called_graph; 68 ulong ticks_per_second; 69 70 this(string fname) { 71 filename = fname; 72 } 73 void requestCancel() { 74 _cancelRequested = true; 75 } 76 private void splitLines(void[] buffer) { 77 lines.assumeSafeAppend; 78 content = cast(string)buffer; 79 int lineStart = 0; 80 for (int i = 0; i < content.length; i++) { 81 char ch = content.ptr[i]; 82 if (ch == '\r' || ch == '\n') { 83 if (lineStart < i) { 84 lines ~= content[lineStart .. i]; 85 } 86 lineStart = i + 1; 87 } 88 } 89 // append last line if any 90 if (lineStart < content.length) 91 lines ~= content[lineStart .. $]; 92 } 93 bool load() { 94 void[] file; 95 try 96 { 97 file = read(filename); 98 } 99 catch (Exception ex) 100 { 101 Log.e("Cannot open trace file ", filename); 102 return false; 103 } 104 if (file.length == 0) { 105 Log.e("Trace log ", filename, " is empty"); 106 return false; 107 } 108 Log.d("Opened file ", filename, " ", file.length, " bytes"); 109 splitLines(file); 110 Log.d("Lines: ", lines.length); 111 return lines.length > 0; 112 } 113 bool parse() { 114 bool caller = true; 115 string function_name; 116 FunctionEdge[string] caller_graph; 117 FunctionEdge[string] called_graph; 118 ulong function_times; 119 ulong function_and_descendant; 120 ulong function_only; 121 foreach(i, line; lines) { 122 if (_cancelRequested) 123 return false; 124 if (line.length == 0) { 125 continue; // Ignore blank lines 126 } else if (line[0] == '=') { // Seperator between call graph and summary data 127 auto number = indexOfAny(line, "1234567890"); 128 if (number < 0) 129 { 130 Log.e("Corrupt trace.log (can't compute ticks per second), please re-profile and try again"); 131 return false; 132 } 133 auto space = indexOf(line[number .. $], ' ') + number; 134 ticks_per_second = to!ulong(line[number .. space]); 135 break; 136 } else if (line[0] == '-') { //Seperator between each function call graph 137 caller = true; 138 if (function_name.length != 0) 139 nodes[text(function_name)] = new FunctionNode(function_name, 140 function_times, function_and_descendant, function_only, 141 caller_graph, called_graph); 142 caller_graph = null; 143 called_graph = null; 144 } else if (line[0] == '\t') 145 { 146 // A function either calling or called by this function 147 /* 148 We can't assume a name starts with an '_' because it might be an extern "C" which hasn't been mangled. 149 We also can't assume the character encodin of what ever language that is so we look for the last tab 150 and asusme the identifier starts on the next character. 151 */ 152 // auto pos = indexOfAny(line, "_"); 153 auto pos = lastIndexOf(line, '\t') + 1; 154 auto start_pos = indexOfAny(line, "1234567890"); 155 if (start_pos < 0 || pos < 0 || pos < start_pos) 156 { 157 Log.e("Corrupt trace.log (call count is non-numeric), please re-profile and try again"); 158 return false; 159 } 160 immutable times = to!ulong(line[start_pos .. pos - 1]); 161 auto name = line[pos .. $]; 162 if (caller) 163 { 164 caller_graph[text(name)] = new FunctionEdge(name, times); 165 } 166 else 167 { 168 called_graph[text(name)] = new FunctionEdge(name, times); 169 } 170 } 171 /* 172 In the case of a call to a non-D function, the identifier might not start with an '_' (e.g. extern "C"). But, we can't know 173 how those identifiers are stored so we can't assume an encoding - and hence we must assume that what ever we have is correct. 174 */ 175 // else if (indexOf("_abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ", line[0]) >= 0) //The name of the function were're currently examining the call graph for (seperates callers from called) 176 else //The name of the function were're currently examining the call graph for (seperates callers from called) 177 { 178 auto start_tab = indexOf(line, '\t'); 179 auto middle_tab = indexOf(line[start_tab + 1 .. $], '\t') + start_tab + 1; 180 auto last_tab = indexOf(line[middle_tab + 1 .. $], '\t') + middle_tab + 1; 181 function_name = line[0 .. start_tab]; 182 //if (function_name.length > 1024) 183 // Log.d("long function name: ", function_name); 184 function_times = to!ulong(line[start_tab + 1 .. middle_tab]); 185 function_and_descendant = to!ulong(line[middle_tab + 1 .. last_tab]); 186 function_only = to!ulong(line[last_tab + 1 .. $]); 187 caller = false; 188 } 189 } 190 if (function_name.length != 0) 191 { 192 nodes[text(function_name)] = new FunctionNode(function_name, 193 function_times, function_and_descendant, function_only, caller_graph, called_graph); 194 } 195 makeSorted(); 196 return true; 197 } 198 199 void makeSorted() { 200 nodesByFunctionTime.reserve(nodes.length); 201 foreach(key, value; nodes) { 202 nodesByFunctionTime ~= value; 203 } 204 nodesByTotalTime = nodesByFunctionTime.dup; 205 nodesByCallCount = nodesByFunctionTime.dup; 206 nodesByName = nodesByFunctionTime.dup; 207 sortFunctionNodes(nodesByFunctionTime, TraceSortOrder.BY_FUNCTION_TIME); 208 sortFunctionNodes(nodesByTotalTime, TraceSortOrder.BY_TOTAL_TIME); 209 sortFunctionNodes(nodesByCallCount, TraceSortOrder.BY_CALL_COUNT); 210 sortFunctionNodes(nodesByName, TraceSortOrder.BY_NAME); 211 } 212 } 213 214 private __gshared static char[] demangleBuffer; 215 216 private string demangle(string mangled_name) { 217 import core.demangle : demangle; 218 //const (char) [] demangled_name; 219 string demangled_name; // = dlangide.tools.d.demangle.demangle(mangled_name); 220 //if (demangled_name[0] == '_') { // in the unlikely event that we fail to demangle, fall back to the phobos demangler 221 try { 222 if (demangleBuffer.length < mangled_name.length + 16384) 223 demangleBuffer.length = mangled_name.length * 2 + 16384; 224 demangled_name = cast(string)core.demangle.demangle(mangled_name, demangleBuffer[]); 225 } catch (Exception e) { 226 demangled_name = mangled_name; 227 } 228 //} 229 if (demangled_name.length > 1024) 230 return demangled_name[0..1024] ~ "..."; 231 return demangled_name.dup; 232 } 233 234 /* 235 CLASS FUNCTION_EDGE 236 ------------------- 237 There's one of these objects for each function in program being profiled. 238 */ 239 class FunctionEdge 240 { 241 public: 242 string name; // the demangled name of the function 243 string mangled_name; // the mangled name 244 ulong calls; // number of times the function is called 245 246 public: 247 /* 248 THIS() 249 ------ 250 Constructor 251 */ 252 this(string mangled_name, ulong calls) 253 { 254 this.mangled_name = mangled_name; 255 256 this.name = demangle(mangled_name); 257 258 this.calls = calls; 259 } 260 } 261 262 /* 263 CLASS FUNCTION_NODE 264 ------------------- 265 266 */ 267 class FunctionNode 268 { 269 public: 270 FunctionEdge[string] called_by; 271 FunctionEdge[string] calls_to; 272 string name; 273 string mangled_name; 274 ulong number_of_calls; 275 ulong function_and_descendant_time; // in cycles 276 ulong function_time; // in cycles 277 278 private: 279 /* 280 PERCENT() 281 --------- 282 Compute top/bottom to 2 decimal places 283 */ 284 double percent(double top, double bottom) 285 { 286 return cast(double)(cast(size_t)((top / bottom * 100_00.0))) / 100.0; 287 } 288 289 /* 290 TO_US() 291 ------- 292 Convert from ticks to micro-seconds 293 */ 294 size_t to_us(double ticks, double ticks_per_second) 295 { 296 return cast(size_t)(ticks / ticks_per_second * 1000 * 1000); 297 } 298 299 public: 300 /* 301 THIS() 302 ------ 303 */ 304 this(string mangled_name, ulong calls, ulong function_and_descendant_time, 305 ulong function_time, FunctionEdge[string] called_by, FunctionEdge[string] calls_to) 306 { 307 this.mangled_name = mangled_name; 308 309 this.name = demangle(mangled_name); 310 311 this.number_of_calls = calls; 312 this.function_and_descendant_time = function_and_descendant_time; 313 this.function_time = function_time; 314 this.called_by = called_by; 315 this.calls_to = calls_to; 316 } 317 318 } 319 320 DMDTraceLogParser parseDMDTraceLog(string filename) { 321 scope(exit) demangleBuffer = null; 322 DMDTraceLogParser parser = new DMDTraceLogParser(filename); 323 if (!parser.load()) 324 return null; 325 if (!parser.parse()) 326 return null; 327 return parser; 328 } 329 330 class DMDProfilerLogParserThread : Thread { 331 private DMDTraceLogParser _parser; 332 private bool _finished; 333 private bool _success; 334 335 this(string filename) { 336 super(&run); 337 _parser = new DMDTraceLogParser(filename); 338 } 339 340 @property bool finished() { return _finished; } 341 @property DMDTraceLogParser parser() { return _success ? _parser : null; } 342 343 void requestCancel() { 344 _parser.requestCancel(); 345 } 346 void run() { 347 scope(exit) demangleBuffer = null; 348 if (!_parser.load()) { 349 _finished = true; 350 return; 351 } 352 if (!_parser.parse()) { 353 _finished = true; 354 return; 355 } 356 _success = true; 357 _finished = true; 358 // Done 359 } 360 } 361 362 alias DMDProfilerLogParserListener = void delegate(DMDTraceLogParser parser); 363 364 class DMDProfilerLogParserOperation : BackgroundOperationWatcher { 365 366 string _filename; 367 DMDProfilerLogParserListener _listener; 368 dstring _description; 369 DMDProfilerLogParserThread _thread; 370 DMDTraceLogParser _result; 371 372 this(AppFrame frame, string filename, OutputPanel log, DMDProfilerLogParserListener listener) { 373 super(frame); 374 _filename = filename; 375 _listener = listener; 376 _description = "Parsing DMD trace log file"d; 377 _thread = new DMDProfilerLogParserThread(filename); 378 _thread.start(); 379 } 380 381 /// returns description of background operation to show in status line 382 override @property dstring description() { return _description; } 383 /// returns icon of background operation to show in status line 384 override @property string icon() { return "folder"; } 385 /// update background operation status 386 override void update() { 387 if (_finished) { 388 return; 389 } 390 if (_thread.finished) { 391 _thread.join(); 392 _result = _thread.parser; 393 //_extprocess.kill(); 394 //_extprocess.wait(); 395 _finished = true; 396 return; 397 } 398 if (_cancelRequested) { 399 _thread.requestCancel(); 400 _thread.join(); 401 _result = _thread.parser; 402 //_extprocess.kill(); 403 //_extprocess.wait(); 404 _finished = true; 405 return; 406 } 407 super.update(); 408 } 409 override void removing() { 410 super.removing(); 411 //if (_exitCode != int.min && _listener) 412 _listener(_result); 413 } 414 }