Jerry Pommer - December 14, 2015
A large customer of ours complained of the browser being unusable for them on a particular admin page. Users experienced a deadlock on the Schedules page at start-of-day that lasted 20 to 30 seconds before it would respond to user input again. After verifying the condition, I used the Chrome browser’s profiling tools to help find the code that was running during the deadlock:
The profiler shows a lot of rendering going on here, much of which is redundant. The big CPU spike shown in the profile snapshot above starts at around 8 seconds into page load and completes approximately 20 seconds later. It appears that there is a large burst of activity, then a break, and then another burst pattern that looks very similar to the first:
This kind of behavior is nearly always because of a loop doing more than it should. The page under test is driven by Marionette and Backbone, and is rendering several lists of content. What we see in the image above is the CPU profile of a double render of a collection.
We have a collection of scheduled override data that is fetched from the server and presented in a CollectionView. That means it renders a view item for each piece of override data added to the collection that is being monitored for changes. Experience with our front-end stack led me to first look at the collection itself, and how it was being loaded with that data. It is a Backbone collection, which by default fires an ‘add’ event for each item that is retrieved from the server and added to the collection. The view layer is sensitive to those ‘add’ events, and will try to re-render whatever it needs to whenever the collection changes.
After the loading of all the items in the collection (and some other dependencies) is complete, they are sorted for a sensible presentation. The sorting also triggers re-rendering of the views to ensure they are displayed in the right order. So, it appeared in the above CPU profile that each element added to the collection would trigger a render to the screen, and then the following sort event would trigger that render sequence all over again.
Backbone allows suppression of the individual ‘add’ events from the collection, so that our sort is the only thing that triggers the rendering and nothing will be drawn to the screen before the data is entirely loaded, sorted, and ready to display. That cut the deadlock time by more than half, to around 9 seconds:
While that is a huge improvement, I felt like there wasn’t enough complexity or sheer volume of the data being processed here to excuse 8-10 seconds of waiting to use the product. We are talking about less than 50 list items here!
Delving deeper in, I found the real source of the bottleneck. This page was calling complex subviews into existence and rendering them inside each already-rendered list item view. Rendering the subviews in each parent item view causes a redraw of each parent item too. In the case of these subview items, it isn’t necessary to draw them until the information they contain is needed for a particular operation.
Here is an instance in which it is best to defer the rendering work until the user wants to see it. I reworked the UI a bit to replace those unnecessarily rendered views with clickable items that, when clicked by the user, trigger re-rendering of only the item the user is really interested in, cutting the start-of-day dead-time down to around three seconds:
But again, three seconds is just too long. You can see in this profile capture that we are down to five render operations in this point in the page load - far fewer than we started with.
But why five? I went deeper, looking for more triggers that could be causing the redraw, and came up with another subview that was actually a hidden component and only surfaced when the user triggered a new item create operation. Only one was needed for each new item created in the UI, and only if the user wanted to add something to the list.
Instead, this hidden view component was being rendered for each item already in the override list at start-of-day, and would never be shown in the UI for those items. I refactored that code as well, only rendering that piece of UI if it fell inside a parent element being used for creating a new override. Eliminating all that unnecessary rendering got us down to a single render operation and a far more acceptable wait period of 1.8 seconds:
With that all fixed, we can start looking for other optimizations, such as the 2 seconds of CPU churn right before this render loop happens, and the 6.5 seconds of absolute silence before that (it’s actually waiting for a response to a server query there). But this fix alone has a huge impact on the usability of this page.
– Carefully consider your layout when breaking view components into smaller, reusable sub-components, especially when dealing with collections. Every child view added to a parent after the parent is rendered can cause the parent to redraw. If done without considering the consequences, it can be a tremendous performance killer.
– If it doesn’t need to be visible at start-of-day, then don’t draw it until it is needed. If you are adding loads of data to each item in a list that will start out collapsed anyway, don’t do the render work on that collapsed data until it really needs to be seen. Sure, cache it client side and have it ready for instant presentation. The real overhead is getting it on the screen.
– It’s okay to make compromises in the design if it means maintaining a high-quality user experience. Give yourself permission (or win it from someone else) if the visual plan doesn’t scale well.