Bazaar

performance regression for 'log' in trunk?

Bug #562429 reported by Parth Malwankar
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Bazaar
Fix Released
High
John A Meinel

Bug Description

I just noticed a performance difference between trunk and bzr 2.1.1 on Ubuntu 9.10. 'bzr log' on emacs repo has gone from ~37s to ~46s.

[emacs-bzr]% time xbzr log > /dev/null
/home/parthm/src/bzr.dev/trunk/bzr --no-plugins log > /dev/null 44.02s user 1.70s system 96% cpu 47.166 total
[emacs-bzr]% time xbzr log > /dev/null
/home/parthm/src/bzr.dev/trunk/bzr --no-plugins log > /dev/null 44.41s user 1.84s system 99% cpu 46.490 total
[emacs-bzr]% time xbzr log > /dev/null
/home/parthm/src/bzr.dev/trunk/bzr --no-plugins log > /dev/null 44.45s user 1.63s system 99% cpu 46.088 total

[emacs-bzr]% time bzr log > /dev/null
bzr log > /dev/null 36.61s user 1.74s system 97% cpu 39.276 total
[emacs-bzr]% time bzr log > /dev/null
bzr log > /dev/null 35.79s user 1.58s system 99% cpu 37.380 total
[emacs-bzr]% time bzr log > /dev/null
bzr log > /dev/null 36.45s user 1.88s system 99% cpu 38.453 total
[emacs-bzr]% alias xbzr
xbzr='/home/parthm/src/bzr.dev/trunk/bzr --no-plugins'
[emacs-bzr]% xbzr version --short
2.2.0dev1
[emacs-bzr]% bzr version --short
2.1.1
[emacs-bzr]%

[trunk]% ./bzr --no-plugins version-info
revision-id: <email address hidden>
date: 2010-04-13 10:19:53 +0100
build-date: 2010-04-13 22:30:24 +0530
revno: 5151
branch-nick: trunk
[trunk]%

Below is the log of the 'make' on trunk. Not sure if I am missing something or if this is a regression.

