1.29-1.32.2: performance regression with many accounts

[markokocic]

This issue was discussing a severe performance regression affecting 1.29-1.32.2 with many accounts.
(There is a separate moderate drop in general performance affecting hledger 1.26 and later, see #2122.
The issue for comparing hledger vs Ledger performance is #2363.)

---

Lately I noticed that hledger was not as fast as it was. It is an issue because some scripts that I have that execute hledger multiple times are becoming very slow.

I decided to benchmark it against ledger.

My system:

marko@fine ~> hledger stats
Main file                : /home/marko/src/ledgers/transactions.ledger
Included files           :
Transactions span        : 2011-11-29 to 2024-01-16 (4431 days)
Last transaction         : 2024-01-15 (3 days from now)
Transactions             : 17385 (3.9 per day)
Transactions last 30 days: 156 (5.2 per day)
Transactions last 7 days : 37 (5.3 per day)
Payees/descriptions      : 3382
Accounts                 : 470 (depth 6)
Commodities              : 4 ($, inr, rsd, €)
Market prices            : 0 ()

Run time (throughput)    : 3.45s (5035 txns/s)

Balance command

marko@fine ~> time hledger bal > /dev/null

________________________________________________________
Executed in    4.07 secs    fish           external
   usr time    3.91 secs  878.00 micros    3.91 secs
   sys time    0.18 secs  185.00 micros    0.18 secs

Then I converted my journal file in order to use it with ledger:

marko@fine ~> hledger print --round=soft > test.journal

And tested it again with ledger

marko@fine ~> time ledger bal -f test.journal > /dev/null

________________________________________________________
Executed in  381.00 millis    fish           external
   usr time  344.67 millis    1.35 millis  343.31 millis
   sys time   36.13 millis    0.20 millis   35.93 millis

The result is that for balance operation, hledger takes 10 times more time that ledger.

My system is a small Linux VM with 2 CPU and 4 GB RAM. Hledger is the latest one built from source.

Other commands are also slower. Notice above that hledger print took 3.45 seconds. In ledger it's less than 1 second.

marko@fine ~> time ledger print -f test.journal > /dev/null

________________________________________________________
Executed in    1.13 secs      fish           external
   usr time  984.76 millis    1.29 millis  983.47 millis
   sys time  144.16 millis    0.23 millis  143.92 millis

[simonmichael]

Thanks for this useful data @markokocic. See https://hledger.org/ledger.html#performance - Ledger was always up to 10x faster with "big data" in certain reports. Usually I compare our performance relative to past versions as well as Ledger. Here's what I get just now on a macbook air m1:

~/src/hledger$ just --set BENCHEXES ledger,hledger-1.29,hledger-1.30,hledger-1.31,hledger-1.32 bench 
Running benchmarks with ledger,hledger-1.29,hledger-1.30,hledger-1.31,hledger-1.32 (times are approximate, can be skewed):
Running 4 tests 1 times with 5 executables at 2024-01-12 07:08:16 HST:

Best times:
+----------------------------------------------------++--------+--------------+--------------+--------------+--------------+
|                                                    || ledger | hledger-1.29 | hledger-1.30 | hledger-1.31 | hledger-1.32 |
+====================================================++========+==============+==============+==============+==============+
| -f examples/10000x1000x10.journal print            ||   5.48 |         0.80 |         0.85 |         0.86 |         0.89 |
| -f examples/10000x1000x10.journal register         ||  16.88 |         5.04 |         5.43 |         6.25 |         4.89 |
| -f examples/10000x1000x10.journal balance          ||   0.42 |         0.83 |         0.85 |         0.86 |         0.80 |
| -f examples/10000x1000x10.journal balance --weekly ||   0.40 |        11.19 |         9.42 |        10.19 |         9.94 |
+----------------------------------------------------++--------+--------------+--------------+--------------+--------------+

These benchmarks are using the 10k-transaction sample file, about half the size of yours:

~/src/hledger$ hledger-1.32 -f examples/10000x1000x10.journal stats
Main file                : /Users/simon/src/hledger/examples/10000x1000x10.journal
Included files           : 
Transactions span        : 2000-01-01 to 2027-05-19 (10000 days)
Last transaction         : 2027-05-18 (1222 days from now)
Transactions             : 10000 (1.0 per day)
Transactions last 30 days: 31 (1.0 per day)
Transactions last 7 days : 8 (1.1 per day)
Payees/descriptions      : 10000
Accounts                 : 1000 (depth 10)
Commodities              : 26 (A, B, C, D, E, F, G, H, I, J, K, L, M, N, O, P, Q, R, S, T, U, V, W, X, Y, Z)
Market prices            : 10000 (A)

Run time (throughput)    : 0.76s (13157 txns/s)

hledger vs hledger:

• This is a faster machine than yours but we'd expect the performance change over time to be similar.
• I'm not seeing a slowdown in recent hledger.
• Two years ago with 1.24.99 (see doc) I was achieving 23k txns/s on this machine, and I haven't seen that recently. Possibly a slowdown since then, or some other explanation..

hledger vs Ledger:

• This brew-installed Ledger binary might be wrongly built in debug mode and not showing its true speed; I seem to remember that being an issue. Though, we have the impression the Ledger formula is built with proper release options..

[simonmichael]

What are the details of your ledger and hledger installations - optimised system packages ? Which distro ?

Could you check memory usage ? Perhaps hledger is using all of yours and swapping ? Here are three ways:

• use GNU time (/usr/bin/time maybe)
• add +RTS -s -RTS to hledger commands
• watch while it runs in a fast-updating top

[markokocic]

hi @simonmichael

I wasn't under the impression that my ledger file is considered big :)

I am using Debian unstable. Ledger is the one that comes with it. Hledger is built from git using stack install

marko@fine:~$ time ledger b -f test.journal > /dev/null

real    0m0.426s
user    0m0.366s
sys     0m0.061s

marko@fine:~$ time hledger bal -f test.journal > /dev/null

real    0m3.610s
user    0m3.443s
sys     0m0.185s

marko@fine:~$ ledger --version
Ledger 3.3.2-20230330, the command-line accounting tool
without support for gpg encrypted journals and with Python support

Copyright (c) 2003-2023, John Wiegley.  All rights reserved.

This program is made available under the terms of the BSD Public License.
See LICENSE file included with the distribution for details and disclaimer.

marko@fine:~$ hledger --version
hledger 1.32.99-g76209d576-20240109, linux-x86_64
marko@fine:~$

marko@fine:~$ time hledger +RTS -s -RTS bal -f test.journal > /dev/null
   3,737,626,528 bytes allocated in the heap
     357,050,840 bytes copied during GC
      60,780,704 bytes maximum residency (9 sample(s))
       1,845,336 bytes maximum slop
             157 MiB total memory in use (0 MiB lost due to fragmentation)

                                     Tot time (elapsed)  Avg pause  Max pause
  Gen  0       897 colls,     0 par    0.471s   0.473s     0.0005s    0.0090s
  Gen  1         9 colls,     0 par    0.510s   0.511s     0.0567s    0.1683s

  TASKS: 4 (1 bound, 3 peak workers (3 total), using -N1)

  SPARKS: 0 (0 converted, 0 overflowed, 0 dud, 0 GC'd, 0 fizzled)

  INIT    time    0.002s  (  0.002s elapsed)
  MUT     time    2.238s  (  2.219s elapsed)
  GC      time    0.982s  (  0.984s elapsed)
  EXIT    time    0.001s  (  0.005s elapsed)
  Total   time    3.223s  (  3.210s elapsed)

  Alloc rate    1,669,829,075 bytes per MUT second

  Productivity  69.4% of total user, 69.1% of total elapsed


real    0m3.229s
user    0m3.049s
sys     0m0.193s
marko@fine:~$

I then ran hledger again multiple times and watched memory usage in top, and its virtual memory was around ~1gb, and resident maxed around 150-180 M. There was enough RAM available in VM and swap was not used.

[simonmichael]

Yours is not "big data" :), but it's bigger than the files most users typically work with (I am guessing most of us split by year to avoid such slowness). And it's big enough where traditionally it's expected that Ledger will be faster.

I haven't yet been able to reproduce this on mac though. I'll try it on a GNU/linux machine.

Your initial report said that hledger itself is getting slower; this would be more concerning. You can check that by benchmarking with some BENCHEXES like I did above.

[simonmichael]

Any more info on this @markokocic ? Can you show a slowdown in recent hledger versions ?

[markokocic]

hi @simonmichael , sorry for the delay, compiling hledger from source on my system takes a bit of time :)

