Speed Up Your App's Launch With BTTimeLog
2009-07-14
Reducing the amount of time an app takes to launch is tricky: there aren't any good tools that help figure out what is taking time and what is not. To complicate things, there is a lot happening at once. Instantiating some system objects uses a lot of resources for a while (often on other threads), so the real time taken to get from A to B in your code may be nothing like what you think it should be based on a linear analysis.
To help speed up my own apps, and not only at launch time, I've created a small class called BTTimeLog (download here). It works by tracking the system time to microsecond precision and logging the time differences and accumulated time as it hits different parts of the code. Since it creates meaningful, reproducible results, it can be used to accurately assess the effect of code changes and measure progress toward a known goal.
BTTimeLog has preprocessor conditionals that allow the logging code to be removed completely from production code. Each logging call is accompanied by a log level parameter that can be used to filter out calls that fall below a certain level. You can also fall back to NSLog using conditionals.
To use BTTimeLog, compile BTTimeLog.m into your app and add BTTimeLog.h to your .pch file or any other file that is globaly #imported. I normally maintain a separate AppGlobals.h file for this sort of thing (string constants, view tags, categories, etc.)
At various places in your app, add macro calls of the form
The first argument sets the level of the log call. The number should be between 0 and 7, with 7 being the highest level, and so the last one to be removed by filtering. The second argument is a format string. The optional third and subsequent arguments provide data for the format string.
Each line will generate a line of text in the log that looks like this:
The first number is the log level. The second is the time in milliseconds since BTTimeLog was initialized, or since the time was reset. The third number is the time difference in milliseconds since the previous line in the log. Next comes the class and method selector, and finally the string with the parameters substituted. The file and line number are not included, because you don't need them: just search for the method.
Having the class and method selector logged is useful for another reason: the format string can be short and to the point and you can use an identical line of code pasted all over the place. I use "Start" and "End" as strings in the example below at the begining and end of all my methods. Here I've also used several calls in [AppUtility initialiseSpacedout] to narrow down where time is being spent there.
Most of the 600ms spent in applicationDidFinishLaunching: is happening just before the controllers are set up, so I should pay attention to what is in the NIBs and see how the views are being initialized. When I think I have improved the time, I can measure the effect.
If the logging is too verbose, I can turn off logging below a given level globally with a preprocessor variable or an environment parameter, or dynamically via a method call, +setLoggingMinLevel:. All my Start and End lines above are level 3 logs, so by filtering to level 3 that's all I see. Also note that the logging level provided in the call to BTLogString doesn't have to be a constant: you can use an int variable and change it dynamically or even globally, perhaps using another macro to combine a global setting with a local setting.
And if you have some user-initiated or repetitive event that fires off some action that you are trying to measure and minimize, you can reset the elapsed time with:
if you want to show in the log that the time was reset, or
if you want to rest the time silently.
Download BTTimeLog
BTTimeLog is supplied as source and is free to use and improve.
To help speed up my own apps, and not only at launch time, I've created a small class called BTTimeLog (download here). It works by tracking the system time to microsecond precision and logging the time differences and accumulated time as it hits different parts of the code. Since it creates meaningful, reproducible results, it can be used to accurately assess the effect of code changes and measure progress toward a known goal.
BTTimeLog has preprocessor conditionals that allow the logging code to be removed completely from production code. Each logging call is accompanied by a log level parameter that can be used to filter out calls that fall below a certain level. You can also fall back to NSLog using conditionals.
To use BTTimeLog, compile BTTimeLog.m into your app and add BTTimeLog.h to your .pch file or any other file that is globaly #imported. I normally maintain a separate AppGlobals.h file for this sort of thing (string constants, view tags, categories, etc.)
At various places in your app, add macro calls of the form
The first argument sets the level of the log call. The number should be between 0 and 7, with 7 being the highest level, and so the last one to be removed by filtering. The second argument is a format string. The optional third and subsequent arguments provide data for the format string.
Each line will generate a line of text in the log that looks like this:
The first number is the log level. The second is the time in milliseconds since BTTimeLog was initialized, or since the time was reset. The third number is the time difference in milliseconds since the previous line in the log. Next comes the class and method selector, and finally the string with the parameters substituted. The file and line number are not included, because you don't need them: just search for the method.
Having the class and method selector logged is useful for another reason: the format string can be short and to the point and you can use an identical line of code pasted all over the place. I use "Start" and "End" as strings in the example below at the begining and end of all my methods. Here I've also used several calls in [AppUtility initialiseSpacedout] to narrow down where time is being spent there.
Most of the 600ms spent in applicationDidFinishLaunching: is happening just before the controllers are set up, so I should pay attention to what is in the NIBs and see how the views are being initialized. When I think I have improved the time, I can measure the effect.
If the logging is too verbose, I can turn off logging below a given level globally with a preprocessor variable or an environment parameter, or dynamically via a method call, +setLoggingMinLevel:. All my Start and End lines above are level 3 logs, so by filtering to level 3 that's all I see. Also note that the logging level provided in the call to BTLogString doesn't have to be a constant: you can use an int variable and change it dynamically or even globally, perhaps using another macro to combine a global setting with a local setting.
And if you have some user-initiated or repetitive event that fires off some action that you are trying to measure and minimize, you can reset the elapsed time with:
if you want to show in the log that the time was reset, or
if you want to rest the time silently.
Download BTTimeLog
BTTimeLog is supplied as source and is free to use and improve.