How to interpret these tracing numbers?

[MCMartin]

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?

[Breck_Carter]

Can you post a screen shot? Did you look at the graphical plan?

[MCMartin]

The graphical plan from the tracing does not show any runtime info. Of course running the statement in dbisql is quick as expected.

[Former Member]

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).

[MCMartin]

logging_session_id;request_id;start_time;finish_time;duration_ms;connection_number;request_type;statement_id;query_id;cursor_id;sql_code;logging_session_id;query_id;statement_id;user_object_id;start_time;cache_size_bytes;optimization_goal;optimization_level;user_estimates;optimization_workload;available_requests;active_requests;max_tasks;used_bypass;estimated_cost_ms;plan_xml;sql_rewritten;logging_session_id;cursor_id;query_id;isolation_level;flags;forward_fetches;reverse_fetches;absolute_fetches;first_fetch_time_ms;total_fetch_time_ms
4;539572;'2011-07-28 07:59:50.672';'2011-07-28 08:00:09.811';19139;43601530;3;539569;539570;539571;;4;539570;539569;5309;'2011-07-28 07:59:50.671';0;2;9;1;1;20;7;0;1;12;;;4;539571;539570;0;266;0;0;0;1;1

[MCMartin]

Thanks for moving to a comment Mark, I wasn't aware, that the code highligting works also here

[VolkerBarth]

AFAIK, questions, answers and comments are internally quite identical in OSQA - think object-oriented:)

[MCMartin]

Anything to identify from these number?

[Former Member]

Can you post the rows from sa_diagnostic_cursor for this request as well?

[Former Member]

Nevermind, I see the values in your post. Can't see anything here. As Dan mentioned, you may have blocking going on; we're you recording blocking information in your tracing? Otherwise, it's entirely possible the time is just how long the application took to process the row (i.e. held the result set / cursor open for 19 seconds.)

[MCMartin]

There was no blocking for this instance and trying to reproduce this by executing the statement in dbisql is very fast.