Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Performance issues for "bal -V" when having a lot of market prices #999

Open
erikryb opened this issue Apr 2, 2019 · 18 comments

Comments

Projects
None yet
2 participants
@erikryb
Copy link

commented Apr 2, 2019

I have a lot of market prices in my journal. Daily market prices for several commodities, about 25000 entries in total. The command "bal -V" is very slow as a result. This is the result of profiling:

	Mon Apr  1 22:15 2019 Time and Allocation Profiling Report  (Final)

	   hledger +RTS -p -RTS bal assets liabilities -V

	total time  =      119.74 secs   (119737 ticks @ 1000 us, 1 processor)
	total alloc = 106,803,275,920 bytes  (excludes profiling overheads)

COST CENTRE MODULE              SRC                                      %time %alloc

amountValue Hledger.Data.Amount Hledger/Data/Amount.hs:(452,1)-(455,16)   96.2   97.0
                                                                                                                 individual     inherited
COST CENTRE                   MODULE                SRC                                         no.   entries  %time %alloc  %time %alloc
    journalApplyValue         Hledger.Cli.Utils     Hledger/Cli/Utils.hs:(127,1)-(133,22)       2481       1    0.0    0.0   96.3   97.0
     overJournalAmounts       Hledger.Data.Journal  Hledger/Data/Journal.hs:1009:1-74           2612       1    0.0    0.0   96.3   97.0
      traverseJournalAmounts  Hledger.Data.Journal  Hledger/Data/Journal.hs:(1017,1)-(1026,38)  2613       1    0.0    0.0   96.3   97.0
       amountValue            Hledger.Data.Amount   Hledger/Data/Amount.hs:(452,1)-(455,16)     2717    9921   96.2   97.0   96.3   97.0

The function "amountValue" calls the function "commodityValue", which seems to be sorting the market prices. This may be the reason it performs so slowly. Perhaps the solution would be to store the market prices internally in a data type which has faster lookup, instead of having to sort the entries from the journal every time?

EDIT: One option is having jmarketprices :: SortedList MarketPrice in the Journal type, where SortedList is from here.

@simonmichael

This comment has been minimized.

Copy link
Owner

commented Apr 3, 2019

Thanks for the report. Just curious, how many years' worth of data do you have in that one file ?

@erikryb

This comment has been minimized.

Copy link
Author

commented Apr 4, 2019

Thanks for the report. Just curious, how many years' worth of data do you have in that one file ?

Some of the entries in that run dated back to 2001, which I realize is more than necessary for me. If I remove all entries before 2010, it still takes over one minute to run the command. I now have daily prices of 10 commodities, where two go back to 2017, two to 2013, one to 2011, and the rest to 2010.

@simonmichael

This comment has been minimized.

Copy link
Owner

commented Apr 19, 2019

@erikryb not necessary for this issue but it would be interesting to see stats output since 2001 & since 2010 too. As a one-year-at-a-time user I'm interested in what sort of performance others experience.

simonmichael added a commit that referenced this issue Apr 19, 2019

@simonmichael

This comment has been minimized.

Copy link
Owner

commented Apr 19, 2019

Some benchmark results, just for the record (with the same number of P records as transactions):

$ quickbench  "hledger -f examples/100x100x10-noprice.journal bal -V" "hledger -f examples/100x100x10.journal bal" "hledger -f examples/100x100x10.journal bal -V"
Running 3 tests 1 times at 2019-04-19 15:57:57 PDT:

Best times:
+-------------------------------------------------------++------+
|                                                       ||      |
+=======================================================++======+
| hledger -f examples/100x100x10-noprice.journal bal -V || 0.12 |
| hledger -f examples/100x100x10.journal bal            || 0.12 |
| hledger -f examples/100x100x10.journal bal -V         || 0.12 |
+-------------------------------------------------------++------+
$ quickbench  "hledger -f examples/1000x1000x10-noprice.journal bal -V" "hledger -f examples/1000x1000x10.journal bal" "hledger -f examples/1000x1000x10.journal bal -V"
Running 3 tests 1 times at 2019-04-19 15:45:47 PDT:

