what is the best and reliable way to find the time taken by SOQL query to execute ? can we rely on SOQL_EXECUTE_BEGIN and SOQL_EXECUTE_END events in the debug log and compare their timestamps to get the execute time of the query ?

  • If your goal is to understand or evaluate soql performance you may also be interested in the soql explain api pilot: salesforce.com/us/developer/docs/api_rest/Content/… – Samuel De Rycke Oct 9 '14 at 21:33
  • you can evaluate soql performance by using the query plan tool from Dev Console. I am more interested in finding how much time query is taking to execute in real time – apn Oct 9 '14 at 21:45

I'd declare a datetime variable just before the query, then do a datetime variable just after the query, then compare the two values.

Something like:

datetime qryStart = datetime.now();
database.query(<query string>);
datetime qryEnd = datetime.now();
//debug number of seconds the query ran
system.debug(logginglevel.WARN, (qryEnd.getTime() - qryStart.getTime()) /1000);
| improve this answer | |
  • Debug log's events SOQL_EXECUTE_BEING and SOQL_EXECUTE_END also has the timestamp. the question is which one to trust ? – apn Oct 9 '14 at 21:46
  • That wouldn't be to hard to figure out. If you debug both of the timestamps and compare them to SOQL_EXECUTE_BEGIN and SOQL_EXECUTE_END you'd have an answer very quickly. My method does save you a bit of work by doing math for you. – mkdjns Oct 9 '14 at 22:58
  • Update: The timestamps are different between my method and the event logs which would be the difference between declaring the variables and the query starting/ending. This suggests that the timestamps on SOQL_EXECUTE_BEGIN and SOQL_EXECUTE_END are more accurate. However, we're talking milliseconds. That may or may not be a big deal to you. – mkdjns Oct 9 '14 at 23:10

Setting the Profiling category on debug logs to FINEST exposes query execution times in the ending of debug logs.

For example the overly-simple anonymous apex: List<Contact> c = [SELECT id FROM Contact WHERE Id != null];

This results in a debug log which right before the end contains:

21:04:45.258|CUMULATIVE_PROFILING|SOQL operations|
AnonymousBlock: line 1, column 1: [SELECT id FROM Contact WHERE Id != null]: executed 1 time in 4 ms

21:04:45.258|CUMULATIVE_PROFILING|No profiling information for SOSL operations
21:04:45.258|CUMULATIVE_PROFILING|No profiling information for DML operations
21:04:45.258|CUMULATIVE_PROFILING|method invocations|
External entry point: public static void execute(): executed 1 time in 7 ms

| improve this answer | |

Have you checked out this tool https://apextimeline.herokuapp.com/

| improve this answer | |

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.