ledger v3 slower than ledger v2

[thierry]

Hello,

On below tests, ledger v3 is 21 and 46 times slower that ledger v2.
Some specs:
- CPU is AMD Athlon(tm) Dual Core Processor 4850e, 2500MHz, 64 bits
- RAM is 1790MiB
- OS is Ubuntu 9.10

John, I sent you privately the ledger file.

Thierry

---

$ ledger3 print --anon -f thierry.ledger > thierry.ledger.anon

$ time ledger -f thierry.ledger.anon reg 2eb75f84 1eede0cb >/dev/null
real 0m2.166s
user 0m1.940s
sys 0m0.210s

$ time ledger -f thierry.ledger.anon -V reg 2eb75f84 1eede0cb >/dev/
null
real 0m7.300s
user 0m7.050s
sys 0m0.160s

$ time ledger3 --european -f thierry.ledger.anon reg 2eb75f84 1eede0cb
>/dev/null
real 0m47.190s
user 0m18.100s
sys 0m28.770s

$ time ledger3 --european -f thierry.ledger.anon -V reg 2eb75f84
1eede0cb >/dev/null
real 5m42.510s
user 3m0.020s
sys 2m40.350s

$ ledger -v
Ledger 2.6.2, the command-line accounting tool
$ ledger3 -v
Ledger master-0-g5471370, the command-line accounting tool

[John Wiegley]

On Feb 27, 2010, at 5:37 PM, thierry wrote:

> On below tests, ledger v3 is 21 and 46 times slower that ledger v2.

How did you build it?

John

[Thierry Daucourt]

How did you build it?

I followed instruction from http://github.com/jwiegley/ledger/,
That are:

git clone git://github.com/jwiegley/ledger.git
cd ledger && ./acprep update



Except that instead of:

sudo apt-get install autoconf automake bjam build-essential cvs gettext libboost-date-time1.40-dev libboost-filesystem1.40-dev libboost-regex1.40-dev libboost1.40-dev libbz2-dev libgmp3-dev libmpfr-dev libtool python-dev texinfo zlib1g-dev

I did the following to be able to compile:

sudo apt-get install gccxml libboost-date-time-dev libboost-filesystem-dev libboost-iostreams-dev libboost-python-dev libboost-regex-dev libboost-serialization-dev libboost-serialization-dev libboost-system-dev libboost-system-dev libbsd-dev libcppunit-dev libgmp3-dev libgmpxx4ldbl libicu-dev libmpfr-dev libncurses5-dev python2.6-dev

[John Wiegley]

On Feb 28, 2010, at 5:28 AM, Thierry Daucourt wrote:

How did you build it?

cd ledger && ./acprep update

Try using "acprep opt update" instead, since right now you are building with full debugging on.  That tends to make things many times slower.

John

[Thierry Daucourt]

Hi John,

I did (first "acprep distclean" and then) "acprep opt update" as advised. This improved performance a lot.
But, see below, ledger v3 is still slower than ledger v2 by a ratio varying between 2.17 and 3.76.
26 seconds is a bit long for me, but acceptable compared to previous 5 minutes.

As an experiment, I played with "acprep gprof update" in a duplicated directory. My input ledger file contains 24920 non empty lines. and I was surprised by the number of calls to some ledger functions (between 150 and 200 millions of calls). I do not know if there is anything to dig in this area. I can send gprof output if needed.

Thierry


$ time ledger3 --european -f thierry.ledger --price-db prices.db -V reg ^Actif ^Passif >/dev/null
real    0m26.328s
user    0m25.820s
sys    0m0.110s
$ time ledger -f thierry.ledger --price-db prices.db -V reg ^Actif ^Passif >/dev/null
real    0m6.988s
user    0m6.730s
sys    0m0.220s

