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 }