Very inefficient realloc sequence in SQLite

RESOLVED FIXED

Status

()

defect
RESOLVED FIXED
5 years ago
5 years ago

People

(Reporter: njn, Unassigned)

Tracking

Firefox Tracking Flags

(Not tracked)

Details

Reporter

Description

5 years ago
I've been doing heap churn profiling, i.e. looking for places that call malloc
or realloc a lot. I hit a big one in SQLite. Firefox currently has v3.8.6.1.

> Cumulative {
>   ~296 blocks in heap block record 1 of 23,273
>   ~176,431,095 bytes (~176,431,095 requested / ~0 slop)
>   Individual block sizes: 1,200,128; 1,196,032; 1,191,936; 1,187,840; 1,183,744; 1,179,648; 1,175,552; 1,171,456; 1,167,360; 1,163,264; 1,159,168; 1,155,072; 1,150,976; 1,146,880; 1,142,784; 1,138,688; 1,134,592; 1,130,496; 1,126,400; 1,122,304; 1,118,208; 1,114,112; 1,110,016; 1,105,920; 1,101,824; 1,097,728; 1,093,632; 1,089,536; 1,085,440; 1,081,344; 1,077,248; 1,073,152; 1,069,056; 1,064,960; 1,060,864; 1,056,768; 1,052,672; 1,048,576; 1,044,480; 1,040,384; 1,036,288; 1,032,192; 1,028,096; 1,024,000; 1,019,904; 1,015,808; 1,011,712; 1,007,616; 1,003,520; 999,424; 995,328; 991,232; 987,136; 983,040; 978,944; 974,848; 970,752; 966,656; 962,560; 958,464; 954,368; 950,272; 946,176; 942,080; 937,984; 933,888; 929,792; 925,696; 921,600; 917,504; 913,408; 909,312; 905,216; 901,120; 897,024; 892,928; 888,832; 884,736; 880,640; 876,544; 872,448; 868,352; 864,256; 860,160; 856,064; 851,968; 847,872; 843,776; 839,680; 835,584; 831,488; 827,392; 823,296; 819,200; 815,104; 811,008; 806,912; 802,816; 798,720; 794,624; 790,528; 786,432; 782,336; 778,240; 774,144; 770,048; 765,952; 761,856; 757,760; 753,664; 749,568; 745,472; 741,376; 737,280; 733,184; 729,088; 724,992; 720,896; 716,800; 712,704; 708,608; 704,512; 700,416; 696,320; 692,224; 688,128; 684,032; 679,936; 675,840; 671,744; 667,648; 663,552; 659,456; 655,360; 651,264; 647,168; 643,072; 638,976; 634,880; 630,784; 626,688; 622,592; 618,496; 614,400; 610,304; 606,208; 602,112; 598,016; 593,920; 589,824; 585,728; 581,632; 577,536; 573,440; 569,344; 565,248; 561,152; 557,056; 552,960; 548,864; 544,768; 540,672; 536,576; 532,480; 528,384; 524,288; 520,192; 516,096; 512,000; 507,904; 503,808; 499,712; 495,616; 491,520; 487,424; 483,328; 479,232; 475,136; 471,040; 466,944; 462,848; 458,752; 454,656; 450,560; 446,464; 442,368; 438,272; 434,176; 430,080; 425,984; 421,888; 417,792; 413,696; 409,600; 405,504; 401,408; 397,312; 393,216; 389,120; 385,024; 380,928; 376,832; 372,736; 368,640; 364,544; 360,448; 356,352; 352,256; 348,160; 344,064; 339,968; 335,872; 331,776; 327,680; 323,584; 319,488; 315,392; 311,296; 307,200; 303,104; 299,008; 294,912; 290,816; 286,720; 282,624; 278,528; 274,432; 270,336; 266,240; 262,144; 258,048; 253,952; 249,856; 245,760; 241,664; 237,568; 233,472; 229,376; 225,280; 221,184; 217,088; 212,992; 208,896; 204,800; 200,704; 196,608; 192,512; 188,416; 184,320; 180,224; 176,128; 172,032; 167,936; 163,840; 159,744; 155,648; 151,552; 147,456; 143,360; 139,264; 135,168; 131,072; 126,976; 122,880; 118,784; 114,688; 110,592; 106,496; 102,400; 98,304; 94,208; 90,112; 86,016; 81,920; 77,824; 73,728; 69,632; 65,536; 61,440; 57,344; 53,248; 49,152; 45,056; 40,960; 36,864; 32,768; 28,672; 24,576; 20,480; 16,384; 12,288; 8,192; 4,096; ~4,093 x 3
>   14.12% of the heap (14.12% cumulative)
>   Allocated at {
>     #01: mozilla::storage::(anonymous namespace)::sqliteMemRealloc(void*, int) (/home/njn/moz/mi5/co64dmd/storage/src/../../../storage/src/mozStorageService.cpp:441)
>     #02: sqlite3Realloc (/home/njn/moz/mi5/co64dmd/db/sqlite3/src/../../../../db/sqlite3/src/sqlite3.c:20290)
>     #03: sqlite3DbRealloc (/home/njn/moz/mi5/co64dmd/db/sqlite3/src/../../../../db/sqlite3/src/sqlite3.c:20425)
>     #04: sqlite3StrAccumEnlarge (/home/njn/moz/mi5/co64dmd/db/sqlite3/src/../../../../db/sqlite3/src/sqlite3.c:21283)
>     #05: enlargeAndAppend (/home/njn/moz/mi5/co64dmd/db/sqlite3/src/../../../../db/sqlite3/src/sqlite3.c:21317)
>     #06: sqlite3VXPrintf (/home/njn/moz/mi5/co64dmd/db/sqlite3/src/../../../../db/sqlite3/src/sqlite3.c:21245)
>     #07: sqlite3XPrintf (/home/njn/moz/mi5/co64dmd/db/sqlite3/src/../../../../db/sqlite3/src/sqlite3.c:21577)
>     #08: sqlite3VdbeExpandSql (/home/njn/moz/mi5/co64dmd/db/sqlite3/src/../../../../db/sqlite3/src/sqlite3.c:67779)
>     #09: sqlite3VdbeExec (/home/njn/moz/mi5/co64dmd/db/sqlite3/src/../../../../db/sqlite3/src/sqlite3.c:74396)
>     #10: sqlite3Step (/home/njn/moz/mi5/co64dmd/db/sqlite3/src/../../../../db/sqlite3/src/sqlite3.c:66702)
>     #11: sqlite3_step (/home/njn/moz/mi5/co64dmd/db/sqlite3/src/../../../../db/sqlite3/src/sqlite3.c:66768)
>     #12: mozilla::storage::Connection::stepStatement(sqlite3*, sqlite3_stmt*) (/home/njn/moz/mi5/co64dmd/storage/src/../../../storage/src/mozStorageConnection.cpp:968)
>     #13: mozilla::storage::Statement::ExecuteStep(bool*) (/home/njn/moz/mi5/co64dmd/storage/src/../../../storage/src/mozStorageStatement.cpp:638)
>     #14: mozilla::storage::Statement::Execute() (/home/njn/moz/mi5/co64dmd/storage/src/../../../storage/src/mozStorageStatement.cpp:603)
>     #15: mozilla::dom::indexedDB::(anonymous namespace)::ObjectStoreAddOrPutRequestOp::DoDatabaseWork(mozilla::dom::indexedDB::(anonymous namespace)::TransactionBase*) (/home/njn/moz/mi5/co64dmd/dom/indexedDB/../../../dom/indexedDB/ActorsParent.cpp:14864)
>     #16: mozilla::dom::indexedDB::(anonymous namespace)::TransactionDatabaseOperationBase::RunOnTransactionThread() (/home/njn/moz/mi5/co64dmd/dom/indexedDB/../../../dom/indexedDB/ActorsParent.cpp:12989)
>     #17: mozilla::dom::indexedDB::(anonymous namespace)::TransactionDatabaseOperationBase::Run() (/home/njn/moz/mi5/co64dmd/dom/indexedDB/../../../dom/indexedDB/ActorsParent.cpp:13065)
>     #18: mozilla::dom::indexedDB::TransactionThreadPool::TransactionQueue::Run() (/home/njn/moz/mi5/co64dmd/dom/indexedDB/../../../dom/indexedDB/TransactionThreadPool.cpp:883)
>     #19: nsThreadPool::Run() (/home/njn/moz/mi5/co64dmd/xpcom/threads/../../../xpcom/threads/nsThreadPool.cpp:222)
>     #20: non-virtual thunk to nsThreadPool::Run() (/home/njn/moz/mi5/co64dmd/xpcom/threads/Unified_cpp_xpcom_threads0.cpp:234)
>     #21: nsThread::ProcessNextEvent(bool, bool*) (/home/njn/moz/mi5/co64dmd/xpcom/threads/../../../xpcom/threads/nsThread.cpp:830)
>     #22: NS_ProcessNextEvent(nsIThread*, bool) (/home/njn/moz/mi5/xpcom/glue/nsThreadUtils.cpp:265)
>     #23: mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) (/home/njn/moz/mi5/co64dmd/ipc/glue/../../../ipc/glue/MessagePump.cpp:339)
>   }
> }
 
