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 output could contain garbage data left from filtered out statements [CORE2940] #3322

Closed
firebird-automations opened this issue Mar 23, 2010 · 4 comments

Comments

@firebird-automations
Copy link
Collaborator

Submitted by: @hvlad

Prepare trace configuration file such as

<database>
enabled true

#&#x2060;include\_filter 
exclude\_filter   %no\_trace%

log\_connections true
log\_transactions true
log\_statement\_finish true

print\_plan true
print\_perf true

time\_threshold 0

</database>

and start trace session using this config.

In the second console run isql and attach to any database.

isql :
SQL> select 1 from rdb$database;

CONSTANT

============
1

SQL> commit;

corresponding trace output :

2010-03-23T21:52:18.0500 (404:035CC440) START_TRANSACTION
F:\FB2\FB25.TRACE\TEMP\WIN32\RELEASE\FIREBIRD\BIN\A.FDB (ATT_24, SYSDBA:NONE, XNET:W2K3-X64)
F:\FB2\fb25.trace\temp\Win32\Release\firebird\bin\isql.exe:1456
(TRA_53, CONCURRENCY | WAIT | READ_WRITE)

2010-03-23T21:52:18.0500 (404:035CC440) START_TRANSACTION
F:\FB2\FB25.TRACE\TEMP\WIN32\RELEASE\FIREBIRD\BIN\A.FDB (ATT_24, SYSDBA:NONE, XNET:W2K3-X64)
F:\FB2\fb25.trace\temp\Win32\Release\firebird\bin\isql.exe:1456
(TRA_54, READ_COMMITTED | NO_REC_VERSION | WAIT | READ_WRITE)

2010-03-23T21:52:18.0660 (404:035CC440) EXECUTE_STATEMENT_FINISH
F:\FB2\FB25.TRACE\TEMP\WIN32\RELEASE\FIREBIRD\BIN\A.FDB (ATT_24, SYSDBA:NONE, XNET:W2K3-X64)
F:\FB2\fb25.trace\temp\Win32\Release\firebird\bin\isql.exe:1456
(TRA_53, CONCURRENCY | WAIT | READ_WRITE)

Statement 138:
-------------------------------------------------------------------------------
select 1 from rdb$database
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
PLAN (RDB$DATABASE NATURAL)
1 records fetched
0 ms, 13 fetch(es)

Table Natural Index Update Insert Delete Backout Purge Expunge
***************************************************************************************************************
RDB$DATABASE 1
RDB$CHARACTER_SETS 1
RDB$COLLATIONS 1

2010-03-23T21:52:24.6600 (404:035CC440) COMMIT_TRANSACTION
F:\FB2\FB25.TRACE\TEMP\WIN32\RELEASE\FIREBIRD\BIN\A.FDB (ATT_24, SYSDBA:NONE, XNET:W2K3-X64)
F:\FB2\fb25.trace\temp\Win32\Release\firebird\bin\isql.exe:1456
(TRA_53, CONCURRENCY | WAIT | READ_WRITE)
1 ms, 1 read(s), 1 write(s), 1 fetch(es), 1 mark(s)

2010-03-23T21:52:24.6600 (404:035CC440) COMMIT_TRANSACTION
F:\FB2\FB25.TRACE\TEMP\WIN32\RELEASE\FIREBIRD\BIN\A.FDB (ATT_24, SYSDBA:NONE, XNET:W2K3-X64)
F:\FB2\fb25.trace\temp\Win32\Release\firebird\bin\isql.exe:1456
(TRA_54, READ_COMMITTED | NO_REC_VERSION | WAIT | READ_WRITE)
0 ms, 1 read(s), 1 write(s), 1 fetch(es), 1 mark(s)

This is as expectd. Now issue sql statement which should be filtered out by regular expression %no_trace% :

SQL> select 2 from rdb$database /* no_trace*/;

CONSTANT

============
2

SQL> commit;

Corresponding trace output :

2010-03-23T21:52:31.2380 (404:035CC440) START_TRANSACTION
F:\FB2\FB25.TRACE\TEMP\WIN32\RELEASE\FIREBIRD\BIN\A.FDB (ATT_24, SYSDBA:NONE, XNET:W2K3-X64)
F:\FB2\fb25.trace\temp\Win32\Release\firebird\bin\isql.exe:1456
(TRA_55, CONCURRENCY | WAIT | READ_WRITE)

2010-03-23T21:52:31.3320 (404:035CC440) START_TRANSACTION
F:\FB2\FB25.TRACE\TEMP\WIN32\RELEASE\FIREBIRD\BIN\A.FDB (ATT_24, SYSDBA:NONE, XNET:W2K3-X64)
F:\FB2\fb25.trace\temp\Win32\Release\firebird\bin\isql.exe:1456
(TRA_56, READ_COMMITTED | NO_REC_VERSION | WAIT | READ_WRITE)

2010-03-23T21:52:38.5500 (404:035CC440) COMMIT_TRANSACTION
F:\FB2\FB25.TRACE\TEMP\WIN32\RELEASE\FIREBIRD\BIN\A.FDB (ATT_24, SYSDBA:NONE, XNET:W2K3-X64)
F:\FB2\fb25.trace\temp\Win32\Release\firebird\bin\isql.exe:1456
(TRA_55, CONCURRENCY | WAIT | READ_WRITE)
1 records fetched
0 ms, 5 fetch(es)

Table Natural Index Update Insert Delete Backout Purge Expunge
***************************************************************************************************************
RDB$DATABASE 1
1 ms, 1 read(s), 1 write(s), 1 fetch(es), 1 mark(s)

2010-03-23T21:52:38.5500 (404:035CC440) COMMIT_TRANSACTION
F:\FB2\FB25.TRACE\TEMP\WIN32\RELEASE\FIREBIRD\BIN\A.FDB (ATT_24, SYSDBA:NONE, XNET:W2K3-X64)
F:\FB2\fb25.trace\temp\Win32\Release\firebird\bin\isql.exe:1456
(TRA_56, READ_COMMITTED | NO_REC_VERSION | WAIT | READ_WRITE)
0 ms, 1 read(s), 1 write(s), 1 fetch(es), 1 mark(s)

Note lines

1 records fetched
0 ms, 5 fetch(es)

Table Natural Index Update Insert Delete Backout Purge Expunge
***************************************************************************************************************
RDB$DATABASE 1

after first COMMIT_TRANSACTION event. They are corresponds to the filtered out SQL statement and should not be put into trace output.

Commits: 9685411 035e567

@firebird-automations
Copy link
Collaborator Author

Modified by: @hvlad

assignee: Vlad Khorsun [ hvlad ]

@firebird-automations
Copy link
Collaborator Author

Modified by: @hvlad

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

resolution: Fixed [ 1 ]

Fix Version: 2.5 RC3 [ 10381 ]

Fix Version: 3.0 Alpha 1 [ 10331 ]

@firebird-automations
Copy link
Collaborator Author

Modified by: @pcisar

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

@firebird-automations
Copy link
Collaborator Author

Modified by: @pavel-zotov

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

QA Status: Done successfully

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