Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fbtracemgr: add option to trace get/put segment operations issued by the client [CORE3903] #4239

Open
firebird-automations opened this issue Aug 20, 2012 · 5 comments

Comments

@firebird-automations
Copy link
Collaborator

Submitted by: @pavel-zotov

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.

@firebird-automations
Copy link
Collaborator Author

Commented by: @dyemanov

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.

@firebird-automations
Copy link
Collaborator Author

Commented by: @dyemanov

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

@firebird-automations
Copy link
Collaborator Author

Modified by: @dyemanov

summary: fbtracemgr: add setting to evaluate cost of transmitting BLOB data to client side => fbtracemgr: add option to trace get/put segment operations issued by the client

Version: 2.5.2 [ 10450 ] =>

@firebird-automations
Copy link
Collaborator Author

Modified by: @dyemanov

assignee: Vlad Khorsun [ hvlad ]

@firebird-automations
Copy link
Collaborator Author

Commented by: Sean Leyne (seanleyne)

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants