Debugging Apex With Salesforce’s Debug Logs and Checkpoints

‍“90% of coding is debugging. The other 10% is writing bugs” — @bramcohen

Introduction to debug logs in Salesforce

A typical Salesforce log contains a number of things: code execution, debug statements, timestamps and any governor limits you may be running into.

Code Example

The simplest way to get started with logging in Salesforce is to add a debug statement to your code. We’ll use the default Apex Trigger code example found in the Salesforce docs on Writing Your First Apex Class and Trigger.

In the tutorial, we create a custom objects called a Book with a custom field called Price:

public class HelloWorld {
  public static void applyDiscount(Book__c[] books) {
     for (Book__c book : books) {
        book.Price__c *= 0.9;
     }
  }
}

We have a Trigger which applies a discount of 10% whenever you add a new Book:

trigger HelloWorldTrigger on Book__c (before insert) {
  Book__c[] books = Trigger.new;
  HelloWorld.applyDiscount(books);
}

The easiest thing is to add a System.debug() statement to the trigger like so:

trigger HelloWorldTrigger on Book__c (before insert) {
  Book__c[] books = Trigger.new;
  HelloWorld.applyDiscount(books);
  System.debug('my message that I want to show up in the logs');
}

Enabling Logs in Setup

If I add a new Book, the Salesforce Debug Logs will display the statement that I added. Kind of like throwing a print statement in Python. But where do I see this log?

• First, go to Setup and search for Debug Logs.

Next, setup a new Trace Flag. A Trace Flag tells Salesforce to log any activity caused by a particular user.

• Click New Trace Flag. The Traced Entity Name will be the user that we want to capture logs for. You can use your own user login or another user’s depending on who you want to generate the logs for. Typically for debugging you’ll use your own login.

You will also need to set a Debug Level. There are number of debug levels:

LoggingLevel.NONE
LoggingLevel.ERROR
LoggingLevel.WARN
LoggingLevel.INFO
LoggingLevel.FINE
LoggingLevel.FINER
LoggingLevel.FINEST

Salesforce logs are capped at 2MB so you may need to tinker a bit with your log levels to make sure you stay under that limit.

• In this case, we’re just going to set Apex Code to Finest and System to Debug.
  Leave the rest at Info.
• Click Save.

Be sure to note that your Trace has an expiration date and time. Check this if your logs mysteriously stop showing up after a few minutes of debugging.

Viewing Logs in Setup

Now run your trigger again by creating a new Book. When you return to the Debug Logs you should now see logs.

• Reload the Debug Logs page. You should now see logs.
• Click View to open the log.

Once you are here, you now have log output you can look at.

‍

Understanding Log Messages in Salesforce

What's in a log? The debug log has several useful elements:

