1092898 - Very inefficient realloc sequence in SQLite

Status: RESOLVED FIXED

(Core :: SQLite and Embedded Database Bindings, defect)

Description

[Nicholas Nethercote [inactive]]

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?

Comment 1

[D. Richard Hipp]

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))));

Comment 2

[D. Richard Hipp]

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.

Comment 3

[Nicholas Nethercote [inactive]]

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

Comment 4

[Nicholas Nethercote [inactive]]

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)
>   }
> }

Comment 5

[Nicholas Nethercote [inactive]]

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

[Marco Bonardo [:mak]]

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)

Comment 7

[Nicholas Nethercote [inactive]]

Yeah, there's no great rush. I was just recording it for completeness.

Comment 8

[Ryan VanderMeulen [:RyanVM]]

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

[Arthur K. (he/him)]

(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.

Comment 10

[Nicholas Nethercote [inactive]]

Should be fixed by bug 1122717.