Here I compiled from source using stack install hledger current git head and branches 1.28 and 1.30 and did a quick comparison using my journal. I run every command multiple times and here are representative samples.

Here are some timings (with warm filesystem cache):

Print command:

marko@fine:~$ time hledger-1.28 print > /dev/null

real    0m2.326s
user    0m2.169s
sys     0m0.158s
marko@fine:~$ time hledger-1.30 print > /dev/null

real    0m3.506s
user    0m3.331s
sys     0m0.194s
marko@fine:~$ time hledger-upstream print > /dev/null

real    0m3.845s
user    0m3.632s
sys     0m0.222s

Balance command:

marko@fine:~$ time hledger-1.28 bal > /dev/null

real    0m2.101s
user    0m1.953s
sys     0m0.157s
marko@fine:~$ time hledger-1.30 bal > /dev/null

real    0m3.061s
user    0m2.906s
sys     0m0.169s
marko@fine:~$ time hledger-upstream bal > /dev/null

real    0m3.150s
user    0m2.928s
sys     0m0.237s

As you can see, hledger 1.30 is significantly slower than 1.28, and current git again a bit slower than that.

If you want me to try a specific build, let me know, and I'll compile and run it.

[simonmichael]

Thank you! When you have time, would you mind repeating those timings with examples/10000x10000x10.journal ? You can make that with just samplejournals or make samplejournals.

