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

Performance regression when bulk inserting into table with indices [CORE5302] #2047

Closed
firebird-automations opened this issue Jul 7, 2016 · 9 comments

Comments

@firebird-automations
Copy link
Collaborator

Submitted by: @hvlad

Attachments:
c5302-trace-logs-for-25_30_40.7z

Commits: 96a2422 a75e0af

@firebird-automations
Copy link
Collaborator Author

Commented by: @hvlad

The case was described at http://www.sql.ru/forum/1220706/upala-skorost-update-pri-perehode-s-2-5-na-3-0:

CREATE TABLE TEST_TABLE (
VALUE_1 INTEGER,
VALUE_2 INTEGER,
VALUE_3 INTEGER
);
commit;

CREATE INDEX TEST_TABLE_IDX1 ON TEST_TABLE (VALUE_1);
CREATE INDEX TEST_TABLE_IDX2 ON TEST_TABLE (VALUE_2);
CREATE INDEX TEST_TABLE_IDX3 ON TEST_TABLE (VALUE_3);
CREATE INDEX TEST_TABLE_IDX4 ON TEST_TABLE (VALUE_1, VALUE_2);
CREATE INDEX TEST_TABLE_IDX5 ON TEST_TABLE (VALUE_1, VALUE_3);
CREATE INDEX TEST_TABLE_IDX6 ON TEST_TABLE (VALUE_1, VALUE_2, VALUE_3);
commit;

SET TERM ^ ;

create procedure MAKE_UPDATES
as
declare variable i integer;
declare variable n integer;
begin
i = 0;
n = 50000;
delete from test_table;
while (i < n) do
begin
insert into TEST_TABLE (VALUE_1, VALUE_2, VALUE_3)
values (:i, :i, :i);
i = i + 1;
end
end

^

SET TERM ; ^
COMMIT;

Results (memory and commit stats is omittted)

1. Using Firebird 2.5.6.27018

execute procedure MAKE_UPDATES;
Elapsed time= 0.99 sec
Buffers = 2048
Reads = 42
Writes 975
Fetches = 1054141
commit;

execute procedure MAKE_UPDATES;
Elapsed time= 1.19 sec
Buffers = 2048
Reads = 0
Writes 984
Fetches = 1304860
commit;

execute procedure MAKE_UPDATES;
Elapsed time= 1.84 sec
Buffers = 2048
Reads = 0
Writes 749
Fetches = 2218769
commit;

execute procedure MAKE_UPDATES;
Elapsed time= 1.86 sec
Buffers = 2048
Reads = 0
Writes 761
Fetches = 2139364
commit;

execute procedure MAKE_UPDATES;
Elapsed time= 1.61 sec
Buffers = 2048
Reads = 0
Writes 766
Fetches = 2113376
commit;

2. Using Firebird 3.0.1.32547

execute procedure MAKE_UPDATES;
Elapsed time= 2.218 sec
Buffers = 2048
Reads = 32
Writes = 975
Fetches = 1053352
commit;

execute procedure MAKE_UPDATES;
Elapsed time= 2.672 sec
Buffers = 2048
Reads = 0
Writes = 984
Fetches = 1304191
commit;

execute procedure MAKE_UPDATES;
Elapsed time= 2.958 sec
Buffers = 2048
Reads = 0
Writes = 1050
Fetches = 2503752
commit;

execute procedure MAKE_UPDATES;
Elapsed time= 3.069 sec
Buffers = 2048
Reads = 0
Writes = 1393
Fetches = 2502999
commit;

execute procedure MAKE_UPDATES;
Elapsed time= 2.928 sec
Buffers = 2048
Reads = 0
Writes = 1057
Fetches = 2502628
commit;

@firebird-automations
Copy link
Collaborator Author

Modified by: @hvlad

assignee: Vlad Khorsun [ hvlad ]

@firebird-automations
Copy link
Collaborator Author

Commented by: @hvlad

The regression was introduced with a fix for CORE4914

@firebird-automations
Copy link
Collaborator Author

Commented by: @hvlad

