Here is the full repository. This is a very simple test which inserts 50000 random things into the database with the postgresql-simple database binding. It uses MonadRandom and can generate Things lazily.
Here is the lazy Thing generator.
Here is case1 and specific snippet of code using Thing generator:
insertThings c = do
ts <- genThings
withTransaction c $ do
executeMany c "insert into things (a, b, c) values (?, ?, ?)" $ map (\(Thing ta tb tc) -> (ta, tb, tc)) $ take 50000 ts
Here is case2, which just dumps Things to stdout:
main = do
ts <- genThings
mapM print $ take 50000 ts
In the first case I have very bad GC times:
cabal-dev/bin/posttest +RTS -s
1,750,661,104 bytes allocated in the heap
619,896,664 bytes copied during GC
92,560,976 bytes maximum residency (10 sample(s))
990,512 bytes maximum slop
239 MB total memory in use (0 MB lost due to fragmentation)
Tot time (elapsed) Avg pause Max pause
Gen 0 3323 colls, 0 par 11.01s 11.46s 0.0034s 0.0076s
Gen 1 10 colls, 0 par 0.74s 0.77s 0.0769s 0.2920s
INIT time 0.00s ( 0.00s elapsed)
MUT time 2.97s ( 3.86s elapsed)
GC time 11.75s ( 12.23s elapsed)
RP time 0.00s ( 0.00s elapsed)
PROF time 0.00s ( 0.00s elapsed)
EXIT time 0.00s ( 0.00s elapsed)
Total time 14.72s ( 16.09s elapsed)
%GC time 79.8% (76.0% elapsed)
Alloc rate 588,550,530 bytes per MUT second
Productivity 20.2% of total user, 18.5% of total elapsed
While in the second case times are great:
cabal-dev/bin/dumptest +RTS -s > out
1,492,068,768 bytes allocated in the heap
7,941,456 bytes copied during GC
2,054,008 bytes maximum residency (3 sample(s))
70,656 bytes maximum slop
6 MB total memory in use (0 MB lost due to fragmentation)
Tot time (elapsed) Avg pause Max pause
Gen 0 2888 colls, 0 par 0.13s 0.16s 0.0001s 0.0089s
Gen 1 3 colls, 0 par 0.01s 0.01s 0.0020s 0.0043s
INIT time 0.00s ( 0.00s elapsed)
MUT time 2.00s ( 2.37s elapsed)
GC time 0.14s ( 0.16s elapsed)
RP time 0.00s ( 0.00s elapsed)
PROF time 0.00s ( 0.00s elapsed)
EXIT time 0.00s ( 0.00s elapsed)
Total time 2.14s ( 2.53s elapsed)
%GC time 6.5% (6.4% elapsed)
Alloc rate 744,750,084 bytes per MUT second
Productivity 93.5% of total user, 79.0% of total elapsed
I have tried to apply heap profiling, but did not understand anything. It looks like all of 50000 Thing are constructed in memory first, then transformed into ByteStrings with queries and then these strings are sent to the database. But why does it happen? How do I determine the guilty code?
GHC version is 7.4.2
Compilations flags is -O2 for all libraries and package itself (compiled by cabal-dev in sandbox)
I've checked profile with formatMany and 50k Things. Memory builds up steadily and then quickly drops. Maximum memory used is slightly over 40mb. Main cost centers are buildQuery and escapeStringConn followed by toRow. Half of data are ARR_WORDS (byte strings), Actions and lists.
formatMany pretty much makes one long ByteString from pieces assembled from nested lists of Actions. Actions are converted to ByteString Builders, which retain ByteStrings until used to produce final long strict ByteString.
These ByteStrings live long life up until final BS is constructed.
The strings need to be escaped with libPQ, so any non Plain action BS is passed to libPQ and replaced with new one in escapeStringConn and friends, adding more garbage.
If you replace Text in Thing with another Int, GC time drops from 75% to 45%.
I've tried to lessen use of temporary lists by formatMany and buildQuery, replacing mapM with foldM over Builder. It does not help much but increases code complexity a bit.
TLDR - Builders can't be consumed lazily because all of them are needed to produce final strict ByteString (pretty much array of bytes).
If you have problem with memory, split executeMany into chunks inside same transaction.