Sometimes we see huge difference between totals collected by ASA Profiler and analysis of ASA request log via stored procedure sa_get_request_profile. We capture data for all connections without any filters.

Our application is written on PowerBuilder v12 and used ODBC.
Also we use ASA version 9.

For example please see picture: alt text Profiler gets 213 msecs for 29 invocations of procedure sp_claim_d_claim_main, while Request Log shows 383564 (!) msecs for same executions.
These data were collected for the same runs of stored procedure.

Returned result set is not huge : 10-20 rows.

asked 28 Mar '13, 11:47

Ilia63's gravatar image

Ilia63
821303454
accept rate: 16%


See: http://dcx.sybase.com/index.html#sa160/en/dbusage/performance-s-5753386.html

There are separate steps taken by the database when executing a query.


(Note: The following answer is responding with the assumption that the software is minimally SQL Anywhere 10 and that you are using the new diagnostic profiling tools. I unfortunately don't readily have the definition of the system tables for ASA 9's 'tracing' capabilities and a query to get back the same results. However, I believe the explanation of the behaviour remains the same).

The Application Profiling / Diagnostic Tracing 'Summary Tab' examines how long a statement took to execute/materialize inside the database server / optimizer (PREPARE / DESCRIBE / OPEN). The sa_get_request_profile procedure from a request level log additionally looks at how long you held a cursor open for / retrieve results back into your application (FETCH / CLOSE).

The same cursor results are also stored in the Application Profiling / Diagnostic Tracing tables, although I don't believe these times are displayed readily in the Sybase Central view.

Here's a sample SQL query against the diagnostic tracing data tables to get at the 'cursor result' timings, and should be similar times to what you see in sa_get_request_profile:

 select top 10
          sdr.connection_number,
          sdr.request_id,
          sdc.cursor_id,
         sdc.total_fetch_time_ms,
         sdr.start_time,
         sdr.finish_time,
         sdr.duration_ms
    from sa_diagnostic_cursor sdc,
         sa_diagnostic_request sdr
   where sdr.cursor_id = sdc.cursor_id
order by sdc.total_fetch_time_ms desc;
permanent link

answered 28 Mar '13, 17:13

Jeff%20Albion's gravatar image

Jeff Albion
10.7k171174
accept rate: 24%

edited 28 Mar '13, 17:24

I believe that Ilia63 is comparing the execution profiler with request level logging. The execution profiler has been around a long time (and still is), and is not to be confused with application profiling or database tracing (although such confusion is natural given the new Sybase Central dialog design).

(28 Mar '13, 18:07) Breck Carter
Replies hidden

Thanks. But is there a possibility to analyze the RL-file to get "how long a statement took to execute/materialize inside the database server"? For example, using a tracetime.pl-script (or a similar script)?

(29 Mar '13, 07:43) Ilia63
1

AFAIK request level logging in Version 9 was limited to measuring and recording requests at the client-server boundary and had no ability to peer inside the server and look at what's going on. In particular, if the client application called a stored procedure, only the request and (eventual) response is recorded, which may very well account for the difference you are seeing; i.e., there is a LOT of client-server interface activity required to get a result set back to the application, above and beyond the actual procedure call down inside the server. The execution profiler, on the other hand, doesn't care about the client side, it only looks at what's going on inside, which probably accounts for the huge difference (I think Jeff is saying the same thing, albeit in perhaps a different context). You can take away this fact: Any processing you can push down into the server, if it reduces the client-server traffic, will benefit performance; see http://sqlanywhere.blogspot.ca/2011/07/thursday-quote-michael-stonebraker.html

FWIW request-level logging in SQL Anywhere 10 (and 11 and 12 and 16) is much more powerful. It has the ability to peer inside; see http://dcx.sybase.com/index.html#sa160/en/dbadmin/zr-database-dbengine.html

(29 Mar '13, 09:32) Breck Carter

If connection parameter LCLOSE=NO, then
results of ASA Profiler = results of ASA request log

P.S. LazyClose (LCLOSE) connection parameter:
Controls whether cursor requests are queued until the next request or performed immediately. When this connection parameter is set to YES or AUTO, cursors are not closed until the next database request.
Default = AUTO.

(23 Apr '13, 03:16) Ilia63
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:

×102
×11

question asked: 28 Mar '13, 11:47

question was seen: 1,217 times

last updated: 23 Apr '13, 03:16