Stats on Firebird 4.0.0.288 with patch

execute procedure MAKE_UPDATES;
Elapsed time= 1.005 sec
Buffers = 2048
Reads = 28
Writes = 975
Fetches = 1053362
commit;

execute procedure MAKE_UPDATES;
Elapsed time= 1.315 sec
Buffers = 2048
Reads = 0
Writes = 1236
Fetches = 1304551
commit;

execute procedure MAKE_UPDATES;
Elapsed time= 1.389 sec
Buffers = 2048
Reads = 0
Writes = 1165
Fetches = 2502620
commit;

execute procedure MAKE_UPDATES;
Elapsed time= 1.468 sec
Buffers = 2048
Reads = 0
Writes = 1527
Fetches = 2502337
commit;

execute procedure MAKE_UPDATES;
Elapsed time= 1.349 sec
Buffers = 2048
Reads = 0
Writes = 1165
Fetches = 2501646
commit;

@firebird-automations
Copy link
Collaborator Author

Commented by: @pavel-zotov

Trace logs with config:

log_transactions = true
log_statement_finish = true

-- show following (bigger values - for EXECUTE PROCEDURE, smaller - for COMMIT):

WI-V2.5.6.27023

4019 ms, 8 read(s), 2571 write(s), 1057721 fetch(es), 356280 mark(s)
35 ms, 1 read(s), 140 write(s), 1 fetch(es), 1 mark(s)
6880 ms, 1392 read(s), 5079 write(s), 1357467 fetch(es), 407681 mark(s)
118 ms, 1 read(s), 236 write(s), 1 fetch(es), 1 mark(s)
7975 ms, 4464 read(s), 4934 write(s), 2612922 fetch(es), 806453 mark(s)
68 ms, 1 read(s), 249 write(s), 1 fetch(es), 1 mark(s)
8104 ms, 4458 read(s), 4922 write(s), 2611471 fetch(es), 806423 mark(s)
89 ms, 1 read(s), 249 write(s), 1 fetch(es), 1 mark(s)
7723 ms, 4465 read(s), 4928 write(s), 2611434 fetch(es), 806426 mark(s)
33 ms, 1 read(s), 249 write(s), 1 fetch(es), 1 mark(s)
8211 ms, 4459 read(s), 4922 write(s), 2611429 fetch(es), 806420 mark(s)
43 ms, 1 read(s), 249 write(s), 1 fetch(es), 1 mark(s)
7782 ms, 4466 read(s), 4928 write(s), 2611434 fetch(es), 806423 mark(s)
107 ms, 1 read(s), 249 write(s), 1 fetch(es), 1 mark(s)
8139 ms, 4460 read(s), 4922 write(s), 2611429 fetch(es), 806417 mark(s)
75 ms, 1 read(s), 249 write(s), 1 fetch(es), 1 mark(s)
7826 ms, 4466 read(s), 4927 write(s), 2611434 fetch(es), 806420 mark(s)
102 ms, 1 read(s), 249 write(s), 1 fetch(es), 1 mark(s)
8156 ms, 4458 read(s), 4930 write(s), 2611456 fetch(es), 806441 mark(s)
61 ms, 1 read(s), 252 write(s), 1 fetch(es), 1 mark(s)
8004 ms, 4465 read(s), 4925 write(s), 2611434 fetch(es), 806417 mark(s)
140 ms, 1 read(s), 249 write(s), 1 fetch(es), 1 mark(s)
9010 ms, 4459 read(s), 4930 write(s), 2611459 fetch(es), 806438 mark(s)
42 ms, 1 read(s), 252 write(s), 1 fetch(es), 1 mark(s)

WI-V3.0.1.32566

