5

We are running through a very strange behavior. Actually, we are using Salesforce CPQ. While updating the Quote we started getting "Apex CPU time limit exceeded.." error.

We debugged and found that there were lot of process builders which were updating related records and each update was executing a different set of execution. So, we have to move process builders into trigger which reduced a lot of time as we moved several DMLs into a single update operation.

But while UAT, we started noticing that still CPU time was high some times...and found that if we set the debug log level to fine, CPU time get increased dramatically by 4-6 seconds.

From this question, How to debug hitting CPU time limit, seems that it's true and debug log level increases the CPU time..

If I enable debugging, then the overhead associated with debugging causes it to hit the CPU limit every time. I opened a case with Salesforce and was told this is by design

I read through this Salesforce help article (https://help.salesforce.com/articleView?id=000232681&language=en_US&type=1) and this behavior is not mentioned anywhere.

Appreciate your help and suggestion!

  • Yes, that's why Salesforce recommends not to use Log Level as Finest during deployment and it is processed in Application Server – Santanu Boral May 16 '18 at 7:09
  • Thanks, so you are saying that we should not set trace level to fine at apex class..Right? – Ayub May 16 '18 at 7:14
  • see, we trace this only for a particular scenario and not for all the time. After testing, put your log level as Info level, more debug level means more processing time. In production, ideally, do not set debug logs. – Santanu Boral May 16 '18 at 7:17
7

In addition to agreeing with Santranu's "yes", also bear in mind that the logging calls themselves consume CPU time as the argument string has to be built whether is is stored or not.

We had logging calls that were consuming 30% of the CPU time because the string building included a JSON.serializePretty call that is relatively expensive for large objects:

System.debug(
        '\n**Saved Range**'
        + '\n' + JSON.serializePretty(range)
        + '\n'
        );

I presume this sort of cost is one of the reasons that Apex collections only output a limited number of values when concatenated into a string.

Borrowing from other logging systems we added our own guard to avoid the calls unless a flag is set:

if (Log.isDebug()) {
    System.debug(
            '\n**Saved Range**'
            + '\n' + JSON.serializePretty(range)
            + '\n'
            );
}

As always though, make measurements before making changes aimed at improving performance - avoid Premature Optimization.

  • Log.isDebug() is there a custom setting behind that enables you to record logging when needed. – Pranay Jaiswal May 16 '18 at 8:30
  • @PranayJaiswal Yes exactly. Pity there isn't a built in mechanism in the platform for that as there is in other frameworks. – Keith C May 16 '18 at 8:58
  • 1
    Also worth noting this question about maps: salesforce.stackexchange.com/questions/46525/…. Dumping a map to a debug log can change the runtime cost of get() from constant, to linear in the size of the map. It stops using hashCode() and starts just iterating through the whole map to do a get()! – Aidan May 16 '18 at 9:16

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.