39.0 APEX_CODE,FINEST;APEX_PROFILING,INFO; CALLOUT,INFO;DB,INFO;SYSTEM,DEBUG;VALIDATION,INFO; VISUALFORCE,INFO;WAVE,INFO;WORKFLOW,INFO
05:02:13.0 (218671)|USER_INFO|[EXTERNAL]|00541000001zI0K|jack+albert@bluecanvas.io|Pacific Standard Time|GMT-08:00
05:02:13.0 (257361)|EXECUTION_STARTED
05:02:13.0 (262162)|CODE_UNIT_STARTED|[EXTERNAL]|TRIGGERS
05:02:13.0 (300519)|CODE_UNIT_STARTED|[EXTERNAL]|01q41000001JanC|HelloWorldTrigger on Book trigger event BeforeInsert for [new]
05:02:13.0 (359311)|HEAP_ALLOCATE|[EXTERNAL]|Bytes:8
05:02:13.0 (764600)|HEAP_ALLOCATE|[72]|Bytes:3
05:02:13.0 (834010)|HEAP_ALLOCATE|[77]|Bytes:152
05:02:13.0 (857019)|HEAP_ALLOCATE|[342]|Bytes:408
05:02:13.0 (875943)|HEAP_ALLOCATE|[355]|Bytes:408
05:02:13.0 (894176)|HEAP_ALLOCATE|[467]|Bytes:48
05:02:13.0 (927154)|HEAP_ALLOCATE|[139]|Bytes:6
05:02:13.0 (945255)|HEAP_ALLOCATE|[EXTERNAL]|Bytes:1
05:02:13.0 (1072442)|HEAP_ALLOCATE|[EXTERNAL]|Bytes:8
05:02:13.0 (1086106)|VARIABLE_SCOPE_BEGIN|[1]|this|HelloWorldTrigger|true|false
05:02:13.0 (1139970)|VARIABLE_ASSIGNMENT|[1]|this|{}|0x612fbadc
05:02:13.0 (1191038)|HEAP_ALLOCATE|[EXTERNAL]|Bytes:8
05:02:13.0 (1198395)|VARIABLE_SCOPE_BEGIN|[1]|this|HelloWorldTrigger|true|false
05:02:13.0 (1214030)|VARIABLE_ASSIGNMENT|[1]|this|{}|0x612fbadc
05:02:13.0 (1219830)|STATEMENT_EXECUTE|[1]
05:02:13.0 (1221599)|STATEMENT_EXECUTE|[2]
05:02:13.0 (1258733)|HEAP_ALLOCATE|[50]|Bytes:5
05:02:13.0 (1285175)|HEAP_ALLOCATE|[56]|Bytes:5
05:02:13.0 (1293649)|HEAP_ALLOCATE|[64]|Bytes:7
05:02:13.0 (1684574)|VARIABLE_ASSIGNMENT|[2]|this.books|[{"IsDeleted":false,"OwnerId":"00541000001zI0KAAU",
"Price__c":100.00,
"Name":"Blog Book Test 1"}]|0x612fbadc
05:02:13.0 (1690698)|STATEMENT_EXECUTE|[3]
05:02:13.0 (3258094)|HEAP_ALLOCATE|[3]|Bytes:1
05:02:13.0 (3277447)|METHOD_ENTRY|[1]|01p4100000HR623|HelloWorld.HelloWorld()
05:02:13.0 (3281108)|STATEMENT_EXECUTE|[1]
05:02:13.0 (3286028)|STATEMENT_EXECUTE|[1]
05:02:13.0 (3291206)|METHOD_EXIT|[1]|HelloWorld
05:02:13.0 (3321524)|METHOD_ENTRY|[3]|01p4100000HR623|HelloWorld.applyDiscount(List<Book__c>)
05:02:13.0 (3350205)|VARIABLE_SCOPE_BEGIN|[2]|books|List<Book__c>|true|false
05:02:13.0 (3484434)|VARIABLE_ASSIGNMENT|[2]|books|[{"IsDeleted":false,"OwnerId":"00541000001zI0KAAU","Price__c":
100.00,     
"Name":"Blog Book Test 1"}]|0x2f08a20a
05:02:13.0 (3493612)|STATEMENT_EXECUTE|[2]
05:02:13.0 (3729368)|HEAP_ALLOCATE|[3]|Bytes:5
05:02:13.0 (3757183)|HEAP_ALLOCATE|[3]|Bytes:4
05:02:13.0 (3766245)|VARIABLE_SCOPE_BEGIN|[3]|b|Book__c|true|false
05:02:13.0 (3869071)|VARIABLE_ASSIGNMENT|[3]|b|{"IsDeleted":false,"OwnerId":"00541000001zI0KAAU",
"Price__c":100.00,
"Name":"Blog Book Test 1"}|0x6857411d
05:02:13.0 (3874120)|STATEMENT_EXECUTE|[3]
05:02:13.0 (3875268)|STATEMENT_EXECUTE|[4]
05:02:13.0 (3917921)|HEAP_ALLOCATE|[4]|Bytes:3
05:02:13.0 (3940194)|HEAP_ALLOCATE|[4]|Bytes:28
05:02:13.0 (4002038)|HEAP_ALLOCATE|[4]|Bytes:28
05:02:13.0 (4194737)|VARIABLE_ASSIGNMENT|[4]|this.Price__c|90.000|0x6857411d
05:02:13.0 (4218164)|HEAP_ALLOCATE|[3]|Bytes:5
05:02:13.0 (4239381)|VARIABLE_ASSIGNMENT|[3]|b|null|
05:02:13.0 (4249224)|METHOD_EXIT|[3]|01p4100000HR623|HelloWorld.applyDiscount(List<Book__c>)
05:02:13.0 (4254931)|STATEMENT_EXECUTE|[4]
05:02:13.0 (4259392)|HEAP_ALLOCATE|[4]|Bytes:45
05:02:13.0 (4309898)|USER_DEBUG|[4]|DEBUG|my message that I want to show up in the logs
05:02:13.4 (4323385)|CUMULATIVE_LIMIT_USAGE
05:02:13.4 (4323385)|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
 Maximum CPU time: 0 out of 10000
 Maximum heap size: 0 out of 6000000
 Number of callouts: 0 out of 100
 Number of Email Invocations: 0 out of 10
 Number of future calls: 0 out of 50
 Number of queueable jobs added to the queue: 0 out of 50
 Number of Mobile Apex push calls: 0 out of 10

