On Mon, Dec 6, 2010 at 7:13 PM, Daniel Shahaf <d.s_at_daniel.shahaf.name>wrote:
> Instead of guessing which function causes the lstat() calls, could we
> have a tool tell?
>
> I've looked at 'ltrace -S', but it seems to me that will only tell us
> which public svn_wc_* API is responsible for the calls. Perhaps there
> is another tool that can help us follow the entire call chain down to
> the lstat() call?
>
> Daniel
> . o O (gdb with a breakpoint in lstat() and some fu to extract
> statistics about the stack trace?)
>
Very true.
Okay, after a crash course in using GDB, I've run some further testing.
Running with breakpoints set on the lstat() system call, it looks to be the
known issue that was originally pointed to. A partial stack trace is below:
#0 0x00007ffff644ab45 in __lxstat (vers=<value optimised out>,
name=<value optimised out>, buf=0x7fffffffcbf0)
at ../sysdeps/unix/sysv/linux/wordsize-64/lxstat.c:38
#1 0x00007ffff69269b6 in lstat (finfo=0x7fffffffccf0,
fname=0x6bd638 "/home/djcbecroft/dev/workingcopy/A/beta.txt",
wanted=33137, pool=0x6bd588) at /usr/include/sys/stat.h:464
#2 apr_stat (finfo=0x7fffffffccf0,
fname=0x6bd638 "/home/djcbecroft/dev/workingcopy/A/beta.txt",
wanted=33137, pool=0x6bd588) at file_io/unix/filestat.c:292
#3 0x00007ffff6fb1199 in io_check_path (
path=0x6bd608 "/home/djcbecroft/dev/workingcopy/A/beta.txt",
resolve_symlinks=0, is_special_p=0x7fffffffced8, kind=0x7fffffffcedc,
pool=0x6bd588) at subversion/libsvn_subr/io.c:222
#4 0x00007ffff6fb1346 in svn_io_check_special_path (
path=0x6bd608 "/home/djcbecroft/dev/workingcopy/A/beta.txt",
kind=0x7fffffffcedc, is_special=0x7fffffffced8, pool=0x6bd588)
at subversion/libsvn_subr/io.c:283
#5 0x00007ffff794513d in svn_wc__db_pdh_parse_local_abspath (
pdh=0x7fffffffd038, local_relpath=0x7fffffffd030, db=0x64ad38,
local_abspath=0x6bd608 "/home/djcbecroft/dev/workingcopy/A/beta.txt",
smode=svn_sqlite__mode_readwrite, result_pool=0x6bd588,
scratch_pool=0x6bd588) at subversion/libsvn_wc/wc_db_pdh.c:382
#6 0x00007ffff7935d58 in svn_wc__db_read_info (status=0x7fffffffd184,
kind=0x7fffffffd188, revision=0x0, repos_relpath=0x0,
repos_root_url=0x0,
repos_uuid=0x0, changed_rev=0x0, changed_date=0x0, changed_author=0x0,
last_mod_time=0x0, depth=0x0, checksum=0x0, translated_size=0x0,
target=0x0, changelist=0x0, original_repos_relpath=0x0,
original_root_url=0x0, original_uuid=0x0, original_revision=0x0,
props_mod=0x0, have_base=0x0, have_work=0x0, conflicted=0x0, lock=0x0,
db=0x64ad38,
local_abspath=0x6bd608 "/home/djcbecroft/dev/workingcopy/A/beta.txt",
result_pool=0x6bd588, scratch_pool=0x6bd588)
at subversion/libsvn_wc/wc_db.c:5261
However, I then put the breakpont in the svn_wc__db_read_info function and,
just for A/beta.txt, it gets called 7 times, when in terms leads to 7
additional lstat() calls. Looking further the call stack appears as follows:
#0 svn_wc__db_read_info (status=0x7fffffffd184, kind=0x7fffffffd188,
revision=0x0, repos_relpath=0x0, repos_root_url=0x0, repos_uuid=0x0,
changed_rev=0x0, changed_date=0x0, changed_author=0x0,
last_mod_time=0x0,
depth=0x0, checksum=0x0, translated_size=0x0, target=0x0,
changelist=0x0,
original_repos_relpath=0x0, original_root_url=0x0, original_uuid=0x0,
original_revision=0x0, props_mod=0x0, have_base=0x0, have_work=0x0,
conflicted=0x0, lock=0x0, db=0x64ad38,
local_abspath=0x6bd608 "/home/djcbecroft/dev/workingcopy/A/beta.txt",
result_pool=0x6bd588, scratch_pool=0x6bd588)
at subversion/libsvn_wc/wc_db.c:5259
#1 0x00007ffff78fab96 in walker_helper (db=0x64ad38,
dir_abspath=0x6ba288 "/home/djcbecroft/dev/workingcopy/A",
show_hidden=1,
walk_callback=0x7ffff7ba9026 <get_mergeinfo_walk_cb>,
walk_baton=0x7fffffffd4e0, depth=svn_depth_infinity,
cancel_func=0x4119c3 <svn_cl__check_cancel>, cancel_baton=0x0,
scratch_pool=0x6ba208) at subversion/libsvn_wc/node.c:679
#2 0x00007ffff78facb5 in walker_helper (db=0x64ad38,
dir_abspath=0x67d258 "/home/djcbecroft/dev/workingcopy", show_hidden=1,
walk_callback=0x7ffff7ba9026 <get_mergeinfo_walk_cb>,
walk_baton=0x7fffffffd4e0, depth=svn_depth_infinity,
cancel_func=0x4119c3 <svn_cl__check_cancel>, cancel_baton=0x0,
scratch_pool=0x6a0dc8) at subversion/libsvn_wc/node.c:716
#3 0x00007ffff78faf9a in svn_wc__internal_walk_children (db=0x64ad38,
local_abspath=0x67d258 "/home/djcbecroft/dev/workingcopy",
show_hidden=1,
walk_callback=0x7ffff7ba9026 <get_mergeinfo_walk_cb>,
walk_baton=0x7fffffffd4e0, walk_depth=svn_depth_infinity,
cancel_func=0x4119c3 <svn_cl__check_cancel>, cancel_baton=0x0,
scratch_pool=0x6a0dc8) at subversion/libsvn_wc/node.c:763
#4 0x00007ffff78fb06d in svn_wc__node_walk_children (wc_ctx=0x64ad20,
local_abspath=0x67d258 "/home/djcbecroft/dev/workingcopy",
show_hidden=1,
walk_callback=0x7ffff7ba9026 <get_mergeinfo_walk_cb>,
walk_baton=0x7fffffffd4e0, walk_depth=svn_depth_infinity,
cancel_func=0x4119c3 <svn_cl__check_cancel>, cancel_baton=0x0,
scratch_pool=0x6a0dc8) at subversion/libsvn_wc/node.c:785
Using additional breakpoints, I have verified that
svn_wc__node_walk_children, svn_wc__internal_walk_children and walker_helper
only get called once. It seems to be an issue within the walker_helper
itself.
I'll continue looking at it further - let me know if I'm barking up the
wrong tree.
Cheers,
Daniel B.
... who now has a much greater appreciation for those that debug in GDB on a
regular basis.
> Daniel Becroft wrote on Mon, Dec 06, 2010 at 18:32:09 +1000:
> > On Mon, Dec 6, 2010 at 8:09 AM, Stefan Sperling <stsp_at_elego.de> wrote:
> >
> > > On Mon, Dec 06, 2010 at 07:18:56AM +1000, Daniel Becroft wrote:
> > > > On Fri, Dec 3, 2010 at 9:22 AM, Peter Samuelson <peter_at_p12n.org>
> wrote:
> > > >
> > > > >
> > > > > [Daniel Becroft]
> > > > > > I've just managed to build/install trunk on my ubuntu box at home
> > > (first
> > > > > > application I've ever compiled on it - yey!).
> > > > > >
> > > > > > What debugging tools would you recommend to investigate this
> further?
> > > > > I've
> > > > > > seen output posted that lists function names, and time spent on
> each.
> > > > >
> > > > > The obvious start is 'strace', as in 'strace svn merge ...'. It
> spits
> > > > > out every system call. There's a lot of noise up front as it's
> loading
> > > > > shared libraries and such, but it should still be obvious what
> we're
> > > > > doing when crawling the tree (stat / lstat, open, etc.).<
> > > http://p12n.org/>
> > > >
> > > >
> > > > Thanks. I've run that, and all the calls are lstat(). There are 16
> for
> > > each
> > > > file (or at least, those not affected by the merge). I've copied on
> of
> > > the
> > > > calls below (all 16 of these are identical).
> > > >
> > > > lstat("....../dev/workingcopy/A/beta.txt", {st_dev=makedev(8, 1),
> > > > st_ino=23855167, st_mode=S_IFREG|0644, st_nlink=1, st_uid=1000,
> > > st_gid=1000,
> > > > st_blksize=4096, st_blocks=8, st_size=5,
> st_atime=2010/12/06-07:10:42,
> > > > st_mtime=2010/12/06-07:10:42, st_ctime=2010/12/06-07:10:42}) = 0
> > > >
> > > > It does appear that it's a known issue though. I'll keep
> investigating to
> > > > try and understand why it's getting called at all. Thanks for your
> help.
> > >
> > > That's probably the svn_wc_revision_status2() call in
> > > ensure_wc_is_suitable_merge_target()
> (subversion/libsvn_client/merge.c).
> > >
> > > 1.6.x should be doing the same during reintegrate merges.
> > > 1.7 does it for every merge.
> > >
> > > To verify my theory you can try the patch below.
> > > We could try to optimize this if it is a problem.
> > >
> > > Stefan
> > >
> > > Index: subversion/libsvn_client/merge.c
> > > ===================================================================
> > > --- subversion/libsvn_client/merge.c (revision 1042308)
> > > +++ subversion/libsvn_client/merge.c (working copy)
> > > @@ -9022,6 +9022,7 @@ ensure_wc_is_suitable_merge_target(const char
> *tar
> > > svn_boolean_t
> allow_switched_subtrees,
> > > apr_pool_t *scratch_pool)
> > > {
> > > +#if 0
> > > svn_wc_revision_status_t *wc_stat;
> > >
> > > /* Avoid the following status crawl if we don't need it. */
> > > @@ -9068,6 +9069,7 @@ ensure_wc_is_suitable_merge_target(const char
> *tar
> > > wc_stat->min_rev, wc_stat->max_rev);
> > > }
> > >
> > > +#endif
> > > return SVN_NO_ERROR;
> > > }
> > >
> >
> > Hey Stefan,
> >
> > I've applied the patch, and re-run the test. It's cut the calls down from
> 16
> > to 10.
> >
> > Cheers,
> > Daniel B.
>
Received on 2010-12-06 11:51:26 CET