ApexMagGlass.png
by Anand Narasimhan and Dan Yu

September 2014

Finding, understanding and fixing Apex performance issues can be particularly challenging due to the complexity of working with Apex debug logs. This guide covers the common causes of performance issues, provides best practices and gotchas when analyzing logs using the Developer Console, and explores ways to go beyond traditional log analysis by accessing logs directly via the Salesforce APIs.

Introduction

Force.com is a platform with a multitude of capabilities whereby you can build really compelling end user applications using Visualforce and Apex. However, what can start out as a "cool" application, if not well thought out up front, can soon become a "slow and hard to use" application for the end users due to performance problems.

I and many of my fellow architects (and several of you reading this article) have often been parachuted in to save the day when performance issues happen. Once, when I was at a large strategic customer helping with their service cloud implementation, I needed to apply an understanding of their complete Apex timeline to resolve their issues. From an architecture perspective, the customer implementation was a heavily customized console with lots of real time Apex web service callouts, and dealt with Apex business logic, SOQL, and DML operations. As part of initial load and performance tests, the results for some of the key steps in the business indicated significant performance impact, and they tasked me to help narrow down the problem and provide recommendations / remediations.

Like every developer, the first thing I started to look was a detailed code review to make sure any obvious gotchas were eliminated. Then I went on to reproduce the steps that exhibited slow performance and started to look for patterns. So how does a developer look for patterns? What tools do I use to see what really happens when a user clicks a button or opens a Visualforce page? The rest of this article explores causes of Apex performance problems and some tools and approaches you can use to find and fix them.

Common Performance Bottlenecks for Force.com Apps

Most performance problems fall into a set of common categories. These categories include:

  • Web Service callouts: Callouts can impact performance due to issues with network latency, network stability, and the performance or availability of the external web service.
  • Database queries: SOQL or SOSL statements in your Apex controller or triggers might not be optimal. There have been multiple blog posts about addressing this by tuning your queries, such as:
  • DML statements (cascading effects): Database updates are expensive in general and on Force.com there are a few additional variables in play. For example, Workflow rules, roll-up summary fields and Apex triggers can have subtle dependent effects. Often a combination of these result in a "domino effect" that results in the same workflow being fired twice or even the trigger being invoked twice. For a technique to avoid recursive trigger calls, see this article.
  • Complex Apex processing: Business logic written in Apex is usually expected to run pretty quickly, but often you end up with lots of collection objects and iterations. The atomic operations themselves won't be really expensive but a cumulative total tends to be a big contributor to performance problems.
  • Network connectivity: Often not the first place to look, but sometimes network issues such as latency and redirects might impact performance. See this article for tips on finding and solving network performance issues.
  • Browser performance: Many large enterprises standardize on older versions of browsers and have not been able to catch up to modern browsers. For the service cloud console, a detailed study on browser performance was posted here.

Many of these categories can be investigated using Apex debug logs. Some of these, such as network connectivity and browser issues, might require additional tools and approaches.

Most of the time you’ll be relying on Apex debug logs as your key source of information to find the real cause of the performance issue. It helps to understand what goes into a debug log, and the best ways to analyze debug logs.

Enabling Logs for Salesforce Users and Apex Classes

To use debug logs to find performance issues, you’ll need to enable them. To enable logging and specify log levels for a particular user in your organization, under Setup, go to Monitoring, Debug Logs, Monitored Users. Here you can specify which users will be logged in the debug log when they perform operations. Once you’ve added a user you can further refine what parts of a user operation get logged by specifying log filters for that user. See Monitoring Debug Logs for more details on working with user-level logs.

To enable logging for an Apex class or trigger, under Setup, go to Develop, Apex Classes (or Apex Triggers). Find the class or trigger you want to log, and on the detail page of that class or trigger, go to the Log Filters tab and click Override Log Filters. Here you can set the log filters that will get used when the class or trigger is called.

