On Mon, Dec 6, 2010 at 8:50 PM, Daniel Becroft <djcbecr...@gmail.com> wrote:
> On Mon, Dec 6, 2010 at 7:13 PM, Daniel Shahaf <d...@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 <s...@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 <pe...@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. >> > >
