On Mon, Dec 6, 2010 at 8:50 PM, Daniel Becroft <djcbecroft_at_gmail.com> wrote:
> 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.
>
I think I've found the culprit. As we are walking the children
(svn_wc__internal_walk_children, node.c), we call the walk_callback for each
node. At the moment, this is the get_mergeinfo_walk_cb function in merge.c.
Inside this, we call the following:
svn_wc__node_is_status_present
svn_wc__node_is_status_deleted
svn_wc__node_is_status_absent
svn_wc__path_switched
svn_wc_read_kind
svn_wc__node_get_depth
Each of these will run a separate svn_wc__db_read_info call, and therefore a
separate lstat(). There's also a couple of other calls that might call it
indirectly.
Cheers,
Daniel B.
> 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 22:16:25 CET