[Monotone-devel] Re: nvm.error-handling seems to have caused a serious slowdown

[Timothy Brownawell]

On Mon, 2009-01-26 at 23:10 -0800, Zack Weinberg wrote:
> I just merged mainline into .stripped and I noticed a major slowdown
> in the testsuite, which seems to be down to the error-handling
> changes:  "make check-local -j4" goes like this:
> 
> before merge
> 
> real   5m8.249s
> user  3m45.818s
> sys    5m20.672s
> 
> after merge
> 
> real   6m17.184s
> user  7m54.486s
> sys    5m36.285s

Hmm, I'm not seeing any noticeable slowdown:

==> src/after.times <== "\time ../lua-testsuite.lua"
578.72user 225.81system 47:19.29elapsed 28%CPU 
20112inputs+2254184outputs (45major+18135301minor)pagefaults 0swaps

==> src/before.times <== ... without error-handling branch
577.48user 223.32system 39:39.02elapsed 33%CPU 
17928inputs+2254104outputs (34major+18067510minor)pagefaults 0swaps

==> src/unit-after.times <== "\time make unit_tests.status"
603.86user 33.67system 17:57.09elapsed 59%CPU 
23072inputs+269792outputs (81major+549280minor)pagefaults 0swaps

==> src/unit-before.times <== ... without error-handling branch
596.35user 32.25system 14:26.97elapsed 72%CPU 
1488inputs+271392outputs (8major+551171minor)pagefaults 0swaps

> That's pretty nasty.  I haven't looked into the cause at all, but I
> wonder if the extra field in every vocab object is blowing us out of
> the D-cache...

It looks like it's 12 bytes instead of 8, but there's also the (shared)
string it points to and some shared data for the shared_ptr. I don't
think we have enough copies of the same vocab objects for this to really
matter (well, maybe in the random uncommon ancestors and roster actions
tests)? Plus oprofile doesn't show any big shifts in where time is
spent, but then perhaps it wouldn't if it didn't fit in cache for me in
the first place (except that those two tests don't take up over half the
time)...


The testsuite seems to spend about a third of it's monotone time (as
opposed to time in the tester itself or other utilities) making certs
under "mtn commit". That's 20% or so decrypting keys, and 10% or so
actually signing things. There's also 8-9% each in libstdc++ (no
symbols) and liblua5.1 (no symbols), and 3.5-4% in libsqlite3 (no
symbols).


The unit tester spends 36-37% in "id::operator<(id const &)" (from
toposort_rev_ancestry from the get_uncommon_ancestors_randomly test).
There's also 16-17% in libstdc++ (no symbols), and about 10% in
malloc-related functions.


-- 
Timothy

Free (experimental) public monotone hosting: http://mtn-host.prjek.net