$ time ledger3 --european -f thierry.ledger -V reg ^Actif ^Passif >/dev/null
real    0m24.833s
user    0m24.720s
sys    0m0.100s
$ time ledger -f thierry.ledger -V reg ^Actif ^Passif >/dev/null
real    0m7.049s
user    0m6.840s
sys    0m0.200s

$ time ledger3 --european -f thierry.ledger --price-db prices.db reg ^Actif ^Passif >/dev/null
real    0m4.948s
user    0m4.700s
sys    0m0.230s
$ time ledger -f thierry.ledger --price-db prices.db reg ^Actif ^Passif >/dev/null
real    0m2.277s
user    0m1.970s
sys    0m0.280s


$ grep -c -v -E "^[:spaces:]*$" thierry.ledger
24920

[John Wiegley]

On Mar 1, 2010, at 10:29 AM, Thierry Daucourt wrote:

> As an experiment, I played with "acprep gprof update" in a duplicated directory. My input ledger file contains 24920 non empty lines. and I was surprised by the number of calls to some ledger functions (between 150 and 200 millions of calls). I do not know if there is anything to dig in this area. I can send gprof output if needed.

Yes, I would very much like to see your gprof output.

John

[John Wiegley]

Thierry,

It looks like you've exposed a somewhat pathological case with regard to multiple currencies. Ledger is doing far too much make work than it should be. Is there any chance I can gain access to your data file? Use "ledger print --anon" may, in your case, yield a file which still exposes this problem.

Thanks, John

On Feb 27, 2010, at 5:37 PM, thierry wrote:

[John Wiegley]

On Feb 27, 2010, at 3:37 PM, thierry wrote:

> On below tests, ledger v3 is 21 and 46 times slower that ledger v2.
> Some specs:
> - CPU is AMD Athlon(tm) Dual Core Processor 4850e, 2500MHz, 64 bits
> - RAM is 1790MiB
> - OS is Ubuntu 9.10

While I am working on this: how did you build ledger3? If you used apcrep, this is known to be much slower than 2.x. You have to build it as such:

acprep opt update

The optimized version is much faster -- although it won't beat 2.x, because it's doing a lot more.

John

[Thierry Daucourt]

On Sun, May 23, 2010 at 9:16 AM, John Wiegley <jwie...@gmail.com> wrote:

You have to build it as such:
 acprep opt update

Yes, that's what I did.

FYI, I've timed the duration of ledger to compare "./acprep opt update" and "./acprep opt update --boost=-mt"
On my first use case, duration was 5m59.399s (without mt) and 5m6.123s (with mt).
On a second use case, duration was 39m34.209s (without mt) and 39m9.758s (with mt).
I think I do not have to bother to compile with mt option enabled.

Thierry

[John Wiegley]

Wow, OK. I'm looking into this now. 

John

[thierry]

I've download next branch (with modification suppressing rounding) and
did "./acprep opt update" (no use of boost mt)

$ ledger -v
Ledger next-0-gefcede3, the command-line accounting tool

Here are results:

