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 }