11431 ms, 8 read(s), 975 write(s), 1053183 fetch(es), 352462 mark(s)
138 ms, 375 write(s), 1 fetch(es), 1 mark(s)
12895 ms, 984 write(s), 1304191 fetch(es), 402770 mark(s)
716 ms, 1379 write(s), 1 fetch(es), 1 mark(s)
15829 ms, 9 write(s), 1905526 fetch(es), 602321 mark(s)
681 ms, 1372 write(s), 1 fetch(es), 1 mark(s)
16018 ms, 121 write(s), 1839431 fetch(es), 580376 mark(s)
524 ms, 1002 write(s), 1 fetch(es), 1 mark(s)
15583 ms, 1899236 fetch(es), 600279 mark(s)
690 ms, 1346 write(s), 1 fetch(es), 1 mark(s)
15914 ms, 7 write(s), 1838875 fetch(es), 580188 mark(s)
594 ms, 996 write(s), 1 fetch(es), 1 mark(s)
15588 ms, 1891369 fetch(es), 597695 mark(s)
694 ms, 1325 write(s), 1 fetch(es), 1 mark(s)
15891 ms, 10 write(s), 1838932 fetch(es), 580196 mark(s)
506 ms, 997 write(s), 1 fetch(es), 1 mark(s)
15775 ms, 1887593 fetch(es), 596416 mark(s)
764 ms, 1296 write(s), 1 fetch(es), 1 mark(s)
15847 ms, 9 write(s), 1835952 fetch(es), 579207 mark(s)
500 ms, 998 write(s), 1 fetch(es), 1 mark(s)
15616 ms, 1883895 fetch(es), 595176 mark(s)
637 ms, 1267 write(s), 1 fetch(es), 1 mark(s)

WI-T4.0.0.312

5120 ms, 8 read(s), 975 write(s), 1053183 fetch(es), 352462 mark(s)
171 ms, 375 write(s), 1 fetch(es), 1 mark(s)
6372 ms, 1236 write(s), 1304527 fetch(es), 403106 mark(s)
752 ms, 1379 write(s), 1 fetch(es), 1 mark(s)
9075 ms, 7 write(s), 1910488 fetch(es), 603967 mark(s)
735 ms, 1442 write(s), 1 fetch(es), 1 mark(s)
9687 ms, 298 write(s), 1836660 fetch(es), 579447 mark(s)
563 ms, 1058 write(s), 1 fetch(es), 1 mark(s)
8772 ms, 18 write(s), 1897749 fetch(es), 599813 mark(s)
733 ms, 1412 write(s), 1 fetch(es), 1 mark(s)
9486 ms, 236 write(s), 1836932 fetch(es), 579544 mark(s)
555 ms, 1050 write(s), 1 fetch(es), 1 mark(s)
8767 ms, 9 write(s), 1892261 fetch(es), 597985 mark(s)
699 ms, 1387 write(s), 1 fetch(es), 1 mark(s)
9346 ms, 168 write(s), 1837526 fetch(es), 579733 mark(s)
552 ms, 1043 write(s), 1 fetch(es), 1 mark(s)
8794 ms, 1887371 fetch(es), 596344 mark(s)
753 ms, 1355 write(s), 1 fetch(es), 1 mark(s)
9194 ms, 51 write(s), 1834030 fetch(es), 578571 mark(s)
549 ms, 1045 write(s), 1 fetch(es), 1 mark(s)
8791 ms, 9 write(s), 1882791 fetch(es), 594825 mark(s)
757 ms, 1324 write(s), 1 fetch(es), 1 mark(s)

Every database was created with FW = ON,page_size = default.
Machine: CPU 3.0 GHz, 2core,ram 2 Gb.

DefaultDbCachePages = 256 on 2.5 and default on 3.0 & 4.0.
Packed logs see in attached .7z

@firebird-automations
Copy link
Collaborator Author

Modified by: @pavel-zotov

Attachment: c5302-trace-logs-for-25_30_40.7z [ 13000 ]

@firebird-automations
Copy link
Collaborator Author

Modified by: @hvlad

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

resolution: Fixed [ 1 ]

Fix Version: 3.0.1 [ 10730 ]

Fix Version: 4.0 Alpha 1 [ 10731 ]

@firebird-automations
Copy link
Collaborator Author

Modified by: @pavel-zotov

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

QA Status: No test => Done successfully

@firebird-automations
Copy link
Collaborator Author

Modified by: @pavel-zotov

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

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