05:02:13.4 (4323385)|CUMULATIVE_LIMIT_USAGE_END
05:02:13.0 (7801949)|CODE_UNIT_FINISHED|HelloWorldTrigger on Book trigger event BeforeInsert for [new]
05:02:13.0 (56862492)|CODE_UNIT_FINISHED|TRIGGERS
05:02:13.0 (56876928)|EXECUTION_FINISHED

The first line is the Header. It provides version info and the log levels we set for the various logging categories. It’s here that you can see that your Apex Code log level is set to Finest while Validation is set to Info.

39.0 APEX_CODE,FINEST;APEX_PROFILING,INFO; CALLOUT,INFO;DB,INFO;SYSTEM,DEBUG;VALIDATION,INFO; VISUALFORCE,INFO;WAVE,INFO;WORKFLOW,INFO

The next line provides user info:

USER_INFO|[EXTERNAL]|00541000001zI0K|jack+albert@bluecanvas.io|Pacific Standard Time|GMT-08:00

This user info includes the username of the user which caused the log generating action. It also includes the timezone of that user. (Bryan mentions in his talk a time where knowing timezone information was crucial in squashing a bug!)

Next you can see that execution units have started. An execution unit contains everything happens during a transaction. EXECUTION_STARTED and EXECUTION_FINISHED show the start and end of an execution unit.

05:02:13.0 (257361)|EXECUTION_STARTED
05:02:13.0 (262162)|CODE_UNIT_STARTED|[EXTERNAL]|TRIGGERS
05:02:13.0 (300519)|CODE_UNIT_STARTED|[EXTERNAL]|01q41000001JanC|HelloWorldTrigger on Book trigger event BeforeInsert for [new]

Within transactions you have code units. Code units are “discrete unit of work within a transaction.” Apex classes, triggers, and validation rules are all examples of a code unit.

Each transaction and code unit includes a timestamp and the number of nanoseconds that have transpired since the transaction started (this is the long number in parenthesis after the time stamp). This can be useful for debugging performance issues.

At the very end you get cumulative profiling information including SOQL queries, CPU time and heap size:

05:02:13.4 (4323385)|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
 Maximum CPU time: 0 out of 10000
 Maximum heap size: 0 out of 6000000
 Number of callouts: 0 out of 100
 Number of Email Invocations: 0 out of 10
 Number of future calls: 0 out of 50
 Number of queueable jobs added to the queue: 0 out of 50
 Number of Mobile Apex push calls: 0 out of 10
05:02:13.4 (4323385)|CUMULATIVE_LIMIT_USAGE_END
05:02:13.0 (7801949)|CODE_UNIT_FINISHED|HelloWorldTrigger on Book trigger event BeforeInsert for [new]
05:02:13.0 (56862492)|CODE_UNIT_FINISHED|TRIGGERS
05:02:13.0 (56876928)|EXECUTION_FINISHED

Salesforce has more docs on debug logs which are worth reading.

How to use Checkpoints in Salesforce

You can also use the developer console for debugging. Salesforce has a concept called “checkpoints”.

With checkpoints, you can “investigate the objects in memory at a specific point of execution and see the other objects with references to them.” You can get a dump of variable information at the time of that checkpoint.

• To set a check point, click on the line of code where you want to take the snapshot in the developer console until it shows a little red dot.

If you run your trigger again (in our example by adding a new Book) you can now examine the variable data at that moment.

• In the Checkpoints tab of the developer console, click on the checkpoint to explore the file tree.

Here we can see that the title of the book is Don Quixote and the price is $30 at the point of the checkpoint:

You can set up to 5 checkpoints at once. Using multiple checkpoints can help you figure out where exactly variable information changes. Heap information is also available on checkpoints.

To learn more about checkpoints, check out this documentation.

Salesforce debug log resources

Paid Solutions

There are also some paid solutions that provide advanced debugging solutions.