What this means is that at this stack trace we saw 296 calls to realloc(). And
the sizes of those realloc'd blocks are shown on the "Individual block sizes"
line. (Below 4 KiB the profiler samples, which explains the "~4093 x 3" at the
end, but above that the recording is exact.) You can see that we realloc'd a
block for every 4 KiB multiple between 4 KiB and 1172 KiB. This corresponds
perfectly with jemalloc's class sizes -- for allocations in that range, it
rounds up requests to the nearest 4 KiB multiple. 

This happened because SQLite repeatedly called realloc on a buffer, each time
growing it by a small amount (less than 4 KiB) and the reallocs only did
something each time we passed a 4 KiB multiple.

Looking at the stack trace, it appears that sqlite3VdbeExpandSql is reponsble;
it scans a string looking for certain patterns which it expands. I guess we had
a string whose final expanded size was just under 1,200,128 bytes.

Doubling the size each time would give much better behaviour: 

  4 + 8 + 16 + 32 + 64 + 128 + 256 + 512 + 1024 + 2048 = 4092 KiB

Much better than the 176 MB(!) given by the linear size increase.

The annoying thing about this is that it happens rarely. I've done a few dozen
heap churn profile runs with an e10s build of Firefox and this has only shown
up once. According to the stack trace it's related to IndexedDB, though I don't
know how.

