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

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