Thu, 24 Sep 2015

Debugging Salesforce Apps with Flame Graphs

Salesforce applications can sometimes be difficult to debug. The debug log often has the information you need, but finding it isn't always easy.

For example, in a recent project, I needed to figure out why performing an action from a Visualforce page was causing more SOQL queries than expected, generating warning emails as we neared the governor limit. This was a large application that had been under development for about eight years; many different developers had been involved in various phases of its development.

As with many Salesforce applications that have been through many phases of development, it wasn't obvious how multiple triggers, workflow rules, and Process Builder flows were interrelated.

It was easy enough to figure out which SOQL queries were running multiple times by grepping the debug log, but it wasn't obvious why the method containing the query was being called repeatedly.

In researching ways to analyze call paths, I found Brendan Gregg's work on flame graphs, which visualizes call stacks with stacked bar charts. (You might also be familiar with Chrome's flame charts.)

Visualizing the call path through stacked bar charts turned out to be a good way to make sense of the Salesforce debug log.

So I created Apex Flame to visualize Salesforce debug logs using flame charts or flame graphs.

Here's an example based on the debug log generated from running one of the tests included in the Declarative Lookup Rollup Summaries tool.

Example Flame Graph Reset Zoom Search RollupSummariesSelector.RollupSummariesSelector() (1235996 ns, 0.10%) SObjectSelector.assertIsAccessible() (235478 ns, 0.02%) RollupSummariesSelector.getSObjectFieldList() (1036673 ns, 0.09%) StringBuilder.CSVBuilder.add(String) (4611602 ns, 0.38%) SObjectSelector.getFieldListBuilder() (6141498 ns, 0.51%) SObjectSelector.getFieldListString() (6768212 ns, 0.56%) select Name,Active__c,AggregateOperation__c,AggregateResultField__c,CalculationMode__c,ChildObject__c,ConcatenateDelimiter__c,FieldToAggregate__c,FieldToOrderBy__c,ParentObject__c,RelationshipCriteria__c,RelationshipCriteriaFields__c,RelationshipField__c,CalculateJobId__c,UniqueName__c,CalculationSharingMode__c from LookupRollupSummary__c where CalculationMode__c in :calculationModeNames and ChildObject__c in :childObjectNames and Active__c = true order by ParentObject__c, RelationshipField__c (17721838 ns, 1.47%) RollupSummariesSelector.selectActiveByChildObject(List<RollupSummaries.CalculationMode>, Set<String>) (25244446 ns, 2.09%) RollupService.describeRollups(Schema.SObjectType) (27229671 ns, 2.26%) RollupService.triggerHandler() (28183993 ns, 2.34%) RollupServiceTest3Trigger on Account trigger event AfterInsert for [0011a00000CUUaT] (216806872 ns, 17.98%) RollupServiceTest.. RollupService.RollupService() (4998569 ns, 0.41%) RollupServiceTest3Trigger on Account trigger event BeforeInsert for [new] (111753618 ns, 9.27%) RollupS.. Insert:Account (331363950 ns, 27.48%) Insert:Account SObjectDomain.MockDatabase.hasRecords() (318698 ns, 0.03%) RollupSummaries.Constructor.construct(List<SObject>) (252746 ns, 0.02%) ApexTriggersSelector.getSObjectFieldList() (494428 ns, 0.04%) StringBuilder.CSVBuilder.add(String) (2209819 ns, 0.18%) SObjectSelector.getFieldListBuilder() (2910150 ns, 0.24%) SObjectSelector.getFieldListString() (3082568 ns, 0.26%) select Name,UsageIsBulk,UsageBeforeUpdate,UsageBeforeInsert,UsageBeforeDelete,UsageAfterUpdate,UsageAfterUndelete,UsageAfterInsert,UsageAfterDelete,TableEnumOrId,SystemModstamp,Status,NamespacePrefix,LengthWithoutComments,LastModifiedDate,LastModifiedById,IsValid,Id,CreatedDate,CreatedById,BodyCrc,Body,ApiVersion from ApexTrigger where Name in :names order by Name (6633886 ns, 0.55%) ApexTriggersSelector.selectByName(Set<String>) (10219683 ns, 0.85%) LREngine.RollupSummaryField.isAggregateBasedRollup() (253205 ns, 0.02%) LREngine.RollupSummaryField.isQueryBasedRollup() (333290 ns, 0.03%) LREngine.Context.add(LREngine.RollupSummaryField) (683669 ns, 0.06%) LREngine.RollupSummaryField.isDateOrTime(Schema.DisplayType) (557102 ns, 0.05%) LREngine.RollupSummaryField.isNumber(Schema.DisplayType) (851243 ns, 0.07%) LREngine.RollupSummaryField.isText(Schema.DisplayType) (642769 ns, 0.05%) LREngine.RollupSummaryField.validate() (431676 ns, 0.04%) RollupSummaries.makeTriggerName(LookupRollupSummary__c) (18859039 ns, 1.56%) RollupSummaries.onValidate() (57860434 ns, 4.80%) Rol.. SObjectDomain.handleAfterInsert() (57952353 ns, 4.81%) SO.. SObjectDomain.triggerHandler(SObjectDomain.IConstructable, Boolean, Boolean, Boolean, Boolean, Boolean, List<SObject>, Map<Id,SObject>) (58249145 ns, 4.83%) SO.. SObjectDomain.triggerHandler(System.Type) (59311227 ns, 4.92%) SO.. RollupSummariesTrigger on LookupRollupSummary trigger event AfterInsert for [a051a000002ly2F] (115241071 ns, 9.56%) RollupS.. SObjectDomain.SObjectDomain() (10311621 ns, 0.86%) SObjectDomain.MockDatabase.hasRecords() (3485995 ns, 0.29%) RollupSummaries.RollupSummaries() (2235961 ns, 0.19%) RollupSummaries.Constructor.construct(List<SObject>) (2968808 ns, 0.25%) SObjectDomain.triggerHandler(SObjectDomain.IConstructable, Boolean, Boolean, Boolean, Boolean, Boolean, List<SObject>, Map<Id,SObject>) (3215443 ns, 0.27%) SObjectDomain.triggerHandler(System.Type) (6785400 ns, 0.56%) RollupSummariesTrigger on LookupRollupSummary trigger event BeforeInsert for [new] (48017934 ns, 3.98%) Ro.. Insert:LookupRollupSummary__c (166856163 ns, 13.84%) Insert:Looku.. RollupSummariesSelector.getSObjectFieldList() (452150 ns, 0.04%) StringBuilder.CSVBuilder.add(String) (1558019 ns, 0.13%) SObjectSelector.getFieldListBuilder() (2293678 ns, 0.19%) SObjectSelector.getFieldListString() (2649104 ns, 0.22%) select Name,Active__c,AggregateOperation__c,AggregateResultField__c,CalculationMode__c,ChildObject__c,ConcatenateDelimiter__c,FieldToAggregate__c,FieldToOrderBy__c,ParentObject__c,RelationshipCriteria__c,RelationshipCriteriaFields__c,RelationshipField__c,CalculateJobId__c,UniqueName__c,CalculationSharingMode__c from LookupRollupSummary__c where CalculationMode__c in :calculationModeNames and ChildObject__c in :childObjectNames and Active__c = true order by ParentObject__c, RelationshipField__c (7340162 ns, 0.61%) RollupSummariesSelector.selectActiveByChildObject(List<RollupSummaries.CalculationMode>, Set<String>) (10460284 ns, 0.87%) RollupService.describeRollups(Schema.SObjectType) (10976812 ns, 0.91%) RollupService.triggerHandler() (11852139 ns, 0.98%) RollupServiceTestTrigger on Opportunity trigger event AfterInsert for [0061a00000AjNjf] (377149414 ns, 31.28%) RollupServiceTestTrigger on Oppo.. RollupService.triggerHandler() (1149884 ns, 0.10%) RollupServiceTestTrigger on Opportunity trigger event BeforeInsert for [new] (188822108 ns, 15.66%) RollupServiceTe.. Insert:Opportunity (568896270 ns, 47.19%) Insert:Opportunity RollupActionCalculate.RollupActionCalculate() (1229813 ns, 0.10%) RollupActionCalculate.RollupToCalculate.toServiceRollupToCalculate() (914554 ns, 0.08%) LREngine.LREngine() (11705510 ns, 0.97%) LREngine.IsMultiCurrencyOrg() (1174095 ns, 0.10%) SELECT AccountId, Sum(Amount) lre0 FROM Opportunity WHERE AccountId in :masterIds GROUP BY AccountId (19113729 ns, 1.59%) LREngine.QueryExecutor.query(String, Set<Id>) (19272499 ns, 1.60%) LREngine.WithSharingQueryExecutor.query(String, Set<Id>) (19329423 ns, 1.60%) User Debug: New aggregarte value 100.0 for master 0011a00000CUUaTAAX (971765 ns, 0.08%) User Debug: SOQL is SELECT AccountId, Sum(Amount) lre0 FROM Opportunity WHERE AccountId in :masterIds GROUP BY AccountId (218734 ns, 0.02%) LREngine.rollUp(LREngine.Context, Set<Id>, Boolean) (23289994 ns, 1.93%) LREngine.rollUp(LREngine.Context, Set<Id>) (23341264 ns, 1.94%) LREngine.RollupSummaryField.isAggregateBasedRollup() (172964 ns, 0.01%) LREngine.RollupSummaryField.isQueryBasedRollup() (235926 ns, 0.02%) LREngine.Context.add(LREngine.RollupSummaryField) (520645 ns, 0.04%) LREngine.RollupSummaryField.isAggregateBasedRollup() (213647 ns, 0.02%) LREngine.RollupSummaryField.isDateOrTime(Schema.DisplayType) (433093 ns, 0.04%) LREngine.RollupSummaryField.isNumber(Schema.DisplayType) (291409 ns, 0.02%) LREngine.RollupSummaryField.isText(Schema.DisplayType) (527450 ns, 0.04%) LREngine.RollupSummaryField.validate() (296564 ns, 0.02%) RollupService.createLREngineContexts(List<LookupRollupSummary__c>) (7423909 ns, 0.62%) RollupSummariesSelector.getSObjectFieldList() (439088 ns, 0.04%) StringBuilder.CSVBuilder.add(String) (1518768 ns, 0.13%) SObjectSelector.getFieldListBuilder() (2216018 ns, 0.18%) SObjectSelector.getFieldListString() (2394601 ns, 0.20%) select Name,Active__c,AggregateOperation__c,AggregateResultField__c,CalculationMode__c,ChildObject__c,ConcatenateDelimiter__c,FieldToAggregate__c,FieldToOrderBy__c,ParentObject__c,RelationshipCriteria__c,RelationshipCriteriaFields__c,RelationshipField__c,CalculateJobId__c,UniqueName__c,CalculationSharingMode__c from LookupRollupSummary__c where UniqueName__c in :uniqueNames and Active__c = true order by ParentObject__c, RelationshipField__c (9208942 ns, 0.76%) RollupSummariesSelector.selectActiveByUniqueName(Set<String>) (12026548 ns, 1.00%) RollupSummariesSelector.getSObjectFieldList() (418751 ns, 0.03%) StringBuilder.CSVBuilder.add(String) (1555555 ns, 0.13%) SObjectSelector.getFieldListBuilder() (2244164 ns, 0.19%) SObjectSelector.getFieldListString() (2566370 ns, 0.21%) select Name,Active__c,AggregateOperation__c,AggregateResultField__c,CalculationMode__c,ChildObject__c,ConcatenateDelimiter__c,FieldToAggregate__c,FieldToOrderBy__c,ParentObject__c,RelationshipCriteria__c,RelationshipCriteriaFields__c,RelationshipField__c,CalculateJobId__c,UniqueName__c,CalculationSharingMode__c from LookupRollupSummary__c where CalculationMode__c in :calculationModeNames and ChildObject__c in :childObjectNames and Active__c = true order by ParentObject__c, RelationshipField__c (3684774 ns, 0.31%) RollupSummariesSelector.selectActiveByChildObject(List<RollupSummaries.CalculationMode>, Set<String>) (6684942 ns, 0.55%) RollupService.describeRollups(Schema.SObjectType) (6975134 ns, 0.58%) RollupService.triggerHandler() (7631690 ns, 0.63%) RollupServiceTest3Trigger on Account trigger event AfterUpdate for [0011a00000CUUaT] (21000032 ns, 1.74%) RollupService.triggerHandler() (689974 ns, 0.06%) RollupServiceTest3Trigger on Account trigger event BeforeUpdate for [0011a00000CUUaT] (7372667 ns, 0.61%) Update:SObject (28865245 ns, 2.39%) RollupService.rollup(List<RollupService.RollupToCalculate>) (83997802 ns, 6.97%) Rollu.. RollupActionCalculate.calculate(List<RollupActionCalculate.RollupToCalculate>) (85011182 ns, 7.05%) Rollu.. RollupActionCalculateTest.RollupActionCalculateTest() (3130766 ns, 0.26%) SELECT AnnualRevenue FROM Account WHERE Id = :tmpVar1 (5357048 ns, 0.44%) TestContext.TestContext() (1580402 ns, 0.13%) ApexTriggersSelector.ApexTriggersSelector() (1565665 ns, 0.13%) ApexTriggersSelector.getSObjectType() (246508 ns, 0.02%) SObjectSelector.assertIsAccessible() (746409 ns, 0.06%) ApexTriggersSelector.getSObjectFieldList() (807801 ns, 0.07%) StringBuilder.CSVBuilder.add(String) (9477382 ns, 0.79%) SObjectSelector.getFieldListBuilder() (10872873 ns, 0.90%) StringBuilder.CSVBuilder.getStringValue(String) (236619 ns, 0.02%) StringBuilder.CSVBuilder.getStringValue() (268153 ns, 0.02%) SObjectSelector.getFieldListString() (11221683 ns, 0.93%) SObjectSelector.getSObjectName() (197176 ns, 0.02%) select Name,UsageIsBulk,UsageBeforeUpdate,UsageBeforeInsert,UsageBeforeDelete,UsageAfterUpdate,UsageAfterUndelete,UsageAfterInsert,UsageAfterDelete,TableEnumOrId,SystemModstamp,Status,NamespacePrefix,LengthWithoutComments,LastModifiedDate,LastModifiedById,IsValid,Id,CreatedDate,CreatedById,BodyCrc,Body,ApiVersion from ApexTrigger where Name in :names order by Name (23913926 ns, 1.98%) ApexTriggersSelector.selectByName(Set<String>) (37030248 ns, 3.07%) SObjectSelector.SObjectSelector() (409239 ns, 0.03%) TestContext.isSupported() (41196903 ns, 3.42%) T.. RollupActionCalculateTest.testCalculateAction (1205664192 ns, 100.00%) RollupActionCalculateTest.testCalculateAction all (1205664192 ns, 100%) all