Richard, does this analysis make sense to you? Perhaps you can come up with a
small test case that demonstrates this bad behaviour?
Reporter

Updated

5 years ago
Flags: needinfo?(drh)

Comment 1

5 years ago
I think the following SQL statement exhibits the behavior you are concerned about:

SELECT length(printf('%s-%s-%s-%s-%s-%s-%s-%s-%s-%s',
         hex(randomblob(2050)),
         hex(randomblob(2050)),
         hex(randomblob(2050)),
         hex(randomblob(2050)),
         hex(randomblob(2050)),
         hex(randomblob(2050)),
         hex(randomblob(2050)),
         hex(randomblob(2050)),
         hex(randomblob(2050)),
         hex(randomblob(2050))));
Flags: needinfo?(drh)

Comment 2

5 years ago
Check-in https://www.sqlite.org/src/info/a518bc331823 for SQLite causes the size of the string buffer to grow exponentially (until it hits size bounds) and thus avoid realloc() calls.  This change will be in the next SQLite release (3.8.8).  I'm *guessing* that this issue is not important enough to require a patch release for SQLite (that would be 3.8.6.2 or 3.8.7.2) and that you can wait on the next next scheduled release (3.8.8).  Please correct me if this guess is incorrect.
Reporter

Comment 3

5 years ago
Thank you for the very fast response. Waiting for the next scheduled release sounds fine to me.
Reporter

