Stat Tracker

Saturday, March 22, 2014

Instrument Your Apex Code : DIY Performance Metrics on Force.com

Performance Monitoring on Force.com

There are many instances when you develop on Force.com where you will have to gather performance metrics on your codebase. You may want to log how long a HTTP Callout in Apex code takes, or how long an Apex Trigger runs with complex sharing rules. Gathering these metrics is especially important on the Force.com platform due to Governor Limits and the impact of having long running apex transactions. Unfortunately the native logs on SFDC do not allow you to log more than 20 transactions per user per transaction batch. Also these logs are not easily reportable.

This can present a clear challenge to developers but it can be easily remedied. In this blog post I will show you how you can roll your own Apex performance monitoring framework. You will be able to log performance on your Apex code, easily toggle the monitoring on or off without a deployment of code, and run reports and dashboards on your metric data. All this natively on the Force.com platform! No additional tools or vendor products need apply!

Step 1: Create a Custom Object For Performance Logs

Our first step will be to create a custom object to hold our performance logs. This object will have only a few fields. 

Name - An Autonumber for the transaction in the format of PERF-{00000001}
Apex Class - A string holding the name of the Apex Class for the transaction
Apex Method - A string holding the name of the Apex Method for the transaction
Time in Milliseconds - A number holding the transaction time in milliseconds
Time in Seconds - A formula field based on Time in Milliseconds for showing time in seconds
Notes - Any developer notes you want to add for details about the transaction (Record Ids, etc)
Created By - The user who was executing the code

The total object looks like this. Note: Make sure to "Enable Reports" so we can write native reports!


Bonus: Create a Custom Object Tab and expose the object in your UI if you want.

Step 2: Create a Custom Setting to Toggle Logs On/Off

Now that we have our custom object we need to create a Custom Setting that will allow us to toggle the logs on or off without changing any code. Custom Settings were specifically built to set Application Wide settings like this and is the perfect use case for Custom Settings. We are going to create a Custom Setting called "Global Setting" this is Setting Type "List". 

We are only going to create one custom field called "Log Transactions". 

Once we are done your Custom Setting will look like this:

Step 3: Create our Apex Monitoring Framework Class

Now that we have our data model complete we can build out Apex framework class for monitoring transactions. The class itself is very simple and really only does 3 things: 
1. It automatically logs the transaction time by calculating the time in milliseconds.
2. It reads the Custom Setting to see if logging is set to true.
3. It will insert a log record via DML insert on the System Performance Log.

Here is the complete Apex Class:

public without sharing class SystemPerformanceDAO
{
 public static void insertPerformanceLog(PerformanceTransaction logRec)
  {
    logRec.endTimeMilliseconds = DateTime.Now().getTime();
    Global_Setting__c globalSetting = Global_Setting__c.getInstance('Global_Setting');
    if(globalSetting != null && globalSetting.Log_Transactions__c == true)
    { 
      insert new System_Performance_Log__c(Apex_Class__c = logRec.apexClassName, Apex_Method__c = logRec.apexMethodName, Notes__c = logRec.notes, Time_in_Milliseconds__c = (logRec.endTimeMilliseconds - logRec.startTimeMilliseconds));
    }
  }

  //Class used to maintain the State of the Transaction for use by Apex Classes.
  public class PerformanceTransaction
  {
    public long startTimeMilliseconds {get;set;}
    public long endTimeMilliseconds {get;set;}
    public String apexClassName {get;set;}
    public String apexMethodName {get;set;}
    public String notes {get;set;}
    
    public PerformanceTransaction(String apexClass, String apexMethod, String innotes)
    {
      apexClassName = apexClass;
      apexMethodName = apexMethod;
      notes = innotes;
      startTimeMilliseconds = DateTime.Now().getTime();
      endTimeMilliseconds = 0;
    }
  }
}

Step 4: Instrument our Apex Classes with the Framework

Now that we have our data model and Apex framework classes we can start to instrument our Apex classes and methods. To do this we only add two lines of code to the methods we want to instrument. 

The first line of our Apex methods should invoke the constructor in our framework for a transaction log like this:

SystemPerformanceDAO.PerformanceTransaction performanceLog = new SystemPerformanceDAO.PerformanceTransaction('AccountController','refreshContacts','Account Used: ' + acct.Id);

And the last line of our method should simply invoke our Apex class to log the metric like this:

SystemPerformanceDAO.insertPerformanceLog(performanceLog); 

This makes it very easy for us to add instrumentation to our Apex classes with minimal code. And we don't have to change the code since the framework automatically does that for us by checking the custom setting.

A complete example may something like this:

public with sharing class AccountController
{
    public List<ContactListWrapper> acctContacts {get;set;}
    public Account acct {get;set;}

    public AccountController(ApexPages.StandardController std)
    {
        acct = (Account) std.getRecord();
        acctContacts = new List<ContactListWrapper>();
        List<Contact> contacts = [Select Id, Email, FirstName, LastName from Contact where AccountId =: acct.Id];
        for(Contact c : contacts)
        {
            acctContacts.add(new ContactListWrapper(c));
        }
    }


    public ApexPages.PageReference refreshContacts()
    {
        SystemPerformanceDAO.PerformanceTransaction performanceLog = new SystemPerformanceDAO.PerformanceTransaction('AccountController','refreshContacts','Account Used: ' + acct.Id);
        List<Contact> contacts = [Select Id, Email, FirstName, LastName from Contact where AccountId =: acct.Id];
        for(Contact c : contacts)
        {
            acctContacts.add(new ContactListWrapper(c));
        }
        SystemPerformanceDAO.insertPerformanceLog(performanceLog);       
        return null;
    }
    
    public ApexPages.PageReference saveContactUpdates()
    {
        SystemPerformanceDAO.PerformanceTransaction performanceLog = new SystemPerformanceDAO.PerformanceTransaction('AccountController','saveContactUpdates','Account Used: ' + acct.Id);
        List<Contact> contactUpdates = new List<Contact>();
        for(ContactListWrapper clw : acctContacts)
        {
            if(clw.isSelected)
            {
                contactUpdates.add(clw.acctContact);
            }
        }
        if(contactUpdates.size() > 0)
        {
            upsert contactUpdates;
        }
        SystemPerformanceDAO.insertPerformanceLog(performanceLog);
        return null;
    }

    public class ContactListWrapper
    {
        public boolean isSelected {get;set;}
        public Contact acctContact {get;set;}
        
        public ContactListWrapper(Contact c)
        {
            acctContact = c;
            isSelected = false;
        }
    }
}

Step 5: Instrument our Apex Classes with the Framework

Now that we have our classes instrumented we can use the native Force.com Analytics to build our reports. For this example I create a report to show the average, maximum, and minimum transaction times for each of my controller methods.



Conclusions and Caveats

As you can see in this example, it is fairly simple to roll your own instrumentation on Force.com for performance metrics. One of the caveats is that this approach will consume managed data on the platform. So you will need to monitor your logs data usage and periodically purge the records as needed if you don't have a lot of managed data. 

The other caveat is that this will not work for instrumenting Visualforce Apex controller constructor methods. Visualforce Apex controller constructors do not allow you to perform DML statements.

I hope you found this helpful.