You can drill in by clicking on a statement, or click on Search to highlight statements that match a string.

I'd love to get some feedback from other Salesforce developers. Try out Apex Flame, and let me know what you think.

As for the debugging issue that initially inspired the creation of Apex Flame, it turned out to be the combination of a trigger that wasn't checking whether the old and new values of a field were different, causing it to run code unnecessarily, combined with a workflow rule that was causing the trigger to be called multiple times.

Another recent case in which it turned out to be helpful was in troubleshooting a process builder flow that was failing to update child records as expected. The flow assumed that if the parent record is new (ISNEW()) that it didn't have child records. It turns out this isn't necessarily true because a trigger on the parent object can create child records, and the flow runs after the after insert trigger. The order of execution is documented, but visualizing the execution order made it clear what was causing the unexpected behavior.

tech » salesforce | Permanent Link

Sat, 11 Aug 2012

Kanban for Salesforce

Based on my previous Force.com app for managing Salesforce Cases on a Kanban board, I've built Kanban for Salesforce, a project management tool on the Force.com platform. It uses a custom object for cards so it's not tied to an existing Salesforce native object. Cards can be organizated into sprints.

I've built a proper website for it, and there's an online demo. Check it out at octoberswimmer.com.

tech » salesforce | Permanent Link

Mon, 25 Jun 2012