Comment 4

5 years ago
FWIW, I hit this again; the sizes this time weren't as bad. It's still pretty
rare.

> Cumulative {
>   ~141 blocks in heap block record 1 of 21,208
>   ~38,735,860 bytes (~38,735,860 requested / ~0 slop)
>   Individual block sizes: 561,152; 557,056; 552,960; 548,864; 544,768; 540,672; 536,576; 532,480; 528,384; 524,288; 520,192; 516,096; 512,000; 507,904; 503,808; 499,712; 495,616; 491,520; 487,424; 483,328; 479,232; 475,136; 471,040; 466,944; 462,848; 458,752; 454,656; 450,560; 446,464; 442,368; 438,272; 434,176; 430,080; 425,984; 421,888; 417,792; 413,696; 409,600; 405,504; 401,408; 397,312; 393,216; 389,120; 385,024; 380,928; 376,832; 372,736; 368,640; 364,544; 360,448; 356,352; 352,256; 348,160; 344,064; 339,968; 335,872; 331,776; 327,680; 323,584; 319,488; 315,392; 311,296; 307,200; 303,104; 299,008; 294,912; 290,816; 286,720; 282,624; 278,528; 274,432; 270,336; 266,240; 262,144; 258,048; 253,952; 249,856; 245,760; 241,664; 237,568; 233,472; 229,376; 225,280; 221,184; 217,088; 212,992; 208,896; 204,800; 200,704; 196,608; 192,512; 188,416; 184,320; 180,224; 176,128; 172,032; 167,936; 163,840; 159,744; 155,648; 151,552; 147,456; 143,360; 139,264; 135,168; 131,072; 126,976; 122,880; 118,784; 114,688; 110,592; 106,496; 102,400; 98,304; 94,208; 90,112; 86,016; 81,920; 77,824; 73,728; 69,632; 65,536; 61,440; 57,344; 53,248; 49,152; 45,056; 40,960; 36,864; 32,768; 28,672; 24,576; 20,480; 16,384; 12,288; 8,192; 4,096; ~4,093 x 4
>   5.01% of the heap (5.01% cumulative)
>   Allocated at {
>     #01: mozilla::storage::(anonymous namespace)::sqliteMemRealloc(void*, int) (/home/njn/moz/mi5/co64dmd/storage/src/../../../storage/src/mozStorageService.cpp:441)
>     #02: sqlite3Realloc (/home/njn/moz/mi5/co64dmd/db/sqlite3/src/../../../../db/sqlite3/src/sqlite3.c:20483)
>     #03: sqlite3DbRealloc (/home/njn/moz/mi5/co64dmd/db/sqlite3/src/../../../../db/sqlite3/src/sqlite3.c:20625)
>     #04: sqlite3StrAccumEnlarge (/home/njn/moz/mi5/co64dmd/db/sqlite3/src/../../../../db/sqlite3/src/sqlite3.c:21504)
>     #05: enlargeAndAppend (/home/njn/moz/mi5/co64dmd/db/sqlite3/src/../../../../db/sqlite3/src/sqlite3.c:21538)
>     #06: sqlite3VXPrintf (/home/njn/moz/mi5/co64dmd/db/sqlite3/src/../../../../db/sqlite3/src/sqlite3.c:21466)
>     #07: sqlite3XPrintf (/home/njn/moz/mi5/co64dmd/db/sqlite3/src/../../../../db/sqlite3/src/sqlite3.c:21861)
>     #08: sqlite3VdbeExpandSql (/home/njn/moz/mi5/co64dmd/db/sqlite3/src/../../../../db/sqlite3/src/sqlite3.c:68901)
>     #09: sqlite3VdbeExec (/home/njn/moz/mi5/co64dmd/db/sqlite3/src/../../../../db/sqlite3/src/sqlite3.c:75330)
>     #10: sqlite3Step (/home/njn/moz/mi5/co64dmd/db/sqlite3/src/../../../../db/sqlite3/src/sqlite3.c:67772)
>     #11: sqlite3_step (/home/njn/moz/mi5/co64dmd/db/sqlite3/src/../../../../db/sqlite3/src/sqlite3.c:67838)
>     #12: mozilla::storage::Connection::stepStatement(sqlite3*, sqlite3_stmt*) (/home/njn/moz/mi5/co64dmd/storage/src/../../../storage/src/mozStorageConnection.cpp:968)
>     #13: mozilla::storage::Statement::ExecuteStep(bool*) (/home/njn/moz/mi5/co64dmd/storage/src/../../../storage/src/mozStorageStatement.cpp:638)
>     #14: mozilla::storage::Statement::Execute() (/home/njn/moz/mi5/co64dmd/storage/src/../../../storage/src/mozStorageStatement.cpp:603)
>     #15: mozilla::dom::indexedDB::(anonymous namespace)::ObjectStoreAddOrPutRequestOp::DoDatabaseWork(mozilla::dom::indexedDB::(anonymous namespace)::TransactionBase*) (/home/njn/moz/mi5/co64dmd/dom/indexedDB/../../../dom/indexedDB/ActorsParent.cpp:14853)
>     #16: mozilla::dom::indexedDB::(anonymous namespace)::TransactionDatabaseOperationBase::RunOnTransactionThread() (/home/njn/moz/mi5/co64dmd/dom/indexedDB/../../../dom/indexedDB/ActorsParent.cpp:12978)
>     #17: mozilla::dom::indexedDB::(anonymous namespace)::TransactionDatabaseOperationBase::Run() (/home/njn/moz/mi5/co64dmd/dom/indexedDB/../../../dom/indexedDB/ActorsParent.cpp:13054)
>     #18: mozilla::dom::indexedDB::TransactionThreadPool::TransactionQueue::Run() (/home/njn/moz/mi5/co64dmd/dom/indexedDB/../../../dom/indexedDB/TransactionThreadPool.cpp:883)
>     #19: nsThreadPool::Run() (/home/njn/moz/mi5/co64dmd/xpcom/threads/../../../xpcom/threads/nsThreadPool.cpp:222)
>     #20: non-virtual thunk to nsThreadPool::Run() (/home/njn/moz/mi5/co64dmd/xpcom/threads/Unified_cpp_xpcom_threads0.cpp:234)
>     #21: nsThread::ProcessNextEvent(bool, bool*) (/home/njn/moz/mi5/co64dmd/xpcom/threads/../../../xpcom/threads/nsThread.cpp:830)
>     #22: NS_ProcessNextEvent(nsIThread*, bool) (/home/njn/moz/mi5/xpcom/glue/nsThreadUtils.cpp:265)
>     #23: mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) (/home/njn/moz/mi5/co64dmd/ipc/glue/../../../ipc/glue/MessagePump.cpp:339)
>   }
> }
Reporter

Comment 5

5 years ago
This bug is just waiting on the SQLite 3.8.8 import. There doesn't appear to be a bug for it yet.
we create upgrade bugs when the new Sqlite versions are released. I think there's no hurry here, right?
If you want a bug for tracking purposes, you're free to file one copying the existing ones style (like bug 1101217)
Reporter

Comment 7

5 years ago
Yeah, there's no great rush. I was just recording it for completeness.
drh made an early 3.8.8 build available for testing in another bug if you want to give it a spin:
https://www.sqlite.org/snapshot/sqlite-amalgamation-201412120127.zip

Comment 9

5 years ago
(In reply to Nicholas Nethercote [:njn] from comment #5)
> This bug is just waiting on the SQLite 3.8.8 import. There doesn't appear to
> be a bug for it yet.

Ryan is doing some try testing against 3.8.8 in bug 1122717.
Depends on: SQLite3.8.8.1
Reporter

Comment 10

5 years ago
Should be fixed by bug 1122717.
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.