1. My first use case (something like "ledger Assets:Invest --exchange=
€ -J")
- 5m59.399s (previous ledger version, with rounding)
- 3m31.564s (this ledger version, without rounding)
- 0m1.314s (this ledger version, without rounding, without --exchange
option)

2. My second use case (something like "ledger Assets Liabilities --
exchange=€ -J")
- 39m34.209s (previous ledger version, with rounding)
- 27m1.114s (this ledger version, without rounding)
- 0m5.279s (this ledger version, without rounding, without --exchange
option)

There is definitely an amelioration by dropping the exact rounding
(41% for 1st, 32% for 2nd).
But may I ask to dig further about --exchange impact?

Thanks

Thierry

[John Wiegley]

On May 24, 2010, at 12:41 PM, thierry wrote:

> But may I ask to dig further about --exchange impact?

I absolutely will. :)

John

[John Wiegley]

On Feb 27, 2010, at 5:37 PM, thierry wrote:

> On below tests, ledger v3 is 21 and 46 times slower that ledger v2.

After several days of intensive examination, I think now there is little help for what you're seeing. The slowness comes from (a) the size of your data file and how many commodities you're using, and (b) the correctness and new behavior of --exchange (and, to a lesser extent, -V).

To illustrate what I mean, I've added a new command "pricemap". It outputs a DOT file showing the pricing relationships between all commodities in your data file at a given date. To give an example of how complex the situation can be, consider this data file:

http://ftp.newartisans.com/pub/exchange.dat

At 2009/01/03, the price relationships are as shown here:

http://ftp.newartisans.com/pub/090103.png

But by 2009/01/10, they have changed significantly:

http://ftp.newartisans.com/pub/090110.png

When you use --exchange $, Ledger tries to find the most recent conversion to $ that it can. To do this, it considers not only whether a commodity A could be priced in dollars, but whether it could also be priced in terms of B, which could then be priced in dollars. And so on. It must walk the graph of all possible connections to $, truncating the search only if the most recent valuation down that leg is older than the most recent found so far. Sometimes, it can take several hops before the most recent conversion price is found.

Note to mention that all of this can happen several times for a single posting: while computing the amount, the running total, to see if a revaluation has occurred, to see if a rounding error has occurred, etc.

I have managed to speed things up a fair bit, however, so please try your tests again with the latest 'next' branch. Here are the improvements, using an "acprep opt" build on a 2.26GHz Core i7 (all output going to /dev/null):

Before optimization work (current 'master' branch):

reg, no flags 6.86s
reg, -V 39.23s
reg, -X 85.92s

After optimization work (current 'next' branch):

reg, no flags 5.00s
reg, -V 13.39s
reg, -X 12.91s

John

[John Wiegley]

On Jun 4, 2010, at 6:02 AM, John Wiegley wrote:

> After optimization work (current 'next' branch):
>
> reg, no flags 5.00s
> reg, -V 13.39s
> reg, -X 12.91s

Note too that with --no-rounding, I can get -V and -X numbers within only 2x slower. That is, if you don't need that information (which strictly speaking is there only for exactitude, but adds little value).

John

[thdox]

On Mon, May 24, 2010 at 8:41 PM, thierry wrote:

I've download next branch (with modification suppressing rounding) and
did "./acprep opt update" (no use of boost mt)

I downloaded today the next branch source code

$ ledger -v
Ledger next-0-gefcede3, the command-line accounting tool

$ ledger -v
Ledger 3.0.0-20100623, the command-line accounting tool
 

Here are results:

1. My first use case (something like "ledger Assets:Invest --exchange=
€ -J")
- 5m59.399s (previous ledger version, with rounding)
- 3m31.564s (this ledger version, without rounding)
- 0m1.314s (this ledger version, without rounding, without --exchange
option)

- 0m7.001s (Ledger 3.0.0-20100623, with rounding)
- 0m6.289s (Ledger 3.0.0-20100623, without rounding)
- 0m1.291s (Ledger 3.0.0-20100623, without rounding, without --exchange option)
 

2. My second use case (something like "ledger Assets Liabilities --
exchange=€ -J")
- 39m34.209s (previous ledger version, with rounding)
- 27m1.114s (this ledger version, without rounding)
- 0m5.279s (this ledger version, without rounding, without --exchange
option)

- 1m0.702s (Ledger 3.0.0-20100623, with rounding)
- 0m54.790s (Ledger 3.0.0-20100623, without rounding)
- 0m5.558s (Ledger 3.0.0-20100623, without rounding, without --exchange option)
 

There is definitely an amelioration by dropping the exact rounding
(41% for 1st, 32% for 2nd).

The --no-rounding is a 10% speed improvement with Ledger 3.0.0-20100623 on my machine.
6.289/7.001=.898
54.790/60.702=.902
 

But may I ask to dig further about --exchange impact?

I definitely acknowledge the performance boost, and I am very happy of it!


One question :

Your results are :

> using an "acprep opt" build on a 2.26GHz Core i7 (all output going to /dev/null):
>

>    reg, no flags       5.00s
>    reg, -V            13.39s
>    reg, -X            12.91s

My results are, on a AMD Athlon(tm) Dual Core Processor 4850e, 2500MHz, 64 bits
 
$ time ledger reg        > /dev/null
real    0m12.727s
$ time ledger reg -X € > /dev/null
real    2m8.355s

The ratio are 12.7/5=2.54 and 128.355/12.91=9.94

When my ledger executable is running I can see that only one core is used. I suspect you used a compilation option that enables ledger executable to use several cores when running. Am I right ? What is this option ?
 

Thanks

Thank you very much for the speed improvement.

Thierry

[John Wiegley]

On Aug 10, 2010, at 5:58 PM, thdox wrote:

> Your results are :
>
> > using an "acprep opt" build on a 2.26GHz Core i7 (all output going to /dev/null):
> >
> > reg, no flags 5.00s
> > reg, -V 13.39s
> > reg, -X 12.91s
>
> My results are, on a AMD Athlon(tm) Dual Core Processor 4850e, 2500MHz, 64 bits
>
> $ time ledger reg > /dev/null
> real 0m12.727s
> $ time ledger reg -X € > /dev/null
> real 2m8.355s
>
> The ratio are 12.7/5=2.54 and 128.355/12.91=9.94
>
> When my ledger executable is running I can see that only one core is used. I suspect you used a compilation option that enables ledger executable to use several cores when running. Am I right ? What is this option ?

This is troubling. Ledger only ever uses one core, however it uses main memory pretty
heavily. So the fact that my i7 has direct access to main memory could account for a bit of the difference. But an order of magnitude? Also, on OS X I'm using the -fast option to gcc, which is often 2-3x faster than -O3. What version of gcc do you have?

John

[Simon Michael]

Looks like some nice speedups there!

[Thierry Daucourt]

> What version of gcc do you have?

$ gcc --version
gcc (Ubuntu 4.4.3-4ubuntu5) 4.4.3

> Also, on OS X I'm using the -fast option to gcc, which is often 2-3x faster than -O3.

--fast is a Mac OX X only option
(http://developer.apple.com/mac/library/documentation/DeveloperTools/gcc-4.0.1/gcc/Optimize-Options.html)

I've dig and read a little about compilation flags:
- gcc man pages
- gentoo Compilation Optimization Guide (a linux distro where they
recompile every bit), and they recommend "-march=k8 -O2 -pipe"
- AMD GCC Quick Reference Guide (my CPU is AMD Athlon 64 x2), and they
recommend "-O3 -mtune=k8 -funroll-all-loops -fprefetch-loop-arrays
-ffast-math"

Here are the results:

With defaults from "./acprep opt" :
CFLAGS = -O3 -fomit-frame-pointer
CXXFLAGS = -fpch-deps -Wconversion -pthread -O3 -fomit-frame-pointer -pipe
time ~/ledger/ledger reg -X € -J > /dev/null
real 2m5.204s

With CXXFLAGS = CFLAGS = -march=k8 -O2 -pipe
time ~/ledger-O2/ledger reg -X € -J > /dev/null
real 2m12.285s

With CXXFLAGS = CFLAGS = -O3 -mtune=k8 -funroll-all-loops
-fprefetch-loop-arrays -ffast-math
time ~/ledger-O3/ledger reg -X € -J > /dev/null
real 2m13.937s

My conclusion is that I will stick with defaults compiler flags from
"acprep opt"...

Thierry

[thierry]

Well, more than 2 minutes is still long, and this morning, while
thinking about it during breakfast, I've found the clue : the number
of "price relationships" as explained in
http://groups.google.com/group/ledger-cli/msg/8158214761fcf1ef.

So I've tested:
1) downsizing my prices.db to one value per month
2) reporting only monthly or yearly

% time ledger reg -X € -J
2m07.451s
% time ledger reg -X € -J --price-db prices.db-monthly
42.755s
% time ledger reg -X € -J -M
34.802s
% time ledger reg -X € -J -M --price-db prices.db-monthly
12.562s
% time ledger reg -X € -J -Y
9.555s
% time ledger reg -X € -J -Y --price-db prices.db-monthly
3.401s

% wc -l prices.db prices.db-monthly
14804 prices.db
963 prices.db-monthly

By reducing the number of registry lines to analyse (using --monthly=-
M or --yearly=-Y) *AND* by reducing the number of values in prices.db
files (by moving away from daily values to monthly values), the number
of "price relationships" is greatly reduced.
So, as "ledger reg -X € -J -M --price-db prices.db-monthly" is exactly
what I want, and 12 seconds is more than acceptable, I will consider
this thread as ended! ;-)

Thank you John for improvements and explanations

Thierry

[John Wiegley]

>>>>> thierry <thierry.daucou...@public.gmane.org> writes:

> Hello, On below tests, ledger v3 is 21 and 46 times slower that ledger v2.
> Some specs:
> - CPU is AMD Athlon(tm) Dual Core Processor 4850e, 2500MHz, 64 bits
> - RAM is 1790MiB
> - OS is Ubuntu 9.10

At last, Thierry, this is solved. I'm now using the Boost.Graph library to
manage historical commodity prices, and Dijkstra's shortest-path algorithm to
find most-recent conversion rates.

Care to test out your example again? :)

