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

TRACE: add statistics of actions that were after transaction finished [CORE3598] #3952

Closed
firebird-automations opened this issue Sep 13, 2011 · 10 comments

Comments

@firebird-automations
Copy link
Collaborator

Submitted by: @pavel-zotov

Currently we can not see any statistics about cost of such actions as truncationg GTT and cleaning of temp blobs that take place after commit/rollback.
Discussion about this can be found here (in russian): http://www.sql.ru/forum/actualutils.aspx?action=gotomsg&tid=860810&msg=10871916

2 hvlad: it seems to me that no any change since that topic, isn't ?

Commits: 02adff3 a2e489e

@firebird-automations
Copy link
Collaborator Author

Modified by: @hvlad

assignee: Vlad Khorsun [ hvlad ]

@firebird-automations
Copy link
Collaborator Author

Modified by: @hvlad

Fix Version: 2.5.2 [ 10450 ]

Fix Version: 3.0 Alpha 1 [ 10331 ]

@firebird-automations
Copy link
Collaborator Author

Modified by: @hvlad

Version: 2.5.1 [ 10333 ]

Version: 2.5.0 [ 10221 ]

@firebird-automations
Copy link
Collaborator Author

Modified by: @hvlad

status: Open [ 1 ] => Resolved [ 5 ]

resolution: Fixed [ 1 ]

@firebird-automations
Copy link
Collaborator Author

Modified by: @pcisar

status: Resolved [ 5 ] => Closed [ 6 ]

@firebird-automations
Copy link
Collaborator Author

Modified by: @pavel-zotov

QA Status: No test

@firebird-automations
Copy link
Collaborator Author

Commented by: @pavel-zotov

Prepare and launch trace with config:

enabled = true
time_threshold = 0
log_transactions = true
log_statement_finish = true
print_perf = true

Execute following script on FB 2.5.6 and 3.0:

recreate table test(s varchar(1000) unique);
set count on;
insert into test select rpad('', 1000, uuid_to_char(gen_uuid())) from rdb$types rows 200;
rollback;

On 3.0 trace log for INSERT and ROLLBACK statements will be:

2016-01-20T14:56:19.9670 (4240:00C43AD0) START_TRANSACTION
C:\MIX\firebird\QA\fbt-repo\tmp\E30.FDB (ATT_88, Garbage Collector, NONE, <internal>)
(TRA_189, READ_COMMITTED | REC_VERSION | WAIT | READ_ONLY)

2016-01-20T14:56:20.0140 (4240:00C42930) EXECUTE_STATEMENT_FINISH
e30 (ATT_89, SYSDBA:NONE, NONE, TCPv4:192.168.43.154/1384)
C:\MIX\firebird\fb30\isql.exe:4700
(TRA_188, CONCURRENCY | WAIT | READ_WRITE)

Statement 133:
-------------------------------------------------------------------------------
insert into test select rpad('', 1000, uuid_to_char(gen_uuid())) from rdb$types rows 200
0 records fetched
91 ms, 2 read(s), 165 write(s), 2170 fetch(es), 747 mark(s)

Table Natural Index Update Insert Delete Backout Purge Expunge
***************************************************************************************************************
RDB$TYPES 200
TEST 200

2016-01-20T14:56:20.0610 (4240:00C42930) ROLLBACK_TRANSACTION
e30 (ATT_89, SYSDBA:NONE, NONE, TCPv4:192.168.43.154/1384)
C:\MIX\firebird\fb30\isql.exe:4700
(TRA_188, CONCURRENCY | WAIT | READ_WRITE)
48 ms, 120 write(s), 3150 fetch(es), 895 mark(s)

Table Natural Index Update Insert Delete Backout Purge Expunge
***************************************************************************************************************
TEST 200

2016-01-20T14:56:20.0610 (4240:00C42930) TRACE_FINI
SESSION_2

::: NOTE :::
This trace DOES contain info about statistics per table for rollback (see line with backout = 200 after "48 ms, 120 write(s), 3150 fetch(es), 895 mark(s)") .

Now run the same on 2.5. Trace will be:

===2016-01-20T15:00:57.7800 (2556:011DD2A8) EXECUTE_STATEMENT_FINISH
e25 (ATT_3, SYSDBA:NONE, NONE, TCPv4:192.168.43.154)
C:\MIX\firebird\fb25\bin\isql.exe:5180
(TRA_11, CONCURRENCY | WAIT | READ_WRITE)

Statement 142:
-------------------------------------------------------------------------------
insert into test select rpad('', 1000, uuid_to_char(gen_uuid())) from rdb$types rows 200
0 records fetched
297 ms, 6 read(s), 754 write(s), 3788 fetch(es), 1718 mark(s)

Table Natural Index Update Insert Delete Backout Purge Expunge
***************************************************************************************************************
RDB$TYPES 200
TEST 200

2016-01-20T15:00:57.9360 (2556:011DD2A8) ROLLBACK_TRANSACTION
e25 (ATT_3, SYSDBA:NONE, NONE, TCPv4:192.168.43.154)
C:\MIX\firebird\fb25\bin\isql.exe:5180
(TRA_11, CONCURRENCY | WAIT | READ_WRITE)
160 ms, 175 read(s), 334 write(s), 4215 fetch(es), 809 mark(s)

2016-01-20T15:00:57.9360 (2556:011DD2A8) TRACE_FINI
SESSION_7

Here we can see only info about 'overall' results of rollback process but not detailed info about tables that were involved in this process.

Is it possible to backport 'per-table-inf' from 3.0 to 2.5 ?

@firebird-automations
Copy link
Collaborator Author

Modified by: @pavel-zotov

status: Closed [ 6 ] => Closed [ 6 ]

QA Status: No test => Done with caveats

Test Details: Implementation for 2.5 was deferred because its output does not contain per-table block for ROLLBACK event.
Waiting for reply on issue in this ticket, date = 20-jan-2016.

@firebird-automations
Copy link
Collaborator Author

Commented by: @hvlad

> Is it possible to backport 'per-table-inf' from 3.0 to 2.5 ?
Per-table statistics at transaction level are not accumulated in v2.5
Enabling it is possible but have almost no sence as it adds some run-time cost, while there is no way to query it (except of "tx end" trace event).

@firebird-automations
Copy link
Collaborator Author

Modified by: @pavel-zotov

status: Closed [ 6 ] => Closed [ 6 ]

QA Status: Done with caveats => Done successfully

Test Details: Implementation for 2.5 was deferred because its output does not contain per-table block for ROLLBACK event.
Waiting for reply on issue in this ticket, date = 20-jan-2016.

=>

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