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

Martin's gravatar image

Martin
8.6k118151237
accept rate: 14%

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

(28 Jul '11, 03:41) Breck Carter
Replies hidden
Comment Text Removed

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

(28 Jul '11, 04:15) Martin

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

permanent link

answered 28 Jul '11, 22:31

Dan%20Farrar's gravatar image

Dan Farrar
43143
accept rate: 80%

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
(29 Jul '11, 08:16) Martin
Replies hidden
Comment Text Removed

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

(29 Jul '11, 11:30) Martin

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

(29 Jul '11, 11:49) Volker Barth

Anything to identify from these number?

(12 Aug '11, 11:41) Martin

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

(17 Aug '11, 16:45) Tyson Lewis

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

(17 Aug '11, 18:56) Tyson Lewis

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

(18 Aug '11, 04:08) Martin
showing 1 of 7 show all flat view
Your answer
toggle preview

Follow this question

By Email:

Once you sign in you will be able to subscribe for any updates here

By RSS:

Answers

Answers and Comments

Markdown Basics

  • *italic* or _italic_
  • **bold** or __bold__
  • link:[text](http://url.com/ "title")
  • image?![alt text](/path/img.jpg "title")
  • numbered list: 1. Foo 2. Bar
  • to add a line break simply add two spaces to where you would like the new line to be.
  • basic HTML tags are also supported

Question tags:

×11

question asked: 28 Jul '11, 02:59

question was seen: 897 times

last updated: 18 Aug '11, 04:08