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 static import core.demangle; 223 if (demangleBuffer.length < mangled_name.length + 16384) 224 demangleBuffer.length = mangled_name.length * 2 + 16384; 225 demangled_name = cast(string)core.demangle.demangle(mangled_name, demangleBuffer[]); 226 } catch (Exception e) { 227 demangled_name = mangled_name; 228 } 229 //} 230 if (demangled_name.length > 1024) 231 return demangled_name[0..1024] ~ "..."; 232 return demangled_name.dup; 233 } 234 235 /* 236 CLASS FUNCTION_EDGE 237 ------------------- 238 There's one of these objects for each function in program being profiled. 239 */ 240 class FunctionEdge 241 { 242 public: 243 string name; // the demangled name of the function 244 string mangled_name; // the mangled name 245 ulong calls; // number of times the function is called 246 247 public: 248 /* 249 THIS() 250 ------ 251 Constructor 252 */ 253 this(string mangled_name, ulong calls) 254 { 255 this.mangled_name = mangled_name; 256 257 this.name = demangle(mangled_name); 258 259 this.calls = calls; 260 } 261 } 262 263 /* 264 CLASS FUNCTION_NODE 265 ------------------- 266 267 */ 268 class FunctionNode 269 { 270 public: 271 FunctionEdge[string] called_by; 272 FunctionEdge[string] calls_to; 273 string name; 274 string mangled_name; 275 ulong number_of_calls; 276 ulong function_and_descendant_time; // in cycles 277 ulong function_time; // in cycles 278 279 private: 280 /* 281 PERCENT() 282 --------- 283 Compute top/bottom to 2 decimal places 284 */ 285 double percent(double top, double bottom) 286 { 287 return cast(double)(cast(size_t)((top / bottom * 100_00.0))) / 100.0; 288 } 289 290 /* 291 TO_US() 292 ------- 293 Convert from ticks to micro-seconds 294 */ 295 size_t to_us(double ticks, double ticks_per_second) 296 { 297 return cast(size_t)(ticks / ticks_per_second * 1000 * 1000); 298 } 299 300 public: 301 /* 302 THIS() 303 ------ 304 */ 305 this(string mangled_name, ulong calls, ulong function_and_descendant_time, 306 ulong function_time, FunctionEdge[string] called_by, FunctionEdge[string] calls_to) 307 { 308 this.mangled_name = mangled_name; 309 310 this.name = demangle(mangled_name); 311 312 this.number_of_calls = calls; 313 this.function_and_descendant_time = function_and_descendant_time; 314 this.function_time = function_time; 315 this.called_by = called_by; 316 this.calls_to = calls_to; 317 } 318 319 } 320 321 DMDTraceLogParser parseDMDTraceLog(string filename) { 322 scope(exit) demangleBuffer = null; 323 DMDTraceLogParser parser = new DMDTraceLogParser(filename); 324 if (!parser.load()) 325 return null; 326 if (!parser.parse()) 327 return null; 328 return parser; 329 } 330 331 class DMDProfilerLogParserThread : Thread { 332 private DMDTraceLogParser _parser; 333 private bool _finished; 334 private bool _success; 335 336 this(string filename) { 337 super(&run); 338 _parser = new DMDTraceLogParser(filename); 339 } 340 341 @property bool finished() { return _finished; } 342 @property DMDTraceLogParser parser() { return _success ? _parser : null; } 343 344 void requestCancel() { 345 _parser.requestCancel(); 346 } 347 void run() { 348 scope(exit) demangleBuffer = null; 349 if (!_parser.load()) { 350 _finished = true; 351 return; 352 } 353 if (!_parser.parse()) { 354 _finished = true; 355 return; 356 } 357 _success = true; 358 _finished = true; 359 // Done 360 } 361 } 362 363 alias DMDProfilerLogParserListener = void delegate(DMDTraceLogParser parser); 364 365 class DMDProfilerLogParserOperation : BackgroundOperationWatcher { 366 367 string _filename; 368 DMDProfilerLogParserListener _listener; 369 dstring _description; 370 DMDProfilerLogParserThread _thread; 371 DMDTraceLogParser _result; 372 373 this(AppFrame frame, string filename, OutputPanel log, DMDProfilerLogParserListener listener) { 374 super(frame); 375 _filename = filename; 376 _listener = listener; 377 _description = "Parsing DMD trace log file"d; 378 _thread = new DMDProfilerLogParserThread(filename); 379 _thread.start(); 380 } 381 382 /// returns description of background operation to show in status line 383 override @property dstring description() { return _description; } 384 /// returns icon of background operation to show in status line 385 override @property string icon() { return "folder"; } 386 /// update background operation status 387 override void update() { 388 if (_finished) { 389 return; 390 } 391 if (_thread.finished) { 392 _thread.join(); 393 _result = _thread.parser; 394 //_extprocess.kill(); 395 //_extprocess.wait(); 396 _finished = true; 397 return; 398 } 399 if (_cancelRequested) { 400 _thread.requestCancel(); 401 _thread.join(); 402 _result = _thread.parser; 403 //_extprocess.kill(); 404 //_extprocess.wait(); 405 _finished = true; 406 return; 407 } 408 super.update(); 409 } 410 override void removing() { 411 super.removing(); 412 //if (_exitCode != int.min && _listener) 413 _listener(_result); 414 } 415 }