1

Could someone explain me how many times a single trigger is fired when a single record is updated? I cannot paste the whole debug log because of it's size this is just a part of it.

12:35:37.830 (28830076751)|CODE_UNIT_STARTED|[EXTERNAL]|01qt000000001NS|SoM_RequestComplete on SoM_Request trigger event AfterUpdate|__sfdc_trigger/SoM_RequestComplete
12:35:37.830 (28830114625)|HEAP_ALLOCATE|[EXTERNAL]|Bytes:8
12:35:37.830 (28830124547)|HEAP_ALLOCATE|[EXTERNAL]|Bytes:8
12:35:37.830 (28830152111)|HEAP_ALLOCATE|[EXTERNAL]|Bytes:4
12:35:37.830 (28830160112)|VARIABLE_SCOPE_BEGIN|[1]|this|SoM_RequestComplete|true|false
12:35:37.830 (28830185850)|VARIABLE_ASSIGNMENT|[1]|this|{}|0x438382e5
12:35:37.830 (28830223024)|HEAP_ALLOCATE|[EXTERNAL]|Bytes:4
12:35:37.830 (28830232730)|VARIABLE_SCOPE_BEGIN|[1]|this|SoM_RequestComplete|true|false
12:35:37.830 (28830249132)|VARIABLE_ASSIGNMENT|[1]|this|{}|0x438382e5
12:35:37.830 (28830258330)|STATEMENT_EXECUTE|[1]
12:35:37.830 (28830272527)|STATEMENT_EXECUTE|[4]
12:35:37.830 (28830279310)|STATEMENT_EXECUTE|[5]
12:35:37.830 (28830294526)|HEAP_ALLOCATE|[5]|Bytes:4
12:35:37.830 (28830322526)|VARIABLE_SCOPE_BEGIN|[5]|completeRequest|Set<Id>|true|false
12:35:37.830 (28830359021)|VARIABLE_ASSIGNMENT|[5]|completeRequest|[]|0x14d58fa2
12:35:37.830 (28830367543)|STATEMENT_EXECUTE|[6]
12:35:37.830 (28830380611)|HEAP_ALLOCATE|[6]|Bytes:4
12:35:37.830 (28830399220)|VARIABLE_SCOPE_BEGIN|[6]|holdId|List<Id>|true|false
12:35:37.830 (28830431330)|HEAP_ALLOCATE|[EXTERNAL]|Bytes:4
12:35:37.830 (28830444196)|VARIABLE_ASSIGNMENT|[6]|holdId|[]|0x321af56f
12:35:37.830 (28830450872)|STATEMENT_EXECUTE|[7]
12:35:37.830 (28830465943)|HEAP_ALLOCATE|[7]|Bytes:4
12:35:37.830 (28830478041)|VARIABLE_SCOPE_BEGIN|[7]|completedTruckDecalReqs|Map<Id,SoM_Request__c>|true|false
12:35:37.830 (28830500275)|VARIABLE_ASSIGNMENT|[7]|completedTruckDecalReqs|{}|0x31609b7
12:35:37.830 (28830547737)|HEAP_ALLOCATE|[EXTERNAL]|Bytes:8
12:35:37.830 (28830561015)|HEAP_ALLOCATE|[8]|Bytes:8
12:35:37.830 (28830591157)|HEAP_ALLOCATE|[8]|Bytes:5
12:35:37.830 (28830614573)|VARIABLE_SCOPE_BEGIN|[8]|req|SoM_Request__c|true|false
12:35:37.830 (28831303143)|VARIABLE_ASSIGNMENT|[8]|req|{"SoM_Priority__c":true,"SoM_Conditional_Reviews_Complete__c":false,"LastModifiedDate":"2018-12-13T17:35:37.000Z","SoM_Days_on_Hold__c":0,"SOM_Total_Balance__c":0.00,"Item_Requested_Detail__c":"TRANSFER OWNERSHIP 2 (236 more) ...","Name":"RQ-1803-03335","SoM_Existing_License_Inspection__c":true,"SoM_Applicant_Name__c":" ","Current_LGU_Population__c":14674,"SoM_Account_ID__c":"001t000000BK7Ub","CreatedById":"005t0000000lUPAAA2","Dishonored_Payment_in_less_tha_36_months__c":true,"Trucks_for_Fee__c":0,"SOM_Total_Payments__c":2897.65,"SoM_Days_Clock_Ran__c":179,"IsDeleted":false,"SoM_Completed_Date__c":"2018-12-13T00:00:00.000Z","SoM_Clock_Exceeded__c":true,"Issued_Number__c":"03335","SoM_Clock_Update__c":false,"SoM_Received_Date__c":"2018-03-16T00:00:00.000Z","SoM_Clock_Status__c":"Not Started","SoM_Total_Days__c":0,"Launch_Review_Process__c":false,"CreatedDate":"2018-03-20T15:21:17.000Z","Id":"a2Nt00000009YkVEAU","SoM_Account_Name__c":"001t000000BK7UbAAL","SoM_Special_License_Request__c":false,"SoM_Items_Requested__c":"Transfer Ownership ( (59 more) ...","Completed_Clock_Request_Transactions__c":0,"OwnerId":"00Gt0000000J3hbEAC","Conditional_Request__c":true,"RecordTypeId":"012t00000004HuaAAE","SoM_Status__c":"Complete","SoM_Business_ID__c":"0260399","SoM_Additional_Records_in_APEX__c":false,"SoM_Business_County__c":"GR TRAVERSE","SoM_Current_LGU_Account__c":"TRAVERSE CITY","SoM_Church_or_School_Invest_Required__c":false,"Confirm_Complete_Request__c":true,"Is_Portal__c":false,"SystemModstamp":"2018-12-13T17:35:37.000Z","SoM_Requires_Inspection__c":false,"Override_and_Launch_Review_Workflow__c":false,"SOM_Total_Fees__c":2897.65,"Request_ID__c":"R-2353586","SoM_Last_Start_Date__c":"2018-04-04T14:58:44.000Z","LastActivityDate":"2018-04-12T00:00:00.000Z","SoM_Free_Money_Applied__c":false,"SoM_Initials__c":"SG","SoM_Type__c":"Transfer Ownership ( (38 more) ...","SoM_Free_Money__c":false,"SoM_Days_in_Review__c":0,"SOM_Historical__c":false,"LastModifiedById":"005t00000015RAWAA2","Request_Number__c":"_HL_ENCODED_../a2Nt0 (42 more) ..."}|0x73e48ca3
12:35:37.830 (28831345433)|STATEMENT_EXECUTE|[9]
12:35:37.830 (28831411214)|STATEMENT_EXECUTE|[10]
12:35:37.830 (28831426927)|HEAP_ALLOCATE|[8]|Bytes:5
12:35:37.830 (28831447399)|VARIABLE_ASSIGNMENT|[8]|req|null|
12:35:37.830 (28831465246)|STATEMENT_EXECUTE|[19]
12:35:37.830 (28831476591)|STATEMENT_EXECUTE|[22]
12:35:37.831 (28831484811)|CUMULATIVE_LIMIT_USAGE
12:35:37.831 (28831484811)|LIMIT_USAGE_FOR_NS|(default)|
  Number of SOQL queries: 94 out of 100 ******* CLOSE TO LIMIT
  Number of query rows: 279 out of 50000
  Number of SOSL queries: 0 out of 20
  Number of DML statements: 32 out of 150
  Number of DML rows: 54 out of 10000
  Maximum CPU time: 8267 out of 10000 ******* CLOSE TO LIMIT
  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