[markokocic]

Balance:

marko@fine:~/src/cvstree/hledger$ time hledger-1.28 bal -f examples/10000x10000x10.journal > /dev/null

real    0m3.788s
user    0m3.664s
sys     0m0.137s
marko@fine:~/src/cvstree/hledger$ time hledger-1.28 bal -f examples/10000x10000x10.journal > /dev/null

real    0m2.378s
user    0m2.251s
sys     0m0.133s
marko@fine:~/src/cvstree/hledger$ time hledger-1.30 bal -f examples/10000x10000x10.journal > /dev/null

real    0m10.405s
user    0m10.304s
sys     0m0.153s
marko@fine:~/src/cvstree/hledger$ time hledger-1.30 bal -f examples/10000x10000x10.journal > /dev/null

real    0m10.616s
user    0m10.517s
sys     0m0.153s
marko@fine:~/src/cvstree/hledger$ time hledger-upstream bal -f examples/10000x10000x10.journal > /dev/null

real    0m11.772s
user    0m11.631s
sys     0m0.202s
marko@fine:~/src/cvstree/hledger$ time hledger-upstream bal -f examples/10000x10000x10.journal > /dev/null

real    0m10.661s
user    0m10.518s
sys     0m0.194s

Print:

marko@fine:~/src/cvstree/hledger$ time hledger-1.28 print -f examples/10000x10000x10.journal > /dev/null

real    0m1.890s
user    0m1.786s
sys     0m0.105s
marko@fine:~/src/cvstree/hledger$ time hledger-1.28 print -f examples/10000x10000x10.journal > /dev/null

real    0m1.604s
user    0m1.523s
sys     0m0.081s
marko@fine:~/src/cvstree/hledger$ time hledger-1.30 print -f examples/10000x10000x10.journal > /dev/null

real    0m9.865s
user    0m9.719s
sys     0m0.189s
marko@fine:~/src/cvstree/hledger$ time hledger-1.30 print -f examples/10000x10000x10.journal > /dev/null

real    0m9.911s
user    0m9.809s
sys     0m0.146s
marko@fine:~/src/cvstree/hledger$ time hledger-upstream print -f examples/10000x10000x10.journal > /dev/null

real    0m11.398s
user    0m11.236s
sys     0m0.217s
marko@fine:~/src/cvstree/hledger$ time hledger-upstream print -f examples/10000x10000x10.journal > /dev/null

real    0m9.836s
user    0m9.739s
sys     0m0.141s

Here is the difference even more drastical than in my journal file. The drop in 1.30 is even more visible. I'm building 1.29 right now, will post the results later.

[markokocic]

Ok, just built 1.29 and repeated the same test:

marko@fine:~/src/cvstree/hledger$ time hledger-1.29 print -f examples/10000x10000x10.journal > /dev/null

real    0m10.524s
user    0m10.429s
sys     0m0.141s
marko@fine:~/src/cvstree/hledger$ time hledger-1.29 print -f examples/10000x10000x10.journal > /dev/null

real    0m9.934s
user    0m9.577s
sys     0m0.401s
marko@fine:~/src/cvstree/hledger$ time hledger-1.29 print -f examples/10000x10000x10.journal > /dev/null

real    0m10.761s
user    0m10.634s
sys     0m0.170s
marko@fine:~/src/cvstree/hledger$ time hledger-1.29 bal -f examples/10000x10000x10.journal > /dev/null

real    0m12.260s
user    0m12.147s
sys     0m0.166s
marko@fine:~/src/cvstree/hledger$ time hledger-1.29 bal -f examples/10000x10000x10.journal > /dev/null

real    0m10.653s
user    0m10.045s
sys     0m0.661s

As the results show, the main slowdown started with 1.29. After that, it became a bit slower, but not so significantly.

[simonmichael]

Thanks! Very strange. I'll try to reproduce it on other platforms.