Kanban Cases Board Updated for Multiple Filters

I've updated my kanban tool for Salesforce Cases to allow filtering Cases by multiple criteria. In addition to Owner, you can now filter by the age of the Case, the Priority, and the Type.

Install CaseBoard Install to a sandbox

tech » salesforce | Permanent Link

Tue, 22 May 2012

Kanban Board for Managing Salesforce Cases

I've started building a tool to manage Salesforce Cases on a kanban board. Each case is a card, and each Status picklist value is a list on which the cases can be organized. You can drag cases around to prioritize and track progression.

The lists are organized left-to-right in the same order that the picklist values are arranged top-to-bottom. There's a custom setting to treat the first picklist value, typically "New", as your backlog. The backlog is hidden by default, and can be shown by clicking the arrow on the top left.

If you use Salesforce Cases, please try it out. I would love to get some feedback and suggestions for features. It's still early in development, but I was able to get off to a good start on the front-end by adapting code from huboard, a great tool for managing github tickets.

Install CaseBoard Install to a sandbox

This is also my first time trying to build my own commercial application on the force.com platform. Thoughts from anyone who has sold applications on the AppExchange would also be appreciated.

Update 2012-05-27: Added better handling of many open Cases.
Update 2012-06-24: Now supports filtering by multiple criteria.
Update 2012-08-11: I've developed a new project management tool not tied to native Cases, Kanban for Salesforce.

