I have done some tracing using Plans_with_statistics type and now during interpretation of the results I am puzzled:
I have an entry in sa_diagnostic_request which shows a duration_ms of 19000 => 19 seconds. I thought a good starting point for analysis, so I had a look at sa_diagnostic_query for the mentioned query_id which shows, that the start_time is nearly identical to the start_time of the request. My Interpretation: the optimizer directly started to process the request so no waiting. Active_requests are below available_requests, estimated_cost_ms for the statement is 12 ms, so expectation is way below 19 seconds.
So I took a look at the sa_diagnostic_cursor for the mentioned cursor_id: first_fetch_time_ms is 1 and total_fetch_time_ms is also 1.
Now I was puzzled, which number to look at to identify which of the steps needed 19 seconds? Optimization directly started, database seems to be able to directly execute the statement and fetching seems to be quite fast. So where was the time spend?
asked 28 Jul '11, 02:59
Can you post the full rows for this request/cursor from the sa_diagnostic_request and sa_diagnostic_cursor tables?
Blocking is a possibility; the duration_ms reports wall clock time for the entire cursor, which ticks away while the cursor is blocked (or held open by the application).
answered 28 Jul '11, 22:31