Reading Debug Logs to Determine What's Using CPU TIme

Question

There is a flow running that attempts to insert ~150 opportunities. It is failing with a CPU Time Limit Exceeded error. When I attempt to reproduce the issue using debug on the flow, I'm getting different packages in the error. Sometimes, it will say

 "CANNOT_INSERT_UPDATE_ACTIVATE_ENTITY: webm.webmergeOpportunityTrigger". 

Other times it will say

"CANNOT_INSERT_UPDATE_ACTIVATE_ENTITY: npsp.TDTM_Opportunity". 

Both of those are managed packages. I'm assuming I'm getting an error based on whatever package it was in when it hit the limit and stopped the process, which is why it changes on each run.

I'm trying to figure out where the error is actually happening, and so I enabled debug logs. When I find the lines that say "CLOSE TO LIMIT", the "close to limit" lines always say "LIMIT_USAGE_FOR_NS|(default)|".

Is this telling me that the limit is being hit by code running in the default namespace? I see other LIMIT_USAGE_FOR_NS with other namespace names, and they all have almost no CPU usage.

My ultimate goal is to figure out exactly what is causing the CPU time usage. (I've been pulled in to look at something I didn't create, so I'm flying blind on where to even look.)

12:06:59.963 (16963912183)|LIMIT_USAGE_FOR_NS|(default)| Number of SOQL queries: 10 out of 100 Number of query rows: 125 out of 50000 Number of SOSL queries: 0 out of 20 Number of DML statements: 5 out of 150 Number of Publish Immediate DML: 0 out of 150 Number of DML rows: 240 out of 10000 Maximum CPU time: 10307 out of 10000 ******* CLOSE TO LIMIT

Answer 1

CPU time is, at the moment, a global resource. If package A uses 200ms, then calls package B that uses 12,000ms, then A uses another 100ms, it may trip the CPU limit, even though it was really package B's fault. That's a consequence of the CPU limits being flexible (e.g. you are not strictly cut off at the 10,000ms marker) and the limit being a global limit.

Your best option is to set up a profiling trace flag and see which package appears to be using the most time. I understand that this is tricky, but even the engineers at salesforce.com think so, too. Without going too deep into a subject I only know a scant about, the general suggestion has been that it is hard to determine which milliseconds should be attributed to which namespace, which is why it is a shared global limit to begin with.

To set a profiling trace flag, create a TraceFlag (e.g. in the Developer Console under Debug > Change Log Levels) with all levels set to NONE or INFO, the lowest possible setting, then set Profiling to the highest possible setting. This will give you a relatively terse log that should tell you which package(s) are responsible for spending the most time, and which methods you've written that are contributing to the most time use.