John

[thierry]

My specs are now:

- CPU is AMD Athlon(tm) Dual Core Processor 4850e, 2500MHz, 64 bits

(unchanged)
- RAM is 5474MiB (upgraded +4GB, anyway today ledger+OS did not pass
the 1.8GB RAM usage)
- OS is Ubuntu 11.10 (upgraded from 9.10)

In Aug 2010, my ledger file was 24920 non empty lines (I do not have
lines with only comments).
Today, my ledger file is 29901 non empty lines.

On Aug 2010, my price.db daily values was 14804 lines (I still have
that old file, but I do not use anymore price.db file with daily
values.

On Aug 2010, my price.db monthly values was 963 lines.
Today, my price.db is 1162 lines.

In the table below:
- 1st column are tests from 12-Aug-2010
- 2nd column are tests from today before compiling with Boost.Graph
- 3rd column are tests from today after compilation including
Boost.Graph

The compilation was done using :
$ ./acprep distclean
$ ./acprep opt update --no-patch

Output is redirected to /dev/null.

I re-used my tests from my 12-Aug-2010 post:

| reg -X € -J | 2m07.451s | 2m01.476s
| 1m16.583s |
| reg -X € -J --price-db prices.db-monthly | 0m42.755s | 1m04.551s
| 0m58.373s |
| reg -X € -J -M | 0m34.802s | 0m34.283s
| 0m24.437s |
| reg -X € -J -M --price-db prices.db-monthly | 0m12.562s | seg fault
| 0m19.944s |
| reg -X € -J -Y | 0m09.555s | 0m08.683s
| 0m07.117s |
| reg -X € -J -Y --price-db prices.db-monthly | 0m03.401s | 0m04.280s
| 0m05.448s |

My first conclusions is that having a price.db with daily values
(instead of monthly value) has less negative impact on performance
(now 25% slower instead of 100%slower). This is helpfull, because
maintaining my price.db with only monthly values is painful has I have
to filter by hand.

I digged further and compiled with
$ ./acprep gprof update

John, I will send you privately the gmon.out and gmon.txt files as
they are big.

With this profiling enabled, I believe that the culprit are functions
like exchange_commodities and find_price.

Best regards,
Thierry


On Mar 5, 12:07 pm, John Wiegley <jwieg...@gmail.com> wrote: