Blog

You are currently viewing Using JS Profiler to Solve App Slowness in Loklak Search

Using JS Profiler to Solve App Slowness in Loklak Search

The loklak search web application had an issue of application slowdown in the development environment. There was a highly prominent lag and a slowdown in the application while typing a search query in the search box. This issue was being faced from but the reason for the lad and slowdown was unknown. So this blog explains how the issue was identified, what were the reasons behind it, and how the issue was solved.

The most important aspect of fixing any bug in the application is to first identify it. Here in our case what helped us to identify the issue was the proper use of JS profiler to find the hidden issue underneath.

Reporting of the issue

The issue was observed and reported in the issue #365. On discussion it was observed that the issue was not being observed by all the users but only some of them, this made it really interesting as the application, on the whole, was being shipped uniformly to all the users but still only fractions of them were facing this issue, and all the people who were experiencing this were the developers of the application

Detection

For the detection of the issue, it was important to have a starting point to search issue. Here the only thing which we knew about the issue was that it was being faced only when typing in the application search box. So this was our starting ground. The most important tool while solving such issues is the browser itself. The dev tools in the most modern browsers have a built in Javascript Profiler. A profiler is a tool which dynamically at the run time records the activities happening in the various threads of the application, most importantly main thread. So we can find the JS profiler in browser dev tools, in Chrome 59 it is in Performance tab.

In every profiler there is a record button (marked above) pressing this will start monitoring all the activities on various JS threads and other pipelines. So this profiler and understanding its logs is the key to solve any performance related issue in any web application.

So we started by hitting the record button and then typing in the search box. And this is the output which we saw for profiling. This output contains a lot of numbers and to make sense of all of them it is important to understand the important bits of it as the output, on the whole, can be a lot overwhelming.

Observations

We will go piece by piece and will try to make sense of the output and if possible identify the reason for our original issue.

 

  • This is the timeline strip which represents the overall view of the main thread of JS. The yellow portions show the percentage of CPU utilization with respect to time, here we can clearly see the consistent blocking CPU utilization by the main thread over a span of 10 seconds (during which we typed). The high CPU utilization starts with our first keystroke.
  • The red rectangles at the top represent the dropped frames, the frames which are never rendered due to heavy load, and the green line at the bottom represent the frames per second which you can see is practically zero. This implies that the CPU is entirely hogged up by the main thread and there is no room left for rendering frames.
  • Now, this is the Interactions panel this indicates all the user generated events which are triggered. It clearly shows that the key up and key character events are getting triggered but are taking a lot of processing time. The first key press, key character and key up events run normally. But then each subsequent event hogs up the CPU.
  • The above observation indicates what ever is the issue in the application it is in between the registering of an event and its final processing.
  • So the natural question arises what we do during this processing. On looking at the code it seems like we dispatch a Redux Action that the query string has updated, according to the action reducer updates the state. Now, this implies that our reducer is taking the time to update the state. But this does not make sense, as reducers are the pure functions, i.e. they don’t make any blocking calls. So they can’t hog up all the CPU cycles for 10 seconds.
  • So we need to investigate further to identify what is happening after the action is dispatched, to the store. This is the function call stack trace on the main thread. What we see here is each nested function call as we move down the tree.
  • The above trace shows that what all is happening when a key is pressed. There is again a key point to observe that the time to process the events is increasing per keystroke, for the first key stroke it starts from 112ms and jumps to 400ms in for the subsequent key presses, which causes the slowdown.
  • Now we can see in the above stack trace and find out the Rate determining step for each event processing. The RDS of a step is the slowest step which causes the whole process to execute slowly.
  • Now as we move down the tree we find that all the steps are taking very nominal time but some function down in the tree is causing the issues. So we move down the tree to identify the rate determining function call.
  • As we move down the tree we first find our action dispatch call as expected, the processing of this call is not taking much time but some of the functions in that process are causing our issue, thus we continue to move down the tree.
  • Here we find our culprit which is causing our issue the slowest step is a method which is making a call to our StoreDevtools module and notifying it about the latest store update. This notifying action is taking the most time.
  • As we move down the tree we first find our action dispatch call as expected, the processing of this call is not taking much time but some of the functions in that process are causing our issue, thus we continue to move down the tree.
  • Here we find our culprit which is causing our issue the slowest step is a method which is making a call to our StoreDevtools module and notifying it about the latest store update. This notifying action is taking the most time.
  • So the issue was caused by the import of dev-tools module in our app module 
    StoreDevtoolsModule.instrumentOnlyWithExtension();
  • Now another important observation here is that why only a few people were facing this issue
    • The only people who faced this issue were the developers working on the project because as the import statement says “instrumentOnlyWithExtension” it specifies that this module will only run when there is Devtools Extension installed.
    • And this is the case with the application developers only.

Fixing the issue

  • For fixing the issue it was decided that for best performance the StoreDevTools module will not be included in the package by default.
  • The module can be selectively imported for testing purposes as and when required by the developers
  • It will always be removed while merging into the main branch.

Results

Now after all these efforts and fixing it is worth mentioning the speed gains which were achieved after removing store dev-tools module.

  • This the profiler output after running the profiling on similar queries as before. Without even going into detail we can see it is much cleaner now.
  • These are the main thread and frame rates achieved after the removal of the module. We can clearly see the main thread is completely free and we thus achieve high frame rates.
  • The last important observation is that the action dispatching which was taking about 350ms earlier is now taking only 2.5ms. Such a performance boost is huge at about 140x at each key press.

Conclusion

When a web application has slow response or lag, it makes the users leave the application altogether, and this causes the huge setback to the efforts which we developers make in increasing the user interaction. Thus, any issue on client side must be solved as quickly as possible. The most important tool with which we use to test and predict what is going wrong with the application is the browser itself. The browser and the dev-tools provide us important tools required to optimize the application for improving the performance.

Resources and links

Tags:

Leave a Reply

This site uses Akismet to reduce spam. Learn how your comment data is processed.