Best times:
+---------------------------------------------------------++------+
|                                                         ||      |
+=========================================================++======+
| hledger -f examples/1000x1000x10-noprice.journal bal -V || 0.30 |
| hledger -f examples/1000x1000x10.journal bal            || 0.30 |
| hledger -f examples/1000x1000x10.journal bal -V         || 0.46 |
+---------------------------------------------------------++------+
$ quickbench  "hledger -f examples/10000x1000x10-noprice.journal bal -V" "hledger -f examples/10000x1000x10.journal bal" "hledger -f examples/10000x1000x10.journal bal -V"
Running 3 tests 1 times at 2019-04-19 15:45:53 PDT:

Best times:
+----------------------------------------------------------++-------+
|                                                          ||       |
+==========================================================++=======+
| hledger -f examples/10000x1000x10-noprice.journal bal -V ||  1.20 |
| hledger -f examples/10000x1000x10.journal bal            ||  1.43 |
| hledger -f examples/10000x1000x10.journal bal -V         || 41.34 |
+----------------------------------------------------------++-------+
@simonmichael

This comment has been minimized.

Copy link
Owner

commented Apr 19, 2019

And profiterole-simplified profiles for the 10000 txn case without and with -V.

@simonmichael

This comment has been minimized.

Copy link
Owner

commented Apr 20, 2019

@erikryb SortedList sounds good, but I'm unsure how it will work with "-V chooses the most recent one, or in case of equal dates, the last-parsed one".

simonmichael added a commit that referenced this issue Apr 20, 2019