[trunk]% make
building extension modules.
python setup.py build_ext -i
running build_ext
building 'bzrlib._annotator_pyx' extension
creating build/temp.linux-i686-2.6
creating build/temp.linux-i686-2.6/bzrlib
gcc -pthread -fno-strict-aliasing -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -fPIC -I/usr/include/python2.6 -c bzrlib/_annotator_pyx.c -o build/temp.linux-i686-2.6/bzrlib/_annotator_pyx.o
gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions build/temp.linux-i686-2.6/bzrlib/_annotator_pyx.o -o /storage/parth/src/bzr.dev/trunk/bzrlib/_annotator_pyx.so
building 'bzrlib._bencode_pyx' extension
gcc -pthread -fno-strict-aliasing -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -fPIC -I/usr/include/python2.6 -c bzrlib/_bencode_pyx.c -o build/temp.linux-i686-2.6/bzrlib/_bencode_pyx.o
gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions build/temp.linux-i686-2.6/bzrlib/_bencode_pyx.o -o /storage/parth/src/bzr.dev/trunk/bzrlib/_bencode_pyx.so
building 'bzrlib._chunks_to_lines_pyx' extension
gcc -pthread -fno-strict-aliasing -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -fPIC -I/usr/include/python2.6 -c bzrlib/_chunks_to_lines_pyx.c -o build/temp.linux-i686-2.6/bzrlib/_chunks_to_lines_pyx.o
gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions build/temp.linux-i686-2.6/bzrlib/_chunks_to_lines_pyx.o -o /storage/parth/src/bzr.dev/trunk/bzrlib/_chunks_to_lines_pyx.so
building 'bzrlib._groupcompress_pyx' extension
gcc -pthread -fno-strict-aliasing -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -fPIC -I/usr/include/python2.6 -c bzrlib/_groupcompress_pyx.c -o build/temp.linux-i686-2.6/bzrlib/_groupcompress_pyx.o
gcc -pthread -fno-strict-aliasing -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -fPIC -I/usr/include/python2.6 -c bzrlib/diff-delta.c -o build/temp.linux-i686-2.6/bzrlib/diff-delta.o
gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions build/temp.linux-i686-2.6/bzrlib/_groupcompress_pyx.o build/temp.linux-i686-2.6/bzrlib/diff-delta.o -o /storage/parth/src/bzr.dev/trunk/bzrlib/_groupcompress_pyx.so
building 'bzrlib._knit_load_data_pyx' extension
gcc -pthread -fno-strict-aliasing -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -fPIC -I/usr/include/python2.6 -c bzrlib/_knit_load_data_pyx.c -o build/temp.linux-i686-2.6/bzrlib/_knit_load_data_pyx.o
gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions build/temp.linux-i686-2.6/bzrlib/_knit_load_data_pyx.o -o /storage/parth/src/bzr.dev/trunk/bzrlib/_knit_load_data_pyx.so
building 'bzrlib._known_graph_pyx' extension
gcc -pthread -fno-strict-aliasing -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -fPIC -I/usr/include/python2.6 -c bzrlib/_known_graph_pyx.c -o build/temp.linux-i686-2.6/bzrlib/_known_graph_pyx.o
gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions build/temp.linux-i686-2.6/bzrlib/_known_graph_pyx.o -o /storage/parth/src/bzr.dev/trunk/bzrlib/_known_graph_pyx.so
building 'bzrlib._rio_pyx' extension
gcc -pthread -fno-strict-aliasing -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -fPIC -I/usr/include/python2.6 -c bzrlib/_rio_pyx.c -o build/temp.linux-i686-2.6/bzrlib/_rio_pyx.o
gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions build/temp.linux-i686-2.6/bzrlib/_rio_pyx.o -o /storage/parth/src/bzr.dev/trunk/bzrlib/_rio_pyx.so
building 'bzrlib._dirstate_helpers_pyx' extension
gcc -pthread -fno-strict-aliasing -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -fPIC -I/usr/include/python2.6 -c bzrlib/_dirstate_helpers_pyx.c -o build/temp.linux-i686-2.6/bzrlib/_dirstate_helpers_pyx.o
gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions build/temp.linux-i686-2.6/bzrlib/_dirstate_helpers_pyx.o -o /storage/parth/src/bzr.dev/trunk/bzrlib/_dirstate_helpers_pyx.so
building 'bzrlib._readdir_pyx' extension
gcc -pthread -fno-strict-aliasing -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -fPIC -I/usr/include/python2.6 -c bzrlib/_readdir_pyx.c -o build/temp.linux-i686-2.6/bzrlib/_readdir_pyx.o
bzrlib/_readdir_pyx.c: In function ‘__pyx_f_6bzrlib_12_readdir_pyx__read_dir’:
bzrlib/_readdir_pyx.c:1094: warning: ‘__pyx_exc_lineno’ may be used uninitialized in this function
bzrlib/_readdir_pyx.c:1137: warning: ‘__pyx_exc_lineno’ may be used uninitialized in this function
gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions build/temp.linux-i686-2.6/bzrlib/_readdir_pyx.o -o /storage/parth/src/bzr.dev/trunk/bzrlib/_readdir_pyx.so
building 'bzrlib._chk_map_pyx' extension
gcc -pthread -fno-strict-aliasing -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -fPIC -I/usr/include/python2.6 -c bzrlib/_chk_map_pyx.c -o build/temp.linux-i686-2.6/bzrlib/_chk_map_pyx.o
gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions build/temp.linux-i686-2.6/bzrlib/_chk_map_pyx.o -lz -o /storage/parth/src/bzr.dev/trunk/bzrlib/_chk_map_pyx.so
building 'bzrlib._patiencediff_c' extension
gcc -pthread -fno-strict-aliasing -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -fPIC -I/usr/include/python2.6 -c bzrlib/_patiencediff_c.c -o build/temp.linux-i686-2.6/bzrlib/_patiencediff_c.o
In file included from /usr/include/python2.6/Python.h:8,
                 from bzrlib/_patiencediff_c.c:28:
/usr/include/python2.6/pyconfig.h:1028:1: warning: "_POSIX_C_SOURCE" redefined
In file included from /usr/include/stdlib.h:25,
                 from bzrlib/_patiencediff_c.c:26:
/usr/include/features.h:210:1: warning: this is the location of the previous definition
gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions build/temp.linux-i686-2.6/bzrlib/_patiencediff_c.o -o /storage/parth/src/bzr.dev/trunk/bzrlib/_patiencediff_c.so
building 'bzrlib._simple_set_pyx' extension
gcc -pthread -fno-strict-aliasing -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -fPIC -I/usr/include/python2.6 -c bzrlib/_simple_set_pyx.c -o build/temp.linux-i686-2.6/bzrlib/_simple_set_pyx.o
gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions build/temp.linux-i686-2.6/bzrlib/_simple_set_pyx.o -o /storage/parth/src/bzr.dev/trunk/bzrlib/_simple_set_pyx.so
building 'bzrlib._static_tuple_c' extension
gcc -pthread -fno-strict-aliasing -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -fPIC -I/usr/include/python2.6 -c bzrlib/_static_tuple_c.c -o build/temp.linux-i686-2.6/bzrlib/_static_tuple_c.o
gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions build/temp.linux-i686-2.6/bzrlib/_static_tuple_c.o -o /storage/parth/src/bzr.dev/trunk/bzrlib/_static_tuple_c.so
building 'bzrlib._btree_serializer_pyx' extension
gcc -pthread -fno-strict-aliasing -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -fPIC -I/usr/include/python2.6 -c bzrlib/_btree_serializer_pyx.c -o build/temp.linux-i686-2.6/bzrlib/_btree_serializer_pyx.o
gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions build/temp.linux-i686-2.6/bzrlib/_btree_serializer_pyx.o -o /storage/parth/src/bzr.dev/trunk/bzrlib/_btree_serializer_pyx.so

Related branches

lp:~jameinel/bzr/2.2-move-to-front-if-changed-562429
Merged into lp:bzr
Andrew Bennetts: Approve
Diff: 66 lines (+25/-9)
2 files modified
NEWS (+4/-0)
bzrlib/index.py (+21/-9)
Revision history for this message
John A Meinel (jameinel) wrote : Re: [Bug 562429] [NEW] performance regression for 'log' in trunk?

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Parth Malwankar wrote:
> Public bug reported:
>
> I just noticed a performance difference between trunk and bzr 2.1.1 on
> Ubuntu 9.10. 'bzr log' on emacs repo has gone from ~37s to ~46s.
>
> [emacs-bzr]% time xbzr log > /dev/null
> /home/parthm/src/bzr.dev/trunk/bzr --no-plugins log > /dev/null 44.02s user 1.70s system 96% cpu 47.166 total
> [emacs-bzr]% time xbzr log > /dev/null
> /home/parthm/src/bzr.dev/trunk/bzr --no-plugins log > /dev/null 44.41s user 1.84s system 99% cpu 46.490 total
> [emacs-bzr]% time xbzr log > /dev/null
> /home/parthm/src/bzr.dev/trunk/bzr --no-plugins log > /dev/null 44.45s user 1.63s system 99% cpu 46.088 total
>
> [emacs-bzr]% time bzr log > /dev/null
> bzr log > /dev/null 36.61s user 1.74s system 97% cpu 39.276 total
> [emacs-bzr]% time bzr log > /dev/null
> bzr log > /dev/null 35.79s user 1.58s system 99% cpu 37.380 total
> [emacs-bzr]% time bzr log > /dev/null
> bzr log > /dev/null 36.45s user 1.88s system 99% cpu 38.453 total
> [emacs-bzr]% alias xbzr
> xbzr='/home/parthm/src/bzr.dev/trunk/bzr --no-plugins'