Remember that all class methods and triggers in the execution path inherit the debug log filters from the class that called them, unless the class or trigger has been set to override the debug log filters. Similarly, all methods and triggers in the execution path inherit the user-level log filters you’ve set, unless you manually override the log filters on the class or trigger. See Debug Log Filtering for more details on how debug filter settings get inherited or overridden.

As for which log filter levels to use? This will depend on your scenario, but it helps to think of logs as a series of categorized events, where the filter level controls which categories you want to see. For detailed information on each log level, see Setting Debug Log Filters.

Logs as Events

Since developers write anything and everything to the debug logs, this can generate a lot of noise, which can make it extremely hard to filter out the noise from the signals. While logs certainly can generate a lot of information, it’s important to understand that much of this information can be grouped together and thought of as events.

Adam Wiggins (co-founder of Heroku) wrote an excellent blog post called the 12-Factor app. One of the characteristics of a 12 factor app is to treat your logs as event streams. Apex debug logs can be thought of as a stream of events associated with user actions. Once you learn to look for events in logs, you can predictively look for certain types of events and filter out the noise.

Apex Debug Log Events

Let's take a quick look at a snippet of debug log to understand how it's structured as events.

32.0 APEX_CODE,DEBUG;APEX_PROFILING,INFO;CALLOUT,INFO;DB,INFO;SYSTEM,DEBUG;VALIDATION,INFO;VISUALFORCE,INFO;WORKFLOW,INFO
11:47:46.030 (30064000)|EXECUTION_STARTED
11:47:46.030 (30159000)|CODE_UNIT_STARTED|[EXTERNAL]|TRIGGERS
11:47:46.030 (30271000)|CODE_UNIT_STARTED|[EXTERNAL]|01qD00000004JvP|myAccountTrigger on Account trigger event BeforeUpdate for [001D000000IzMaE]
11:47:46.038 (38296000)|SYSTEM_METHOD_ENTRY|[2]|System.debug(ANY)
11:47:46.038 (38450000)|USER_DEBUG|[2]|DEBUG|Hello World!
11:47:46.038 (38520000)|SYSTEM_METHOD_EXIT|[2]|System.debug(ANY)
11:47:46.546 (38587000)|CUMULATIVE_LIMIT_USAGE
11:47:46.546|LIMIT_USAGE_FOR_NS|(default)|
Number of SOQL queries: 0 out of 100
Number of query rows: 0 out of 50000
Number of SOSL queries: 0 out of 20
Number of DML statements: 0 out of 150
Number of DML rows: 0 out of 10000
Number of code statements: 1 out of 200000
Maximum heap size: 0 out of 6000000
Number of callouts: 0 out of 10
Number of Email Invocations: 0 out of 10
Number of fields describes: 0 out of 100
Number of record type describes: 0 out of 100
Number of child relationships describes: 0 out of 100
Number of picklist describes: 0 out of 100
Number of future calls: 0 out of 10

11:47:46.546|CUMULATIVE_LIMIT_USAGE_END

11:47:46.038 (38715000)|CODE_UNIT_FINISHED|myAccountTrigger on Account trigger event BeforeUpdate for [001D000000IzMaE]
11:47:47.154 (1154831000)|CODE_UNIT_FINISHED|TRIGGERS
11:47:47.154 (1154881000)|EXECUTION_FINISHED

This snippet of the Apex debug log captures the log output when an Apex trigger gets called due to an Account being updated. Each time-stamped log line corresponds to a debug event.

In the above snippet, the log lines starting with CODE_UNIT_STARTED and ending with CODE_UNIT_FINISHED represent the overall execution event when the myAccountTrigger Apex trigger was called on an Account update. The log lines within that set represent the set of events that occurred as part of executing the trigger code (in this simple example, just a System.debug statement).

For more details on understanding the different log line components and events, see Understanding the Debug Log and Working with Logs in the Developer Console.

Using the Force.com Developer Console

The Developer Console provides many different features for working with debug logs. Becoming a Developer Console expert will help in being able to quickly see and understand all the events in your log files.