lib: speed up -V by sorting market prices just once (#999)
-V is still quite a bit slower than no -V, but not as much as before:

+===========================================================++=======+
| hledger.999.pre -f examples/10000x10000x10.journal bal    ||  5.20 |
| hledger.999.pre -f examples/10000x10000x10.journal bal -V || 57.20 |
| hledger.999 -f examples/10000x10000x10.journal bal        ||  5.34 |
| hledger.999 -f examples/10000x10000x10.journal bal -V     || 17.50 |
+-----------------------------------------------------------++-------+
@simonmichael

This comment has been minimized.

Copy link
Owner

commented Apr 20, 2019

The latest commit fixes the wasteful sorting of market prices that you pointed out, and documents how they should be sorted. I think we can't use SortedList because our market prices are only partly sorted (same-date prices should remain in parse order). Benchmark results show a speedup:

$ stack exec -- quickbench "hledger.999.pre -f examples/1000x1000x10.journal bal" "hledger.999.pre -f examples/1000x1000x10.journal bal -V" "hledger.999 -f examples/1000x1000x10.journal bal -V"
Running 3 tests 1 times at 2019-04-20 14:19:48 PDT:

Best times:
+---------------------------------------------------------++------+
|                                                         ||      |
+=========================================================++======+
| hledger.999.pre -f examples/1000x1000x10.journal bal    || 0.37 |
| hledger.999.pre -f examples/1000x1000x10.journal bal -V || 0.51 |
| hledger.999 -f examples/1000x1000x10.journal bal -V     || 0.47 |
+---------------------------------------------------------++------+
$ stack exec -- quickbench "hledger.999.pre -f examples/10000x1000x10.journal bal" "hledger.999.pre -f examples/10000x1000x10.journal bal -V" "hledger.999 -f examples/10000x1000x10.journal bal -V"
Running 3 tests 1 times at 2019-04-20 14:20:04 PDT:

Best times:
+----------------------------------------------------------++-------+
|                                                          ||       |
+==========================================================++=======+
| hledger.999.pre -f examples/10000x1000x10.journal bal    ||  1.26 |
| hledger.999.pre -f examples/10000x1000x10.journal bal -V || 48.77 |
| hledger.999 -f examples/10000x1000x10.journal bal -V     || 11.37 |
+----------------------------------------------------------++-------+

I have not yet profiled the latest, perhaps it can be improved further.

@simonmichael

This comment has been minimized.

Copy link
Owner

commented Apr 20, 2019

More measurements:

$ stack exec -- quickbench -n2 -v -whledger.999.pre,hledger.999 "hledger bal -V -fexamples/1000x1000x10.journal" "hledger bal -V -fexamples/2000x1000x10.journal" "hledger bal -V -fexamples/3000x1000x10.journal" "hledger bal -V -fexamples/4000x1000x10.journal" "hledger bal -V -fexamples/5000x1000x10.journal" "hledger bal -V -fexamples/6000x1000x10.journal" "hledger bal -V -fexamples/7000x1000x10.journal" "hledger bal -V -fexamples/8000x1000x10.journal" "hledger bal -V -fexamples/9000x1000x10.journal" "hledger bal -V -fexamples/10000x1000x10.journal"
Running 10 tests 2 times with 2 executables at 2019-04-20 15:02:26 PDT:

Best times:
+-----------------------------------------++-----------------+-------------+
|                                         || hledger.999.pre | hledger.999 |
+=========================================++=================+=============+
| bal -V -fexamples/1000x1000x10.journal  ||            0.56 |        0.47 |
| bal -V -fexamples/2000x1000x10.journal  ||            1.31 |        0.80 |
| bal -V -fexamples/3000x1000x10.journal  ||            2.23 |        1.20 |
| bal -V -fexamples/4000x1000x10.journal  ||            4.15 |        2.92 |
| bal -V -fexamples/5000x1000x10.journal  ||           10.67 |        4.15 |
| bal -V -fexamples/6000x1000x10.journal  ||           10.99 |        4.80 |
| bal -V -fexamples/7000x1000x10.journal  ||           20.94 |        9.74 |
| bal -V -fexamples/8000x1000x10.journal  ||           27.87 |        8.18 |
| bal -V -fexamples/9000x1000x10.journal  ||           36.83 |       12.65 |
| bal -V -fexamples/10000x1000x10.journal ||           48.54 |       15.62 |
+-----------------------------------------++-----------------+-------------+

The old one looks superlinear (not O(n^2) as I expected), and the new one looks quicker but still superlinear. I suppose the fact that both number of transactions and number of prices are increasing complicates things a bit. Also there are some odd bumps in the performance curve so maybe these numbers can't really tell the story.

@simonmichael

This comment has been minimized.

Copy link
Owner

commented Apr 21, 2019

+------------------------------------------++-----------------+---------+
|                                          || hledger.999.pre | hledger |
+==========================================++=================+=========+
| -f examples/10000x1000x10.journal bal -V ||           44.88 |   21.38 |
| -f examples/20000x1000x10.journal bal -V ||          315.92 |   85.86 |
| -f examples/30000x1000x10.journal bal -V ||          687.99 |  184.97 |
+------------------------------------------++-----------------+---------+

simonmichael added a commit that referenced this issue Apr 22, 2019

simonmichael added a commit that referenced this issue Apr 22, 2019

lib: add a test for journalApplyValue that times itself (#999)
This test prints the time elapsed (before the OK message).
Mainly to support current performance tuning
(make ghcid-test-Hledger.Cli.Utils.journalApplyValue),
but also for future reference.
@simonmichael

This comment has been minimized.

Copy link
Owner

commented Apr 23, 2019

  • It's still slow because we are still searching/filtering the whole price list once per posting.
  • It's not that easy to see how to make this faster. It can be done (eg split prices by commodity, split into yearly buckets..), but..
  • This is an inherently expensive operation that really we shouldn't be doing. Originally we converted the final reported amounts to value, which is a much smaller number of amounts. Since baf232d we convert all posting amounts to value (as of the report end date) before running reports. This was an easy way to make the feature available to all commands. But it does too much work, and it won't allow showing the value as of each period end in periodic reports (I think). Better to move value conversion back to the individual reports, even though it's more tedious coding.
@simonmichael

This comment has been minimized.

Copy link
Owner

commented Apr 23, 2019

  • Namely the balance, print and register commands and their variants.

simonmichael added a commit that referenced this issue Apr 23, 2019

simonmichael added a commit that referenced this issue Apr 24, 2019

speed up -V/--value by converting reports, not the journal (#999)
Instead of converting all journal amounts to value early on, we now
convert just the report amounts to value, before rendering.

This was basically how it originally worked (for the balance command),
but now it's built in to the four basic reports used by print,
register, balance and their variants - Entries, Postings, Balance,
MultiBalance - each of which now has its own xxValue helper.

This should mostly fix -V's performance when there are many
transactions and prices (the price lookups could still be optimised),
and allow more flexibility for report-specific value calculations.

+------------------------------------------++-----------------+-------------------+--------------------------+
|                                          || hledger.999.pre | hledger.999.1sort | hledger.999.after-report |
+==========================================++=================+===================+==========================+
| -f examples/1000x1000x10.journal bal -V  ||            1.08 |              0.96 |                     0.76 |
| -f examples/2000x1000x10.journal bal -V  ||            1.65 |              1.05 |                     0.73 |
| -f examples/3000x1000x10.journal bal -V  ||            2.43 |              1.58 |                     0.84 |
| -f examples/4000x1000x10.journal bal -V  ||            4.39 |              1.96 |                     0.93 |
| -f examples/5000x1000x10.journal bal -V  ||            7.75 |              2.99 |                     1.07 |
| -f examples/6000x1000x10.journal bal -V  ||           11.21 |              3.72 |                     1.16 |
| -f examples/7000x1000x10.journal bal -V  ||           16.91 |              4.72 |                     1.19 |
| -f examples/8000x1000x10.journal bal -V  ||           27.10 |              9.83 |                     1.40 |
| -f examples/9000x1000x10.journal bal -V  ||           39.73 |             15.00 |                     1.51 |
| -f examples/10000x1000x10.journal bal -V ||           50.72 |             25.61 |                     2.15 |
+------------------------------------------++-----------------+-------------------+--------------------------+

There's one new limitation, not yet resolved: -V once again can pick a
valuation date in the future, if no report end date is specified and
the journal has future-dated transactions. We prefer to avoid that,
but reports currently are pure and don't have access to today's date.
@simonmichael

This comment has been minimized.

Copy link
Owner

commented Apr 24, 2019

@erikryb, let me know how that one performs in your setup. From the commit message:

Instead of converting all journal amounts to value early on, we now
convert just the report amounts to value, before rendering.
...
This should mostly fix -V's performance when there are many
transactions and prices (the price lookups could still be optimised),
and allow more flexibility for report-specific value calculations.

+------------------------------------------++-----------------+-------------------+--------------------------+
|                                          || hledger.999.pre | hledger.999.1sort | hledger.999.after-report |
+==========================================++=================+===================+==========================+
| -f examples/1000x1000x10.journal bal -V  ||            1.08 |              0.96 |                     0.76 |
| -f examples/2000x1000x10.journal bal -V  ||            1.65 |              1.05 |                     0.73 |
| -f examples/3000x1000x10.journal bal -V  ||            2.43 |              1.58 |                     0.84 |
| -f examples/4000x1000x10.journal bal -V  ||            4.39 |              1.96 |                     0.93 |
| -f examples/5000x1000x10.journal bal -V  ||            7.75 |              2.99 |                     1.07 |
| -f examples/6000x1000x10.journal bal -V  ||           11.21 |              3.72 |                     1.16 |
| -f examples/7000x1000x10.journal bal -V  ||           16.91 |              4.72 |                     1.19 |
| -f examples/8000x1000x10.journal bal -V  ||           27.10 |              9.83 |                     1.40 |
| -f examples/9000x1000x10.journal bal -V  ||           39.73 |             15.00 |                     1.51 |
| -f examples/10000x1000x10.journal bal -V ||           50.72 |             25.61 |                     2.15 |
+------------------------------------------++-----------------+-------------------+--------------------------+

There's one new limitation, not yet resolved: -V once again can pick a
valuation date in the future, if no report end date is specified and
the journal has future-dated transactions. We prefer to avoid that,
but reports currently are pure and don't have access to today's date.
@erikryb

This comment has been minimized.

Copy link
Author

commented Apr 24, 2019

@simonmichael, the results look very promising! I will let you know when I have tested it. Thanks a lot! 😃

@erikryb

This comment has been minimized.

Copy link
Author

commented Apr 24, 2019

I have since last time added daily prices for the rest of the commodities that I have, and have now 57852 price entries in total. The new commit makes a great improvement!

Before:
hledger bal assets liabilities -V 301.17s user 0.76s system 100% cpu 5:01.65 total

After:
hledger bal assets liabilities -V 2.77s user 0.10s system 99% cpu 2.873 total

Without -V (latest version):
hledger bal assets liabilities 2.49s user 0.09s system 99% cpu 2.592 total

The difference between -V and no -V is quite small in the latest version, so performance tuning should probably be directed elsewhere for now. You may close the issue if you agree. Thanks again!

@simonmichael

This comment has been minimized.

Copy link
Owner

commented Apr 24, 2019

Presumably the difference is small because your report is not showing many numbers. I realised that with many columns, there could easily be more numbers to convert under the new mechanism. Eg in the test below,

  • we used to convert 20k amounts (10k txns x 2 postings)
  • now we convert 14 million amounts! (10k accounts x 1400 weekly columns)
$ stack exec -- quickbench -w hledger.999.pre,hledger.999.1sort,hledger.999.after-report "hledger -f examples/10000x1000x10.journal bal -W" "hledger -f examples/10000x1000x10.journal bal -WV"
Running 2 tests 1 times with 3 executables at 2019-04-24 07:22:16 PDT:

Best times:
+-------------------------------------------++-----------------+-------------------+--------------------------+
|                                           || hledger.999.pre | hledger.999.1sort | hledger.999.after-report |
+===========================================++=================+===================+==========================+
| -f examples/10000x1000x10.journal bal -W  ||           41.07 |             38.60 |                    38.85 |
| -f examples/10000x1000x10.journal bal -WV ||           87.64 |             70.65 |                    38.50 |
+-------------------------------------------++-----------------+-------------------+--------------------------+

And yet we see no slowdown at all here. Perhaps because most of the reported values are zero ? I tested with more non-zero reported amounts (20k in the balance report):

$ stack exec -- quickbench -w hledger.999.after-report "hledger -f examples/10000x1000x10.journal bal -Y" "hledger -f examples/10000x1000x10.journal bal -YV" "hledger -f examples/10000x1000x10.journal reg" "hledger -f examples/10000x1000x10.journal reg -V" "hledger -f examples/10000x1000x10.journal print" "hledger -f examples/10000x1000x10.journal print -V"
Running 6 tests 1 times with 1 executables at 2019-04-24 08:04:06 PDT:

Best times:
+---------------------------------------------------------------------++--------------------------+
|                                                                     || hledger.999.after-report |
+=====================================================================++==========================+
| hledger.999.after-report -f examples/10000x1000x10.journal bal -Y   ||                     3.14 |
| hledger.999.after-report -f examples/10000x1000x10.journal bal -YV  ||                     3.20 |
| hledger.999.after-report -f examples/10000x1000x10.journal reg      ||                     4.31 |
| hledger.999.after-report -f examples/10000x1000x10.journal reg -V   ||                     4.82 |
| hledger.999.after-report -f examples/10000x1000x10.journal print    ||                     3.35 |
| hledger.999.after-report -f examples/10000x1000x10.journal print -V ||                     3.53 |
+---------------------------------------------------------------------++--------------------------+

Still no slowdown. I'm not sure why.

simonmichael added a commit that referenced this issue Apr 24, 2019

@erikryb

This comment has been minimized.

Copy link
Author

commented Apr 25, 2019

For the bal -W report most of the amounts are indeed zero. I think the number of non-zero amounts cannot be larger than the number of postings, so there should be no slowdown compared to the old way. But if you do bal -WH, with historical amounts, you may get arbitrarily many non-zero amounts. This would result in a slowdown compared to the old version. However, the balance of an account may change only when the account has a transaction, so it should still be possible to compute the values in O(#postings) time.

@erikryb

This comment has been minimized.

Copy link
Author

commented Apr 25, 2019

Here is a comparison which shows the running time of computing daily historical balances on the file generated by runhaskell tools/generatejournal.hs 10000 1000 10.

Old version:
hledger -f examples/10000x1000x10.journal bal -DVH 431.93s user 3.25s system 100% cpu 7:14.91 total

New version:
hledger -f examples/10000x1000x10.journal bal -DVH 530.83s user 4.07s system 100% cpu 8:54.60 total

The difference in running time should be minimized if we convert values before adding them when doing historical or cumulative reports.

simonmichael added a commit that referenced this issue May 3, 2019

valuation: more thorough --value-at; document status (#329, #999)
This feature turns out to be quite involved, as valuation interacts
with the many report variations. Various bugs/specs have been
fixed/clarified relating to register's running total, balance totals
etc. Eg register's total should now be the sum of the posting amount
values, not the values of the original sums. Current level of support
has been documented.

When valuing at transaction date, we once again do early valuation of
all posting amounts, to get more correct results. variants. This means
--value-at=t can be slower than other valuation modes when there are
many transactions and many prices. This could be revisited for
optimisation when things are more settled.
@simonmichael

This comment has been minimized.

Copy link
Owner

commented May 3, 2019

As noted in commit ebf5ed9, certain valuation modes are now slow again (balance --value-at=transaction, mainly) in order to get correct results. The valuation modes which can be done quickly (eg the default -V) are still quick.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.