Difference between totals collected by ASA Profiler and analysis of ASA request log

[former_SQLA_member326303]

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

[jeff_albion · Accepted solution]

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;

[Breck_Carter · Accepted solution]

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

[former_SQLA_member326303 · Accepted solution]

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

[Breck_Carter · Accepted solution]

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

[former_SQLA_member326303 · Accepted solution]

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.