Salesforce Apex Advanced Debugger

Salesforce sells Advanced Debugger which extends the Force.com IDE plug-in for Eclipse. It allows you to set breakpoints for Apex classes and triggers, view variables, see the call stack, interact with global classes, output results to the Console, and much more.

Illuminated Cloud

Some of the paid IDEs like Illuminated Cloud offer an advanced Apex Debugger as a part of their platform as well.

Videos

As always, the Salesforce community has some amazing resources about Apex debugging. As mentioned above, Appirio’s Bryan Leboff gave a great talk on best practices for debugging Apex which you can watch the full video here:

Further Reading

Jitendra Zaa’s blog has a number of great tutorials and posts about debugging, including videos.

‍

Time to Harness the Power of Debug Logs and Checkpoints in Salesforce Apex!

As we've seen throughout this article, Salesforce's Apex presents unique challenges for debugging. That said, armed with the right knowledge and tools, we believe these challenges can be surmounted effectively!

By getting more familiar with tools like Debug Logs and Checkpoints, you'll gain critical insights into the execution of code units and transactions involved in your application. You'll also uncover profiling information such as SOQL queries, CPU time, and heap size. These are invaluable for troubleshooting your Apex code and enhancing its efficiency.  As you fix your code, you can then use DevOps tools like Blue Canvas to smoothly deploy patches to your Salesforce orgs (we offer a free 14-day trial, sign up here).

It's now time to put theory into practice! Remember that a robust debugging process is key to writing efficient, error-free code. Don't let bugs slow you down - empower your development with the right debugging tools and speed up your deployment cycle together with Blue Canvas. 🚀

‍

-------------

FAQ: Debug Logs in Salesforce

What are Debug Logs in Salesforce?

• Debug Logs in Salesforce are logs that provide valuable insights into the execution of Apex code and transactions. They contain code execution details, debug statements, timestamps, and information about governor limits. Debug Logs are essential for troubleshooting and debugging Apex code.

How can I add debug statements to my Apex code for logging purposes?

• To add debug statements to your Apex code in Salesforce, you can use the System.debug() method. Simply include the desired message or variable in the debug statement. 

How can I view Debug Logs in Salesforce?

• To view Debug Logs in Salesforce, you need to access the Setup menu. Search for "Debug Logs" in Setup, and you'll find the option to view and manage the logs. The Debug Logs page provides a list of logs generated by different users. You can click on "View" to open a specific log and examine its contents.

How can I set up Trace Flags for logging activity by a specific user?

• Trace Flags in Salesforce allow you to specify which user's activity should be logged in the Debug Logs. To set up a Trace Flag, go to Setup and search for "Debug Logs." Click on "New Trace Flag" and specify the user for whom you want to capture logs. Additionally, you need to set the Debug Level, which determines the logging granularity. Save the Trace Flag to start logging activity for the specified user.

Why is it important to keep track of the expiration date and time of Trace Flags?

• Trace Flags in Salesforce have an expiration date and time associated with them. It is essential to note this expiration date and time when setting up Trace Flags because if the expiration is reached, the logging for that specific user will stop. If your logs mysteriously stop showing up after a few minutes of debugging, it's worth checking if the Trace Flag has expired.

What information can I find in Salesforce debug logs?

• Salesforce debug logs contain various information that can help in troubleshooting and understanding the behavior of Apex code. Some of the elements found in the logs include code execution details, timestamps, governor limits, heap allocation, variable assignments, and cumulative profiling information. The cumulative profiling information provides insights into metrics such as the number of SOQL queries, CPU time, and heap size.

Are there any paid solutions for advanced debugging in Salesforce?

• Yes, there are paid solutions available for advanced debugging in Salesforce. Salesforce offers the Advanced Debugger, which extends the Force.com IDE plug-in for Eclipse. It allows setting breakpoints, viewing variables, interacting with global classes, and more. Additionally, IDEs like Illuminated Cloud also provide an advanced Apex Debugger as part of their platform.

Are there any recommended resources for learning more about debugging in Salesforce?

• Yes, here are some recommended resources for learning more about debugging in Salesforce:

• Appirio's Bryan Leboff gave a talk on best practices for debugging Apex, and you can watch the full video for more insights.
• Jitendra Zaa's blog provides tutorials and posts about debugging in Salesforce, including videos that can be helpful in understanding the debugging process.