can you run:

time xbzr log --lsprof-file new_bzr.callgrind >/dev/null
time bzr log --lsprof-file old_bzr.callgrind >/dev/null

And attach the result?

John
=:->

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Cygwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAkvEqSsACgkQJdeBCYSNAAP6IgCfZBPRYKSO1o0LFamPHwY442ct
G6sAn0qMzy6z3gFh9ACaqehE1OTyI1O3
=1YbF
-----END PGP SIGNATURE-----

Changed in bzr:
importance: Undecided → High
status: New → Incomplete
Revision history for this message
Parth Malwankar (parthm) wrote :
Revision history for this message
Parth Malwankar (parthm) wrote :
Changed in bzr:
status: Incomplete → Confirmed
Revision history for this message
Parth Malwankar (parthm) wrote :

lsprof-file output attached for trunk (new_bzr.callgrind) and 2.1.1 (old_bzr.callgrind).

Revision history for this message
John A Meinel (jameinel) wrote : Re: [Bug 562429] Re: performance regression for 'log' in trunk?

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Parth Malwankar wrote:
> lsprof-file output attached for trunk (new_bzr.callgrind) and 2.1.1
> (old_bzr.callgrind).
>

I'll have to get a look at this tomorrow.

In the short-term, I wonder if Andrew's 'move index to front' patch is
to blame. I'm doing some profiling elsewhere, and I came across this
taking 3-4s out of a total of 5.5s to do what I was profiling.

I'm guessing it is a bit over-aggressive.

John
=:->

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Cygwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAkvFOZkACgkQJdeBCYSNAANGowCfWweKeiO4Ck5TkTZ4r2CiA5T/
BaYAoJhR6YbOaO2GvxI1DvLCiJvIhZJK
=l7Xd
-----END PGP SIGNATURE-----

Revision history for this message
Andrew Bennetts (spiv) wrote :

John A Meinel wrote:
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA1
>
> Parth Malwankar wrote:
> > lsprof-file output attached for trunk (new_bzr.callgrind) and 2.1.1
> > (old_bzr.callgrind).
> >
>
> I'll have to get a look at this tomorrow.
>
> In the short-term, I wonder if Andrew's 'move index to front' patch is
> to blame. I'm doing some profiling elsewhere, and I came across this
> taking 3-4s out of a total of 5.5s to do what I was profiling.

Looking at new_bzr.callgrind, I think you're right. _move_to_front is
apparently taking almost 25% of the total time.

Parth, if you try John's linked branch I expect you'll find it has fixed
the regression.

Changed in bzr:
status: Confirmed → In Progress
Revision history for this message
Parth Malwankar (parthm) wrote :

Yup. The with the linked branch the timing is between 36.2-38.4s on hot cache again. Thanks.

[emacs-bzr]% time /storage/parth/src/bzr.dev/2.2-move-to-front-if-changed-562429/bzr --no-plugins log > /dev/null
/storage/parth/src/bzr.dev/2.2-move-to-front-if-changed-562429/bzr log > 36.49s user 2.28s system 93% cpu 41.316 total
[emacs-bzr]% time /storage/parth/src/bzr.dev/2.2-move-to-front-if-changed-562429/bzr --no-plugins log > /dev/null
/storage/parth/src/bzr.dev/2.2-move-to-front-if-changed-562429/bzr log > 34.75s user 2.28s system 96% cpu 38.411 total
[emacs-bzr]% time /storage/parth/src/bzr.dev/2.2-move-to-front-if-changed-562429/bzr --no-plugins log > /dev/null
/storage/parth/src/bzr.dev/2.2-move-to-front-if-changed-562429/bzr log > 34.38s user 1.83s system 100% cpu 36.208 total
[emacs-bzr]%

John A Meinel (jameinel)
Changed in bzr:
assignee: nobody → John A Meinel (jameinel)
status: In Progress → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.