The Developer Console makes it easy to filter your debug logs, similar to setting filters for a user or a class. When you open a debug log, in the Execution Log view, you can easily apply a filter to show only the parts of the execution log that pertain to the event(s) you’re interested in. For example, if you were specifically looking for only events related to DML operations, you might want to filter on “DML_” to capture DML_BEGIN and DML_END debug events.

Be careful not to filter out too much information, however. If, for example, you checked Debug Only to filter out everything that’s not a debug statement, you might end up with log lines like the following:

16:11:47:376 USER_DEBUG [6]|DEBUG|Value before update: 100
16:11:50:344 USER_DEBUG [12]|DEBUG|Value before update: 200

It’s hard to tell from this what events occurred, or even how many events occurred, since it’s only showing user debug events added in the code, without any contextual information. Additionally, this might appear like there was a gap of almost 3 seconds without activity, which is misleading (we discuss causes of misleading time gaps in Gaps in Debug Logs below).

Don’t forget that you can customize your console to fit your needs, by using console perspectives. For example, if you’re primarily viewing debug logs, you might find the “Log Only” perspective helpful in providing an uncluttered view of just the log output. See more details about console perspectives here.

Analyzing Logs in the Developer Console

For each log line, the Developer Console lets you drill in and analyze specific information about each event. You can see what triggered the event, down to the corresponding line of code if applicable. When you’ve isolated a particular event that’s causing performance problems, you can analyze the specific log event to find, say, a SOQL query that needs to be tuned. To start analyzing, use the Execution Overview view in the Developer Console, and in particular, look at the timeline view.

To begin analyzing the Apex timeline, you’ll need to collect debug information that matches the events that occur when the performance issue occurs. Enable logging for a user that is able to reproduce the problem and have the user perform the operation you want to analyze. Access the user’s debug log in the Developer Console.

In the Developer Console, you can access the timeline view for the log by clicking on the Timeline tab in the Execution Overview panel. This will give you a visual representation of the duration for each type of transaction.

ApexDC1.png

In the timeline you can look for any unexpected transactions. For example, if you notice a large number of DML transactions, taking up an unexpected amount of the total execution time, it’s probably worth investigating why that’s happening.

Once you’ve identified transactions in the timeline that might be impacting performance, selecting the transaction in the timeline lets you get more details using the Stack Tree panel and the execution log. By drilling into the source of the event, you can pinpoint the exact lines of code that are causing the event, which you can then isolate and debug and tune.

ApexDC2.png

Force.com Performance Profiling Using the Developer Console goes into more detail on the overall process of using the Developer Console find performance issues.

After you’re done analyzing, don’t forget to disable debug logs for the user, so that the organization is not collecting excessive debug information that’s no longer needed.

Why Am I Seeing Time Gaps in Debug Logs?

Unfortunately, there are scenarios where the debug log might appear to be missing detailed information. This is usually due to gaps in the debug log -- notable time gaps between events in the range of tens to hundreds of milliseconds.

You need to be aware of the causes of these gaps so that you don’t mis-interpret them as cues into performance issues.

Causes of Debug Log Gaps

Log gaps are not caused by aberrant behavior in your app. In some cases the cause of the log gap is simple to correct.

Log gaps can occur for the following reasons:

  • Log levels not specific enough: If your debug log level filters aren’t set to the appropriate levels, the Developer Console will automatically filter out finer-level events, making it sometimes appear as if there were gaps in execution. This is remedied by setting your log levels appropriately.
  • Log file truncation: There is a maximum log limit of 2MB per log file. When the limit is hit, detailed log lines are removed, which can result in what looks like gaps in the log. The log lines can be removed from any location, not just the start of the debug log. Note that when lines are removed due to the log file limit, they are removed in ENTRY / EXIT pairs. For example, the lines for a SYSTEM_METHOD_ENTRY and SYSTEM_METHOD_EXIT might both get removed, in order to keep the log view consistent. An example of this sort of gap might look like:
08:37:13.187 (1187280618)|CONSTRUCTOR_EXIT|[984]|01p|<init>(ApexPages.StandardSetController)
08:37:13.620 (1620485725)|METHOD_EXIT|[5181]|01p|CartDetailViewController.searchCartLineItems()

Whereas the actual complete log without truncation would look like:

08:37:13.187 (1187280618)|CONSTRUCTOR_EXIT|[984]|01p|<init>(ApexPages.StandardSetController)
08:37:13.187 (1187311551)|SYSTEM_METHOD_ENTRY|[993]|ApexPages.StandardSetController.cancel()
08:37:13.620 (1620440718)|SYSTEM_METHOD_EXIT|[993]|ApexPages.StandardSetController.cancel()
08:37:13.620 (1620485725)|METHOD_EXIT|[5181]|01p|CartDetailViewController.searchCartLineItems()
  • Apex component initialization cost in Visualforce pages: Using Apex properties or methods in Visualforce pages can sometimes hide the time taken for the component initialization code. For example, if you had a Visualforce component that called getParamValue() in the Apex controller via <apex:outputText value=”{!paramValue}”> the debug log would not catch the initialization cost of <apex:outputText/>.
  • Static Apex methods: Calling static Apex methods will reference the static method in a different class, which might result in a cache miss and thus an extra compilation cost that will not be tracked in the debug log. For example, if you defined the following:
public class ClassA {
	public void call() {
		ClassB.staticCall();
	}
}
public class ClassB {
	public static void staticCall() {}
}

and created an instance of ClassA and called call():

ClassA obj = new ClassA();
obj.call();

the call to the static ClassB method staticCall() might reflect a gap in the debug logs.

  • Salesforce Apex processing issues: In some scenarios, things like extra compilation cost (perhaps due to converting a large amount of Apex code into bytecode) or a garbage collection sweep can result in a gap in the debug log.

All of these issues can cause gaps in the debug log, and are not indicative of any performance problems by themselves. Keep these in mind when reviewing your debug logs.

System.Debug can Skew Log Results

While not a cause of gaps, heavy use of System.Debug methods can result in extra overhead, which in turn can result in masking of performance problems in the debug log.

When using System.Debug and generating debug logs with SYSTEM debug flags set to DEBUG or finer, there is a small amount of overhead generated to create and log the System.Debug messages. An excessive amount of System.Debug calls (for example, in a frequently run loop with many iterations) will have an impact on your debug logs and can make it harder to track down the real performance bottlenecks.

Handling Large Force.com Debug Logs Using the Apex Timeline Tool

Occasionally, you might find yourself with a particularly tricky performance issue that is generating a very large log, or several very large logs, and simply analyzing them in the Developer Console isn’t giving you the clearest view of the situation.

One approach is to view the logs in a different tool that can give you a broader picture. The Developer Console lets you download log files locally, which can help if you just need to view the logs outside of the Developer Console. But, thanks to OAuth and the Tooling API, you can also directly connect to your debug logs and view the data the way you want, when you want.

One of the developers in our community wrote the Apex Timeline tool that connects to your organization using OAuth, uses the Tooling API to load any cached debug logs (or you can upload a local log file), displays the timeline of the log, and wraps this all in an app hosted on Heroku:

ApexTimeline1.png

You can try it yourself by going to https://apextimeline.herokuapp.com and logging in using your org (or checking the sample log).

In the Timeline tab you can see each event displayed on a timeline, giving you a graphical representation of how long each event took. The DB Operations tab lists SOQL query, DML and Trigger information for the log. Finally the JSON tab shows a JSON representation of the data associated with the log.

ApexTimeline2.png

This tool was made with the help of the Java Play framework and the D3 JavaScript timeline plugin.

Let’s look at some of the details of how this tool was developed.

Connecting to Your Organization Using OAuth

Since we want an app that can access the logs directly, the first step is to connect to the user's organization. We use OAuth, which provides a standardized, secure authorization protocol you can use to allow access to your org from another app.

Once we’ve authorized the connection to Salesforce, we have an access token we use to make Tooling API calls.

See Authenticating Apps with OAuth and Digging Deeper into OAuth 2.0 on Force.com for more details on using OAuth.

Getting a List of Log Files

Once connected, we need a list of the currently available logs. This is simply a matter of using the Tooling API to make a query against the ApexLog object. The following Java snippet uses the Tooling API query REST resource to get a list of ApexLog records that can then be parsed and displayed in the UI:

private static final String GET_LOGS_URL_BASE= "/services/data/v31.0/";
private static final String GET_LOGS_QUERY = 
      "SELECT Id,LogUser.Name,LogUserId,LogLength,Operation," +
"Application,Status,DurationMilliseconds,StartTime " +	
"FROM ApexLog ORDER BY SystemModstamp desc LIMIT 100";
		
...
										 
// Use Java Play to issue REST API query using previously obtained OAuth token
JsonNode json = request().body().asJson();
String sessionId = json.findPath("sessionId").getTextValue();
String instanceUrl = json.findPath("instanceUrl").getTextValue();
return async(play.libs.WS.url(instanceUrl+GET_LOGS_URL_BASE+"tooling/query/")
			.setQueryParameter("q",GET_LOGS_QUERY)
			.setHeader("Authorization", "Bearer "+sessionId)
			.setHeader("Accept","application/json")
			.get()
			.map(new Function<WS.Response, Result>() {
						public Result apply(WS.Response response) {
							return ok(response.asJson());
						}
				}
			)

Once the ApexLog information is retrieved, the data is parsed and the list of available logs is shown in the UI. The user can then pick a log to analyze.

Using the Force.com Tooling API to Access Raw Log Data

Once a user selects a debug log to analyze, we take the ApexLog ID and retrieve the raw log lines using the Tooling API. The following Java snippet uses the Debug Log REST resource to retrieve the raw log file contents given an ApexLog ID:

private static final String GET_RAW_LOG_URL = "tooling/sobjects/ApexLog/";

...

String tokenStr = request().cookie("token").value();
JsonNode sessionToken = Json.parse(tokenStr);
String sessionId = sessionToken.get("access_token").getTextValue();
String instanceUrl = sessionToken.get("instance_url").getTextValue();
return async(play.libs.WS.url(instanceUrl+GET_LOGS_URL_BASE+GET_RAW_LOG_URL+logId+"/Body/")
			.setHeader("Authorization", "Bearer "+sessionId)
			.get()
			.map( new Function<WS.Response, Result>() {
					public Result apply(WS.Response response) {
					...							
					}
				  }
            )

Once the raw log file data is retrieved, this can be parsed and presented as needed. This app uses a SFDCLogParser utility class to parse the log file for stats (for example, looking for SOQL or DML event types in a given log line), and also to flatten the log file data into a JSON format suitable for the D3 timeline widget.

The source code for the tool is available on GitHub. See the Tooling API Developer’s Guide for more information on the Tooling API.

Summary

Apex performance problems can be difficult to track down. Salesforce provides detailed logs that help you isolate the problem, but it’s important to understand how log events are represented. You also need to be careful not to mis-interpret log file gaps and System.Debug overuse when analyzing your log files. Fortunately, Salesforce makes it easy to work with log files with built in tools like the Force.com Developer Console, custom tools like the Apex Timeline, or you can even access log files programmatically via the Tooling API.

Other Resources

About the Authors and CCE Technical Enablement

Anand Narasimhan is a Program Architect working with salesforce.com's strategic customers driving customer's success and adoption with the platform. He's been at salesforce.com for 6.5 years and has been involved in some of the largest, most complex global deployments in the Financial Services, Retail, Telco and Logistics industries.

Dan Yu is a Technical Writer within the Technical Enablement team of the salesforce.com Customer-Centric Engineering group. The team’s mission is to help customers understand how to implement technically sound Salesforce solutions. Check out all of the resources that this team maintains on the Architect Core Resources page of Developer Force.