Re: cvs2git profile data

On 12/13/2010 05:42 PM, Alex Bennee wrote:
> Our repository currently takes around 6 hours to do a full import (not
> including the actual fast-import into git). It is very much a CPU
> bound problem with the server showing plenty of spare RAM and not
> overly stretched in terms of IO.
> 
> I took the opportunity to collect some profiling data with the
> following invocation:
> 
> python -m cProfile -o ${IMPORT_GIT_TREE}/profile.data
> ${CVS2GIT_BASE}/cvs2git --options ${SCRIPT_BASE}/repo-cvs2git.options
> 
> As the traces aren't too big I've attached them to the attached
> compressed tarball in case anyone finds them useful:
> 
> cb5918252c7bb648ff3d46efd5cc76d4  profile1.data
> ebc6d1b39369c6118d984da9da3f37c2  profile2.data
> edbeed7d077fb7f647de23f523764168  profile.tar.bz2

Thanks for the data.

I suppose that there are two classes of CVS repository--those with few
tags (e.g., tags only set manually) and those with a huge number of tags
(e.g., tags set by nightly scripts), and that these two classes will
have very different performance profiles.  I suspect that yours is one
of the latter :-)

The expensive thing about tags is tabulating the possible parents for
each tag.  This is expensive for many-tag repositories because the
number of possible parent combinations scales something like

    number_of_files * number_of_revisions_per_file *
average(number_of_tags_per_revision^2)

It is the average of the square that is fatal.

In case anybody is interested, here are the top 50 functions by "time"
(time executing, not including time spent in subroutines), with a few notes:

>    ncalls  tottime  percall  cumtime  percall filename:lineno(function)
> 373089404 2123.950    0.000 3845.862    0.000 record_table.py:301(_get_packed_record)

Most of the calls to _get_packed_record originate from
changeset.py:201(create_graph_node) or from
changeset.py:35(iter_cvs_items).  It might make sense to fiddle with the
cache sizes for these cases and/or implement smarter cache management.

> 772823585 1866.751    0.000 4029.054    0.000 symbol_statistics.py:127(register_possible_parent)

This routine could probably be sped up by using a defaultdict (available
starting in Python 2.5) and by inlining it (it is only called from four
places).  The statistics could be collected by symbol.id rather than by
symbol instance (this would save lookup time and time calling hash()).

> 493196569 1540.437    0.000 1540.437    0.000 {method 'seek' of 'file' objects}
> 987566288 1453.528    0.000 1940.198    0.000 {method 'get' of 'dict' objects}
> 373089404 1418.363    0.000 6775.321    0.000 record_table.py:156(__getitem__)

This can be grouped together with _get_packed_record() above.

>  18494346 1333.759    0.000 5710.188    0.000 symbol_statistics.py:158(register_tag_possible_parents)

This can be grouped with register_possible_parents().

>   7610543 1295.604    0.000 1295.604    0.000 {posix.read}
>  18460594 1285.036    0.000 3576.792    0.000 cvs_file_items.py:937(_adjust_tag_parent)
>    172135 1245.699    0.007 1245.699    0.007 {posix.fork}

The fork calls come from
abstract_rcs_revision_manager.py:52(get_content), which suggests that
you are not using the internal code for extracting content from the CVS
repository.  The internal code should be much faster; I suggest you give
it a try.

> 1624503008 1218.073    0.000 1218.073    0.000 cvs_file_items.py:162(__getitem__)

About 80% of these are also related to register_possible_parents()

> 141412502/140436990 1216.242    0.000 3512.304    0.000 {built-in method load}
>   7351497 1052.883    0.000 1052.883    0.000 {select.select}
> 129257276 1042.738    0.000 1723.673    0.000 cvs_item.py:902(__setstate__)

Used by the unpickler to deserialize data from a database.

> 1627930367  960.929    0.000  960.929    0.000 symbol.py:92(__hash__)

This can be grouped with register_possible_parents().

>  41017875  845.774    0.000  994.289    0.000 {method 'dump' of 'cPickle.Pickler' objects}
> 116908826  749.503    0.000 1206.156    0.000 cvs_path.py:108(get_ancestry)
>      3957  736.786    0.186 9944.325    2.513 changeset.py:201(create_graph_node)
> 1235605900  736.408    0.000  736.408    0.000 {method 'append' of 'list' objects}
> 359311380  647.905    0.000 7177.574    0.000 record_table.py:180(get)
>  70271708  645.909    0.000  908.297    0.000 cvs_item.py:920(check_links)
> 793950954  586.862    0.000  586.862    0.000 {isinstance}
> 373089154  581.802    0.000  827.398    0.000 struct.py:77(unpack)
> 141412475/140436963  486.478    0.000 4371.091    0.000 serializer.py:112(loadf)
> 120728289  479.019    0.000 7294.611    0.000 database.py:278(get_many)
> 505402041  460.134    0.000  460.134    0.000 context.py:34(__init__)
> 121070219/120094707  459.199    0.000 4033.169    0.000 database.py:251(_fetch)
> 251775799  452.962    0.000 1014.617    0.000 record_table.py:87(unpack)
> 100541012  445.162    0.000 1917.926    0.000 cvs_path.py:123(get_cvs_path)
> 37107960/16706495  444.285    0.000  806.241    0.000 cvs_file_items.py:275(process_subitems)
> 616457618  438.568    0.000  438.568    0.000 symbol.py:95(__eq__)
>      9045  416.672    0.046 1532.262    0.169 record_table.py:260(flush)
>  67267307  409.684    0.000  506.029    0.000 default.py:42(get)
> 330776658  358.450    0.000  358.450    0.000 {method 'read' of 'file' objects}
> 182614160  334.610    0.000  334.610    0.000 {method 'copy' of 'dict' objects}
>    959617  320.840    0.000  334.785    0.000 {method 'sort' of 'list' objects}
> 248269119/50550962  317.488    0.000  407.532    0.000 dvcs_common.py:284(_get_all_files)
>  40490955  299.989    0.000  489.128    0.000 {built-in method sub}
> 508653202/508653145  291.446    0.000  291.446    0.000 {len}
>  81500565  276.358    0.000  641.565    0.000 sort.py:65(merge)
> 120729184  272.453    0.000  486.971    0.000 common.py:99(path_join)
>  29340120  263.135    0.000  424.050    0.000 cvs_item.py:775(__setstate__)
> 192774367  259.894    0.000  371.854    0.000 cvs_path.py:172(__cmp__)
> 339920625  253.470    0.000  253.470    0.000 symbol_database.py:43(get_symbol)
> 373089154  245.596    0.000  245.596    0.000 {method 'unpack' of 'Struct' objects}
> 121313355  230.736    0.000  496.478    0.000 record_table.py:122(unpack)
> 321183467  229.498    0.000  237.798    0.000 {method 'add' of 'set' objects}
> 120728289  224.708    0.000 2641.808    0.000 record_table.py:169(get_many)
> 201162141  221.501    0.000  221.501    0.000 {method 'write' of 'file' objects}
>    706426  215.915    0.000  402.004    0.001 cvs_item.py:497(check_links)
>      2181  214.017    0.098  603.593    0.277 {sorted}


-- 
Michael Haggerty
[email protected]
http://softwareswirl.blogspot.com/

------------------------------------------------------
http://cvs2svn.tigris.org/ds/viewMessage.do?dsForumId=1667&dsMessageId=2690585

To unsubscribe from this discussion, e-mail: [[email protected]].