On Mon, 2011-03-21 at 17:23 -0400, C. Michael Pilato wrote: > Recently (last week or so), I've noticed that 'svn commit' has gotten > *really* slow. As in, it takes a full 30 seconds for 'svn commit' to return > when asked to perform a no-op commit of my Subversion trunk directory. > > I was able to discern through code-stepping that the lion's share of the > time spent was in the harvest_committables() code. I sorta suspected > svn_wc__node_get_children_of_working_node() as the problem point, given that > that's the only thing that's really changed in the harvest_committables() > codepath recently, but I didn't really know how to verify that. > > So today I started trying to mess with callgrind a bit. Here's some heavily > filtered output from callgrind_annotate on a no-op commit of just our > trunk/subversion/tests/cmdline directory (committing at higher levels was > taking FOREVER while profiling): > > 4,357,656,366 112,781 756 subversion/svn/main.c:main > 4,352,930,262 112,657 753 subversion/svn/commit-cmd.c:svn_cl__commit > 4,350,334,930 112,511 751 > subversion/libsvn_client/commit.c:svn_client_commit5 > 4,349,499,552 112,341 751 > subversion/libsvn_client/commit_util.c:svn_client__harvest_committables > 4,348,470,026 112,079 748 > subversion/libsvn_client/commit_util.c:harvest_committables > 4,269,103,898 108,354 729 > subversion/libsvn_subr/sqlite.c:svn_sqlite__step > 4,189,859,746 85,024 604 > subversion/libsvn_wc/node.c:svn_wc__node_get_children_of_working_node > 4,179,862,166 83,354 592 > subversion/libsvn_wc/wc_db.c:svn_wc__db_read_children_of_working_node > 4,179,834,710 83,354 592 subversion/libsvn_wc/wc_db.c:gather_children2 > 4,179,798,573 83,354 592 > subversion/libsvn_wc/wc_db.c:add_children_to_hash > 4,046,859,894 116,411 761 > subversion/libsvn_client/commit_util.c:harvest_committables'2 > 90,828,539 16,308 85 > subversion/libsvn_wc/wc_db.c:svn_wc__db_read_info > 83,508,483 18,868 101 subversion/libsvn_wc/wc_db.c:read_info > 32,672,951 492 6 > subversion/libsvn_wc/wc_db_wcroot.c:svn_wc__db_wcroot_parse_local_abspath > 29,042,308 3,196 17 > subversion/libsvn_wc/wc_db.c:svn_wc__db_read_props > 26,587,135 3,253 17 > subversion/libsvn_wc/wc_db_txn.c:svn_wc__db_with_txn > 26,561,409 3,253 17 > subversion/libsvn_subr/sqlite.c:svn_sqlite__with_lock > [...] > > I *think* this supports my hypothesis regarding > svn_wc__node_get_children_of_working_node(). I have yet to try reverting > the introduction of this function to see if that helps, but (because I'm out > of time for today) I wanted to at least get this data out there for someone > else to see.
Ah, that would be me then. Bert mentioned just now on IRC that "STMT_SELECT_WORKING_CHILDREN should perform a max(op_depth) on the parent node or it might create a huge join which just returns the same thing as the old gather children but then a lot slower". I think that's what I meant it to do but it looks like I forgot the "max". Testing with a "max" now. Bert then said: "And just to be sure I think we should check if the sqlite optimizer does the right thing, or that we should just perform the retrieve parent_depth once before the entire query. (I would guess it does the right thing)". I'll take a look tomorrow. - Julian (hoping all it needs is the "max" to bring the speed back)