tech » salesforce | Permanent Link

Fri, 11 May 2012

git diff for Salesforce static resources

Static Resources in Salesforce are often zip files containing multiple files. If you're keeping static resource under version control using git, here's how to get useful diffs for them whether they are zip files or single text files.

Create a shell script which will identify whether a file is a zip file or not. If so, it should unzip the contents to stdout; otherwise, it should just output the contents of the file. I called it resource-conv.

#!/bin/bash

file -b --mime-type $1 | grep application/zip && unzip -c -a $1 || cat $1

Tell git to use this conversion utility for a new "resource" diff driver:

$ git config [--global] diff.resource.textconv resource-conv

Tell your repo that .resource files should use the "resource" diff driver by adding the following to your .gitattributes:

*.resource diff=resource

tech » salesforce | Permanent Link

Tue, 15 Feb 2011

Resetting Chatter Desktop Configuration on Linux

Configuring Salesforce Chatter with an account in an org that doesn't have Chatter enabled results in an unusable app. Upon start-up, it authenticates against the org, shows an error, "Chatter is not enabled for this organization", then exits.

To restore Chatter to a state where it prompts for the org type, Default or Sandbox, I had to remove the Encrypted Local Store used by AIR apps.

$ rm -rf ~/.appdata/Adobe/AIR/ELS/sfdc-desktop.*

tech » salesforce | Permanent Link

Fri, 07 Nov 2008

Convert 15-character Salesforce IDs to 18-characters IDs with PHP

Saleforce uses 15-character IDs as primary keys for every record. When retrieving an ID over the API, 18-character case-insensitive IDs are returned. Generally, this doesn't cause any problems because the 18-character version can be used anywhere the 15-character one is. One problem arises though when you are storing IDs in a text field. In this case, you may need to convert a 15-character ID into its 18-character version. Salesforce provides a description of how to perform this conversion.

Here is a PHP implementation of the algorithm.

function sf15to18($short) {
   $chunks = str_split($short, 5);
   $extra = '';
   foreach ($chunks as $chunk) {
      $chars = str_split($chunk, 1);
      $bits = '';
      foreach ($chars as $char) {
         $bits .= (!is_numeric($char) && $char == strtoupper($char)) ? '1' : '0';
      }
      $map = 'ABCDEFGHIJKLMNOPQRSTUVWXYZ012345';
      $extra .= substr($map, base_convert(strrev($bits), 2, 10), 1);
   }
   return $short . $extra;
}

tech » salesforce | Permanent Link

The state is that great fiction by which everyone tries to live at the expense of everyone else. - Frederic Bastiat