Issue Details (XML | Word | Printable)

Key: CORE-3598
Type: Improvement Improvement
Status: Closed Closed
Resolution: Fixed
Priority: Major Major
Assignee: Vlad Khorsun
Reporter: Pavel Zotov
Votes: 0
Watchers: 0
Operations

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

TRACE: add statistics of actions that were after transaction finished

Created: 13/Sep/11 08:29 PM   Updated: 21/Jan/16 11:44 AM
Component/s: None
Affects Version/s: 2.5.0, 2.5.1
Fix Version/s: 2.5.2, 3.0 Alpha 1

QA Status: Done successfully


 Description  « Hide
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 ?

 All   Comments   Change History   Subversion Commits      Sort Order: Ascending order - Click to sort in descending order
Pavel Zotov added a comment - 20/Jan/16 12:03 PM - edited
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 ?

Vlad Khorsun added a comment - 21/Jan/16 11:26 AM
> 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).