Warning: Illegal string offset 'filter' in /var/sites/t/theproactiveprogrammer.com/public_html/wp-includes/taxonomy.php on line 1409
I intended for this article to be contained within a single post, but it turned out to be too long for that. Click here for part 2.
Over the past couple of days I have been on quite a journey in trying to optimize a method in my current project. I’ve known this operation was slow for the past few months, but it has never really been a priority to address the issue.
On my daily commute I often listen to podcasts, my favourites being .NET Rocks, Radiolab and The Guardian Football Weekly. Earlier this week I listened to a .NET Rocks episode titled Making .NET Perform with Ben Watson. Watson is the author of Writing High Performance .NET Code and during the show he and the guys discussed the topic of performance optimization from a number of different angles. The show inspired me to finally look into this annoying performance issue which had been on my radar for months. As I was listening I contemplated the problem, and in particular took an interest in a discussion on a favourite tool of Watson’s: PerfView. I had never heard of PerfView, but it sounded like the perfect application to help me understand my performance issue, and if nothing else offered the chance to try out a new tool. Apparently it was free and lightweight – two characteristics I always love in a development tool.
Chapter 1: Adventures in PerfView
Later that day, sitting at my desk, I downloaded PerfView and read through its tutorial. What a great tool! I had previously used Red Gate’s ANTS Performance Profiler, admittedly to a limited extent, but PerfView seemed easier to use, just as capable and a great deal more lightweight. Essentially PerfView helps you to explore two aspects of your application – CPU usage and memory allocation. My problem operation involved retrieving several thousand rows of data from an Oracle database, to automatically populate a collection of complex C# objects, using NHibernate. I had a hunch that it was the complexity of each object, with several layers of inheritance and multiple associations, that was the problem. I was perhaps slightly biased having just heard Watson emphasise the importance of memory allocation in .NET applications and how slowness was often a result of memory issues. Indeed, the PerfView tutorial states:
If your app does use 50 Meg or 100 Meg of memory, then it probably is having an important performance impact and you need to take more time to optimize its memory usage.
So I loaded my application in Visual Studio, paused execution with a breakpoint and used PerfView to take a snapshot of the heap, when I knew my large collection of objects would be in memory. I discovered that although IIS express was indeed using over 100MB of memory, only a fraction of this (around 10%) was being used by the heap. So maybe memory allocation wasn’t the problem at all?
Next I decided to use PerfView to analyse the CPU usage during my long operation. In total the operation was taking around one and a half minutes. I ran an analysis and was not surprised to find that the bulk of this time was taken up in the data layer, retrieving data from the database and implicitly populating my collection of several thousand objects. This was just as I had feared. Would I have to redesign my database and class structure to remove some layers of complexity? This would be a huge task. However, on closer inspection, I realised that although over 80% of the CPU usage during this operation was taken up inside my data retrieval method, the total CPU usage time was in fact only 15 seconds or so. Surely this could mean only one thing – it must have been the database query which was taking so long, which suprised me as several thousand rows is of course not much to ask of a database.
Chapter 2 – NHibernate Logging
This project is the first time I have used NHibernate. While I think I can see its benefits, or rather the benefits of using an ORM tool in general, I am not totally convinced. I come from a traditional background of writing and calling my own stored procedures, and miss that complete control of how and when the database is called. There have been a few times when I have wrestled with NHibernate to achieve the desired results, but perhaps this is just a part of getting to grips with it and learning how to use it to my advantage. In any case, having concluded that the problem involved my database query, I wanted to know exactly what query was being executed. After some googling I found that I could use NHibernate logging to obtain this query, by adding a couple of lines to my web.config file.
Using breakpoints to isolate the data access method, I was able to examine my log file to obtain the database query in question. It was indeed a very complex query, with many joins corresponding to the multiple layers of inheritance defined in my class and database structure. However, I noticed that stepping from my data retrieval line of code to the next line was in fact pretty quick, less than 5 seconds in fact. Copying and pasting the cumbersome SQL query into Oracle SQL Developer and executing it from there confirmed that the query itself was indeed very fast, despite its complexity. So my assumption was proved wrong again. It was not memory allocation that was the problem, it was not my data retrieval query, yet it was not CPU usage that was taking up so much time. So what was it? I hit F5 to continue execution from my breakpoint, let the operation complete, and then reexamined my NHibernate log file. To my surprise I discovered that the database had been hit several thousand times, running a relatively simple query each time to populate a collection property on one of my classes. It seemed that, without my knowledge, I had fallen victim to the Select n + 1 problem.