enter image description here

If you look at the trigger (SoM_RequestComplete) in the log , it is called 9 times!! And there other triggers in a similar way called multiple times. What's happening here functionally is.. a checkbox on child record is updating two fields on parent record, there are other triggers which are fired based on those fields on parent record.

4

A single trigger can run many times in a single transaction. This might occur because of workflow field updates, Process Builder flows, triggers that recursively update records, and particularly for batches of records greater than 100 or 200, depending on API version, as well as using AllOrNone=false on DML operations of more than 1 row.

Since there are different causes, there are different solutions to the problem, which mostly involve using asynchronous code to delay some of the business logic for later, checking to see if records have already been processed (a "recursion blocker", as developers tend to call it), optimizing/streamlining code so that fewer DML updates occur, avoiding mixing code and configuration field updates (e.g. avoid using triggers on objects that have workflow field updates/Process flows), using before insert/before update triggers when possible to avoid recursive updates, and perhaps a few other tricks I haven't immediately thought of.

You might want to try using the Apex Replay Debugger if you want to step through your logs and figure out what happened (note: just install the entire Salesforce Extension Pack for a whole set of cool features), or you can use the Developer Console to look at the log using the graphical environment (turn on the "timeline" feature to see how the execution looks, and the "execution stack" feature to see how the methods/triggers were called). Debugging this situation is going to take a bit of time, but the tools you need are there.

  • 1
    and not to forget, batch partial success AllorNone=false replays of the 'successes" and their downstream consequences as outlined above – cropredy Dec 13 '18 at 23:05
  • @cropredy I had a feeling I was forgetting one... – sfdcfox Dec 13 '18 at 23:15
  • @sfdcfox That explains why that trigger was fired 9 times. There were 8 field updates happening through workflow rules!! – SunnyG Dec 14 '18 at 3:53
  • @sfdcfox one more quick question: Assuming SOQL_EXECUTE_BEGIN is what tells that a query being executed. How does a transaction go through when there over 100 of SOQL_EXECUTE_BEGIN ? I have made an update to record and saw 145 (SOQL_EXECUTE_BEGIN) in the same log. As per the Execution Governor Limits you can issue only 100 SOQL queries within an Execution Cycle is what i heard. – SunnyG Dec 14 '18 at 3:59
  • @SunnyG Partial retries, queries for custom metadata, and other situations may roll back the governor limits to a previous point, or not count against the limits in the first place. Also, the limit is per namespace, so you might see queries from different packages you've installed. In theory, there could be many hundreds of queries executed in the logs without breaking the limits. The system is more complicated than one might imagine at first glance. – sfdcfox Dec 14 '18 at 4:07
