Finding the cause of performance issues in your applications is always tricky. The best thing for finding out what parts of an application are slow is to use a profiler. There are a number of profilers out there, but we weren’t happy with any of them, so we wrote our own, using the existing Aspects infrastructure in Elements. The aspect uses AOP to enable us to do instrumental profiling, the end result is the Profiling Aspect, which we're making available as Open Source on GitHub.
Using the Aspect
The aspect can be used by adding a reference to both RemObjects.Profiler.dll and RemObjects.Profiler.Aspect.dll, and then applying the aspect to the classes and/or methods that need to be profiled:
- Oxygene: [RemObjects.Profiler.Profile]
- C#: [RemObjects.Profiler.Profile]
- Swift: @RemObjects.Profiler.Profile
The last step is to set the PROFILE define in the project options and run the application. The profiling aspect automatically adds pre/post code to every method that it’s marked with.
What’s Happening
For every method the aspect is applied to, the aspect adds a call to RemObjects.Profiler.RemObjectsProfiler.Enter at the start of the method and call to RemObjects.Profiler.RemObjectsProfiler.Exit at the end. The RemObjectsProfiler class stores the start/end time and maintains counters and time tables for each method. When the application shuts down, it writes out a .log file next to the executable containing SQL statements to build a simple database containing the profiled data.
Looking at the Results
The log file can be loaded into the included ResultsViewer application:
Above is a screenshot of ResultsViewer running on the log of part of the Elements compiler for a real-life profiling session I did. Given that the aspect is a simple attribute, I was able to apply the attribute to just parts of the code to focus on that part and ignore the rest. The top list view contains the method result list, and can be filtered with the controls at the top.
- Thread contains the managed thread id of the thread that ran the code.
- Count the number of times that method got called.
- Total Ticks is the "gross" time spent in these methods (shown as ticks and as percentage of total time)
- Ticks without children shows how much "net" time is actually spent in this method itself, i.e. excluding the calls originated from the method. (Note that the exclusion only counts other calls also marked for profiling, everything else is included).
The bottom view gets updated depending on the call selected at the top. It shows who called this item and what calls it made. Positive level are calls that this method made, where level 1 is the method that gets directly called, level 2 is the method that gets called by a level 1 method. Negative levels show who called this method, where -1 is a direct caller:
Above has the TypeLoader.IntLoadReference call selected. About 43% of the total time is spent in the FxCache.LoadFile method, which isn’t that strange, since that’s the routine that loads files from disk, 1.57% is spent in TypeLoader.GetNSUses. This method gets called by TypeLoader.LoadReference, which in turn is called by TypeLoader.TryLoadReference.
Seeing FxCache.LoadFile show at the top of the list made me look at the loading code for .fx files in Elements. I applied the profiling aspect to the reader class and it gave me these (filtered) results:
In the end, the ProtoReader.IntReadInt64 method was being called about 10 million times and the code wasn’t very efficient. Optimizing it gave us a 10% speed improvement (relative to the caller, FxCache.LoadCode).
Conclusion
Profiling Aspect is a handy little library that will help you find bottlenecks ion your apps without relying on external profiling tools from this parties. It is supported for all three languages and all three platforms.
More information and the code can be found at the GitHub page for the Profiling Aspect project.
