Avoiding excessive memory consumption by undo-log after series of updates [CORE1477]

[firebird-automations]

Submitted by: Kuznetsov Eugene (eugene)

Is related to CORE1575

Attachments:
Test.zip
c1477-ddl-and-run.sql

Look at the example

Start Transaction: isc_tpb_consistency,isc_tpb_no_auto_undo,isc_tpb_nowait

execute procedure TEST3

-----Statistics-----
Reads = 5344
Writes = 5053
Fetches = 8499490
Marks = 2810214
CurrentMemory = 17139964
MaxMemory = 17840520
NumBuffers = 1000
-----Detail statistics-----
read_seq_count
TEST_TABLE2 = 1000000
update_count
TEST_TABLE2 = 1000000
-----End------

execute procedure TEST3

-----Statistics-----
Reads = 12200
Writes = 495276
Fetches = 15811015
Marks = 5306902
CurrentMemory = 17140460
MaxMemory = 716093252
NumBuffers = 1000
-----Detail statistics-----
read_seq_count
TEST_TABLE2 = 1000000
update_count
TEST_TABLE2 = 1000000
-----End------

Commit Transaction

TEST3 is a simple procedure with the single update statement into it.
During the second call of TEST3 memory consumption grows extensively (see MaxMemory), exceeding database size at least five times more.
It seems, undo-log code needs for optimization.

With best regards, Eugene

Commits: e0db5f3 1a943d1

====== Test Details ======

Waiting for reply from dimitr, letter 09-sep-2016 09:48.

[firebird-automations]

Commented by: Kuznetsov Eugene (eugene)

Test database

[firebird-automations]

Modified by: Kuznetsov Eugene (eugene)

Attachment: Test.zip [ 10590 ]

[firebird-automations]

Modified by: @dyemanov

Link: This issue is related to CORE1575 [ CORE1575 ]

[firebird-automations]

Modified by: @dyemanov

assignee: Dmitry Yemanov [ dimitr ]

[firebird-automations]

Modified by: @dyemanov

Target: 2.5.0 [ 10221 ]

[firebird-automations]

Modified by: @pcisar

Workflow: jira [ 13160 ] => Firebird [ 15593 ]

[firebird-automations]

Modified by: @dyemanov

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

Fix Version: 2.5 Alpha 1 [ 10224 ]

[firebird-automations]

Modified by: @dyemanov

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

Fix Version: 2.5 Beta 1 [ 10251 ]

Fix Version: 2.5 Alpha 1 [ 10224 ] =>

[firebird-automations]

Modified by: @dyemanov

status: Open [ 1 ] => In Progress [ 3 ]

[firebird-automations]

Modified by: @dyemanov

status: In Progress [ 3 ] => Open [ 1 ]

[firebird-automations]

Modified by: @dyemanov

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

resolution: Fixed [ 1 ]

[firebird-automations]

Modified by: @pcisar

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

[firebird-automations]

Modified by: @pavel-zotov

QA Status: No test

[firebird-automations]

Commented by: @pavel-zotov

Problem still exists, it seems to me that ticket should be reopened.
Consider script from attach (this is result of metadata extraction from source .fdb-attach + subsequent SP calls).

Following is result for several FB versions:

1) WI-V2.0.0.12724 (Firebird 2.0 Release Candidate 4):

execute procedure TEST3;
Current memory = 1122080
Delta memory = 14624
Max memory = 2289328
Elapsed time= 21.35 sec
Buffers = 75
Reads = 21127
Writes 21399
Fetches = 8442470

execute procedure TEST3;
Current memory = 1122272
Delta memory = 192
Max memory = 700541716
Elapsed time= 137.07 sec
Buffers = 75
Reads = 48146
Writes 470931
Fetches = 21196669

2) WI-V2.5.1.26351:

execute procedure TEST3;
Current memory = 9716564
Delta memory = 83276
Max memory = 10885284
Elapsed time= 34.68 sec
Buffers = 2048
Reads = 21124
Writes 26231
Fetches = 9442446

execute procedure TEST3;
Current memory = 76828604
Delta memory = 67112040
Max memory = 146681336
Elapsed time= 92.56 sec
Buffers = 2048
Reads = 48138
Writes 72542
Fetches = 20515235

3) WI-V2.5.7.27025:

execute procedure TEST3;
Current memory = 2166032
Delta memory = 15056
Max memory = 3335068
Elapsed time= 27.29 sec
Buffers = 256
Reads = 21125
Writes 21196
Fetches = 11442456

execute procedure TEST3;
Current memory = 10555936
Delta memory = 8389904
Max memory = 80409780
Elapsed time= 78.68 sec
Buffers = 256
Reads = 48142
Writes 66631
Fetches = 22580059

4) WI-V3.0.1.32585, Classic:

execute procedure TEST3;
Current memory = 4899104
Delta memory = 40880
Max memory = 5792864
Elapsed time= 33.856 sec
Buffers = 256
Reads = 9289
Writes = 10495
Fetches = 10944045

execute procedure TEST3;
Current memory = 13290176
Delta memory = 8391072
Max memory = 67749336
Elapsed time= 112.903 sec
Buffers = 256
Reads = 19979
Writes = 14882
Fetches = 15734622

5) WI-V3.0.1.32588, SuperServer:

execute procedure TEST3;
Current memory = 20496512
Delta memory = 235632
Max memory = 21390272
Elapsed time= 30.539 sec
Buffers = 2048
Reads = 9286
Writes = 8755
Fetches = 10944034

execute procedure TEST3;
Current memory = 573122432
Delta memory = 552625920
Max memory = 627581592
Elapsed time= 76.595 sec
Buffers = 2048
Reads = 19979
Writes = 16593
Fetches = 15734624

In all cases ratio of 'Max memory' values for two subsequent calls of SP test3 is extremely high.

[firebird-automations]

Modified by: @pavel-zotov

Attachment: c1477-ddl-and-run.sql [ 13011 ]

[firebird-automations]

Commented by: @dyemanov

Pavel, what TempCacheLimit was used in your tests? It should be default (low) value to see the effect of the patch.

[firebird-automations]

Commented by: @pavel-zotov

All except FB 3.0 SS - default values; on WI-V3.0.1.32588, SuperServer: TempCacheLimit = 2147483647

After changing TempCahceLimit to default value on 3.0 SS statistics is:

execute procedure TEST3;
Current memory = 20655608
Delta memory = 235216
Max memory = 21549368
Elapsed time= 29.693 sec
Buffers = 2048
Reads = 9286
Writes = 8744
Fetches = 10944033

execute procedure TEST3;
Current memory = 87768784
Delta memory = 67113176
Max memory = 142227944
Elapsed time= 68.698 sec
Buffers = 2048
Reads = 19979
Writes = 16600
Fetches = 15734622

So, ratio between Maxmemory values is about 7 times ( 142.2 / 21.5 ).
Is it expected or no ?

[firebird-automations]

Commented by: @dyemanov

64MB is occupied by the temp cache, so the query actually uses ~80MB. The ratio is ~4x. This is expected.

[firebird-automations]

Modified by: @pavel-zotov

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

QA Status: No test => Deferred

Test Details: Waiting for reply from dimitr, letter 09-sep-2016 09:48.