Issue Details (XML | Word | Printable)

Key: CORE-4797
Type: Bug Bug
Status: Open Open
Priority: Minor Minor
Assignee: Unassigned
Reporter: Pavel Zotov
Votes: 0
Watchers: 3
Operations

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

Presence of Trace session affects stats/counts of indexed reads

Created: 17/May/15 07:59 PM   Updated: 17/May/15 10:34 PM
Component/s: Engine, TRACEMGR
Affects Version/s: 3.0 Beta 2, 2.5.5
Fix Version/s: None


 Description  « Hide
Following was done each run on empty database, page = 4k, FW = ON.

DDL:
====

create or alter view vmon as
select r.mon$record_seq_reads seq_reads,r.mon$record_idx_reads idx_reads
from mon$attachments a left join mon$record_stats r on a.mon$stat_id=r.mon$stat_id
where a.mon$attachment_id = current_connection;
commit;
recreate table test(x int);
commit;
insert into test select rand()*100 from (select 1 i from rdb$types rows 100) a, (select 1 i from rdb$types rows 100) b;
commit;
create index test_x on test(x);
commit; ------------------------------- [1]


TEST-1. Without trace.
======

select * from vmon; ----------------------- [a]
out nul; select min(x) from test; out;
commit;
select * from vmon; ----------------------- [b]

Result in 2.5:
~~~~~~~~~~

SEQ_READS IDX_READS
========= =====================
    10173 382

SEQ_READS IDX_READS
========= =====================
    10173 385

Difference of values in IDX_READS column is 385 - 382 = 3 rather than expected 1 (one).
The same result will be for: select x from test order by x rows 1;

Result in 3.0:
~~~~~~~~~~
SEQ_READS IDX_READS
========= =====================
    10178 355

SEQ_READS IDX_READS
========= =====================
    10178 357

Difference of values in IDX_READS column is 357 - 355 = 2 rather than expected 1 (one).
The same result will be for: select x from test order by x rows 1;


TEST-2. WITH trace launching after "commit; --------- [1]" and before first subsequent query to view "vmon".
======

select * from vmon; ----------------------- [a] -- this should be issued AFTER trace session will launched in another window
out nul; select min(x) from test; out;
commit;
select * from vmon; ----------------------- [b]


Result in 2.5:
~~~~~~~~~~
 SEQ_READS IDX_READS
========== =====================
     10173 382

 SEQ_READS IDX_READS
========== =====================
     10173 386

Difference of values in IDX_READS column is 386 - 382 = 4 rather than expected 1 (one). And this value differ from 3 that was received before, without trace.

Result in 3.0: the same as before, difference is 2 rather than 1. Trace has no affect on this.
~~~~~~~~~~

Q1: why differences in IDX_READS column never was 1 ?
Q2: how TRACE session could affect on result of gathering statistics in MON$RECORD_STATS in 2.5 ?!

PS. Tested on: WI-V2.5.5.26870 and WI-T3.0.0.31836, both - SuperClassic.

 All   Comments   Change History   Subversion Commits      Sort Order: Ascending order - Click to sort in descending order
Sean Leyne added a comment - 17/May/15 08:19 PM
Edited Summary for better readability

Pavel Zotov added a comment - 17/May/15 10:34 PM
Found something interesting for 2.5: difference between indexed_reads reporting by MON$ statistics equal to... number of data sources that participating in statement!

Example-1.
=========
commit;
select * from vmon;

set term ^;
execute block as
  declare n int = 10;
  declare i int;
begin
  while (n>0) do
  begin
      execute statement 'select min(a.x) from test a join test2 b on a.x = b.x' into i; -- 20; 22
      n = n-1;
  end
end
^
set term ;^

commit;
select * from vmon;

-- this will report difference = 20 if we run it without trace and 22 if trace will be active. Note that statement contains two data sources, test & test2.

Example-2.
=========
...
   execute statement 'select min(a.x) from test a join test b on a.x = b.x join test c on b.x = c.x' into i;
...

-- will report difference = 30 if we run it without trace and 33 if trace will be active. Note that statement contains three data sources, test, test2 & test3.

Also it was encountered that this difference appear ONLY when trace config:

1) contains print_plan true
AND
2) contains something that forces trace log to be filled with data, .i.e.:
  time_threshold = 0
  log_statement_finish true