2

If you have a workflow field update, the tigger is fired again. Refer to the below excerpt from Triggers and Order of Execution (emphasis mine):

If the record was updated with workflow field updates, fires before update triggers and after update triggers one more time (and only one more time), in addition to standard validations. Custom validation rules, duplicate rules, and escalation rules are not run again.

You may be getting confused with the name of the trigger in the log. Having the name of the trigger does not mean that it's fired those many times. It just mentions the context in which the trigger is getting executed, e.g., variable assignment, heap allocation, etc.

Also note the below mention, that this applies to any type of operation:

The refiring of triggers isn't limited to updates, but applies to all operation types. A workflow field update that fires on record insert will rerun any before and after insert triggers again—as insert triggers.

  • 4
    N.B. I've tested that final paragraph you quoted and it is false. The triggers that run again, run as updates, not inserts. I've filed a bug with the documentation team. – sfdcfox Dec 13 '18 at 22:22
  • Good to know. It seems it was added recently because I do not recollect this being there. – Jayant Das Dec 13 '18 at 22:23
  • yes, doc 'edit' was made in v43 – cropredy Dec 13 '18 at 23:05
  • @cropredy well not too behind then ;) – Jayant Das Dec 13 '18 at 23:39
0

The trigger should be fired only one time for the update made. That said, I have seen several times in my own code where a trigger is fired that updates a record, which in turn causes some other automation to fire. This can sometimes lead to a chain of updates that in turn update the same type of object again in addition to the one that causes the initial fire of the trigger. My understanding is that this can then lead to the trigger being fired multiple times for a single update, though I have only every seen the trigger fire a second time personally.

My recommendation, and the one I received on a similar question previously Here, is to start shoving System.debug messages everywhere in your code and then tracing back through the logs to see what is happening at what time. I'd also strongly recommend filter the logs by debug messages only when doing this process as it is far more readable than seeing the full log dump.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.