Closed
Bug 1092898
Opened 10 years ago
Closed 10 years ago
Very inefficient realloc sequence in SQLite
Categories
(Core :: SQLite and Embedded Database Bindings, defect)
Tracking
()
RESOLVED
FIXED
People
(Reporter: n.nethercote, Unassigned)
References
Details
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•10 years ago
|
Flags: needinfo?(drh)
Comment 1•10 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•10 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•10 years ago
|
||
Thank you for the very fast response. Waiting for the next scheduled release sounds fine to me.
![]() |
Reporter | |
Updated•10 years ago
|
Depends on: cumulative-heap-profiling
![]() |
Reporter | |
Comment 4•10 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•10 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.
Comment 6•10 years ago
|
||
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•10 years ago
|
||
Yeah, there's no great rush. I was just recording it for completeness.
Comment 8•10 years ago
|
||
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•10 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.
Updated•10 years ago
|
Depends on: SQLite3.8.8.1
![]() |
Reporter | |
Comment 10•10 years ago
|
||
Should be fixed by bug 1122717.
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Updated•7 days ago
|
Product: Toolkit → Core
You need to log in
before you can comment on or make changes to this bug.
Description
•