Xapian discuss - Aug 2020 - MultiDatabase shard count limitations

Olly Betts <olly at survex.com> wrote:
> The report you show seems to be just the time take by each function
> directly rather than including functions it calls.  It looks like a lot
> of the time is spent in cursor movement, as totalling up things that
> seem like they'd be due to that I quickly get to 40+% but it's hard
> to tell if that's about the actual total or if this is really where
> almost all time is spent.  If it were 50% then getting rid of it all
> would only halve the time which would be a nice speedup, but still
> too slow for your case (and some cursor movement is required as that's
> how we skip ahead in posting lists).
Understood.
> Can prof report time for a function including things it calls?
callgraph?  Attached is a profile the output of "perf report -g"
with callgraph info.  I'm no perf expert, either, but slowly
learning more as I go along...


Btw, I tried google-pprof (from the Debian stable
google-perftools 2.7-1 package) and couldn't figure it out...
Even the example from the manpage: `google-pprof /bin/ls ls.prof`
didn't seem to work.  It tried to open an invalid URL with
curl 'http://ls.prof/pprof/profile?seconds=30' ... *shrug*

On Mon, Aug 24, 2020 at 05:58:02AM +0000, Eric Wong
wrote:
> Olly Betts <olly at survex.com> wrote:
> > Can prof report time for a function including things it calls?
> 
> callgraph?  Attached is a profile the output of "perf report -g"
> with callgraph info.  I'm no perf expert, either, but slowly
> learning more as I go along...
The list seems to have stripped the attachment, but I was able to dig it
out from the message it sent saying it was held for approval for having
a large attachment.

That's kind of what I was after, in that it seems to be trying to show
time spent in "Children", but it doesn't seem to do that
completely so
I'm not sure how to interpret it.  I'd expect the parent of everything
to show up with 100% including Children (or close to 100%) but nothing
does.
> Btw, I tried google-pprof (from the Debian stable
> google-perftools 2.7-1 package) and couldn't figure it out...
> Even the example from the manpage: `google-pprof /bin/ls ls.prof`
> didn't seem to work.  It tried to open an invalid URL with
> curl 'http://ls.prof/pprof/profile?seconds=30' ... *shrug*
It seems to handle "file not found" by trying to load the filename as
a
URL - that rarely seems helpful, but in particular makes for a confusing
error message.

The docs say to link with -lprofiler but it seems to work fine to
LD_PRELOAD it and I find that easier to work with so I use it like so:

LD_PRELOAD=/usr/lib/x86_64-linux-gnu/libprofiler.so CPUPROFILE=$HOME/prof.out
/usr/bin/xapian-compact /mnt/data/scratch/text/tmp06.db
/mnt/data/scratch/text/06.db
google-pprof /usr/bin/xapian-compact $HOME/prof.out

At the prompt inside, "gv" renders a callgraph in postscript and
"callgrind" generates a file like that from valgrind's callgrind
tool
which you can inspect with kcachegrind, etc.

Cheers,
    Olly

Olly Betts <olly at survex.com> wrote:
> On Mon, Aug 24, 2020 at 05:58:02AM +0000, Eric Wong wrote:
> > Olly Betts <olly at survex.com> wrote:
> > > Can prof report time for a function including things it calls?
> > 
> > callgraph?  Attached is a profile the output of "perf report
-g"
> > with callgraph info.  I'm no perf expert, either, but slowly
> > learning more as I go along...
> 
> The list seems to have stripped the attachment, but I was able to dig it
> out from the message it sent saying it was held for approval for having
> a large attachment.
Oops, I forgot to take into account base64 encoding overhead
and thought it would fit (but maybe gzipping hit another filter)

For the sake of archival, that old report is downloadable via spew
(a random dumping ground of mine):
https://80x24.org/spew/20200825215246.GA9961 at dcvr/2-perf-report-g.txt.gz
> That's kind of what I was after, in that it seems to be trying to show
> time spent in "Children", but it doesn't seem to do that
completely so
> I'm not sure how to interpret it.  I'd expect the parent of
everything
> to show up with 100% including Children (or close to 100%) but nothing
> does.
So I managed to get current xapian.git (commit 61724d477edb)
built with CXXFLAGS=-ggdb3, and it's closer to 100%:

https://80x24.org/spew/20200825215517.GA3936 at
dcvr/2-perf-report-20200825-214820.gz

The machine I'm working on is also significantly busier at the
moment trying to reproduce an unrelated problem.
> > Btw, I tried google-pprof (from the Debian stable
> > google-perftools 2.7-1 package) and couldn't figure it out...
> > Even the example from the manpage: `google-pprof /bin/ls ls.prof`
> > didn't seem to work.  It tried to open an invalid URL with
> > curl 'http://ls.prof/pprof/profile?seconds=30' ... *shrug*
> 
> It seems to handle "file not found" by trying to load the
filename as a
> URL - that rarely seems helpful, but in particular makes for a confusing
> error message.
> 
> The docs say to link with -lprofiler but it seems to work fine to
> LD_PRELOAD it and I find that easier to work with so I use it like so:
> 
> LD_PRELOAD=/usr/lib/x86_64-linux-gnu/libprofiler.so
CPUPROFILE=$HOME/prof.out /usr/bin/xapian-compact
/mnt/data/scratch/text/tmp06.db /mnt/data/scratch/text/06.db
Ah, thanks, I managed to get that part working and generated a
prof.out file, at least
> google-pprof /usr/bin/xapian-compact $HOME/prof.out
> 
> At the prompt inside, "gv" renders a callgraph in postscript and
> "callgrind" generates a file like that from valgrind's
callgrind tool
> which you can inspect with kcachegrind, etc.
Unfortunately, google-pprof can't seem to figure out symbols
like perf can.  I had the same problem with the Debian-provided
-dbgsym packages for 1.4.11-1 as I am having with xapian.git

Neither the callgrind file from pprof nor "top" commands got me
symbol names (but perf did).

(pprof) top --cum
Total: 10 samples
       0   0.0%   0.0%       10 100.0% 0x000055e815ef9352
       0   0.0%   0.0%       10 100.0% 0x000055e815ef9449
       0   0.0%   0.0%       10 100.0% 0x000055e815efb10c
       0   0.0%   0.0%       10 100.0% 0x000055e815f144cc
       0   0.0%   0.0%       10 100.0% 0x000055e815f171aa
       0   0.0%   0.0%       10 100.0% 0x000055e815f1af61
       0   0.0%   0.0%       10 100.0% 0x000055e815f1dac3
       0   0.0%   0.0%       10 100.0% 0x000055e815f22036
       0   0.0%   0.0%       10 100.0% 0x000055e815f52e12
       0   0.0%   0.0%       10 100.0% 0x000055e815fa7c25

Maybe I should've tried -g instead of -ggdb3?
(I've been mainly using -ggdb3 in C code for years,
 and didn't recall -g itself wasn't too useful).