Issue Details (XML | Word | Printable)

Key: CORE-3903
Type: Improvement Improvement
Status: Open Open
Priority: Major Major
Assignee: Vlad Khorsun
Reporter: Pavel Zotov
Votes: 0
Watchers: 2
Operations

If you were logged in you would be able to see more operations.
Firebird Core

fbtracemgr: add option to trace get/put segment operations issued by the client

Created: 20/Aug/12 08:32 AM   Updated: 20/Aug/12 04:14 PM
Component/s: TRACEMGR
Affects Version/s: None
Fix Version/s: None


 Description  « Hide
Consider the following test case:

1. DDL:
------------
recreate table t(b blob);
commit;
insert into t select list(gen_uuid()) from rdb$fields,rdb$fields,rdb$fields;
commit;

2. Run trace and reconnect to that database via TCP:
-------------------------------------------------------------------------
isql localhost:C:\1INSTALL\FIREBIRD\Data\T0.FDB
Database: localhost:C:\1INSTALL\FIREBIRD\Data\T0.FDB
SQL> set blob all;
SQL> set stat on; out nul; select b from t; commit; out;

3. Then open trace log:
---------------------------------
2012-08-20T07:21:02.1870 (500:0212C088) EXECUTE_STATEMENT_START
        C:\1INSTALL\FIREBIRD\DATA\T0.FDB (ATT_2, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
        C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1096
                (TRA_9, CONCURRENCY | WAIT | READ_WRITE)

Statement 37:
-------------------------------------------------------------------------------
select b from t

2012-08-20T07:21:02.1870 (500:0212C088) EXECUTE_STATEMENT_FINISH
        C:\1INSTALL\FIREBIRD\DATA\T0.FDB (ATT_2, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
        C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1096
                (TRA_9, CONCURRENCY | WAIT | READ_WRITE)

Statement 37:
-------------------------------------------------------------------------------
select b from t
1 records fetched
      0 ms, 5 fetch(es)

Table Natural Index Update Insert Delete
************************************************************************************
T 1

2012-08-20T07:21:58.8900 (500:0212C088) CLOSE_CURSOR
        C:\1INSTALL\FIREBIRD\DATA\T0.FDB (ATT_2, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
        C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1096

The time between EXEC_STT_START and FINISH is about 0 ms - this is how long FB-engine extracts BLOB data but NOT how long these data were transmitted to client.
The full time in that sample is DATEDIFF(millisecond from <EXECUTE_STATEMENT_START> to CLOSE_CURSOR).

It will be useful if we have some option in trace config (setting like "print_blob_perf") that will allow us to see in trace full time of BLOB handling, i.e. not only extracting time on server side.

 All   Comments   Change History   Subversion Commits      Sort Order: Ascending order - Click to sort in descending order
Dmitry Yemanov added a comment - 20/Aug/12 08:52 AM
You're wrong here:

> The time between EXEC_STT_START and FINISH is about 0 ms - this is how long FB-engine extracts BLOB data

reading blob contents is not (and cannot be) included in the statement stats. It can be reported as separate trace events though. In other words, tracing execution of blob API calls at the server side (when they're issued explicitly by the client) could be possible. However, tracing remote transmission (network interface) is impossible. So your request can be satisfied only partially.

Dmitry Yemanov added a comment - 20/Aug/12 09:11 AM
I have adjusted the ticket title to represent what could be done. The remaining question is whether it should be done and how.

Currently we trace statement execution and fetch events but their stats may not include I/O required to read or write blob contents (unless blobs are involved in expressions). Logging the get/put segment API calls could be possible, but the output is likely to be bulky - one log entry per up to 32KB of blob data (it means at least 30 log entries per every megabyte read or written) - and it would turn the trace output from kinda "object-based" to "data based". We could also trace only create/open and close events for blobs and report the accumulated stats inside the close blob event (reported read and write I/O will be separated but execution time combined).

Sean Leyne added a comment - 20/Aug/12 04:14 PM
Dmitry,

This type of request crossed-the-line of tracking SQL operations into logging/tracking *all* server operations. When does it end? Logging performance of each cache read vs. disk read, read of data row vs. read of index data...