vc-print-log vs. bzr log

vc-print-log vs. bzr log

[Stephen Berman]

When I'm visiting a file on a local branch of the Emacs bzr trunk and
type `M-! bzr log -r-1 RET' I see the log entry in less than one second.
When I type `C-x v l RET RET' ±19 seconds elapse before the log is
displayed (and the lag time is the same if I limit the display to one
entry).  Is this time difference expected?  Is there a quicker way to
view log entries within VC?

Steve Berman

Re: vc-print-log vs. bzr log

[Andreas Schwab]

Stephen Berman <stephen.berman@gmx.net> writes:

> When I'm visiting a file on a local branch of the Emacs bzr trunk and
> type `M-! bzr log -r-1 RET' I see the log entry in less than one second.

Try again passing the file name.  Does it make a difference?

Andreas.

-- 
Andreas Schwab, schwab@linux-m68k.org
GPG Key fingerprint = 58CA 54C7 6D53 942B 1756  01D3 44D5 214B 8276 4ED5
"And now for something completely different."

Re: vc-print-log vs. bzr log

[Stephen Berman]

On Sat, 15 Sep 2012 15:37:13 +0200 Andreas Schwab <schwab@linux-m68k.org> wrote:

> Stephen Berman <stephen.berman@gmx.net> writes:
>
>> When I'm visiting a file on a local branch of the Emacs bzr trunk and
>> type `M-! bzr log -r-1 RET' I see the log entry in less than one second.
>
> Try again passing the file name.  Does it make a difference?

Somewhat; see below.

On Sat, 15 Sep 2012 16:51:33 +0300 Eli Zaretskii <eliz@gnu.org> wrote:

>> From: Stephen Berman <stephen.berman@gmx.net>
>> Date: Sat, 15 Sep 2012 15:07:03 +0200
>> 
>> When I'm visiting a file on a local branch of the Emacs bzr trunk and
>> type `M-! bzr log -r-1 RET' I see the log entry in less than one second.
>> When I type `C-x v l RET RET' ±19 seconds elapse before the log is
>> displayed (and the lag time is the same if I limit the display to one
>> entry).  Is this time difference expected?
>
> Yes, to some degree, because these two commands do 2 different things.
> The first one shows the last commit in the branch.  The second one
> shows the commits only to the file you are visiting, which means
> digging deeper into the version history.

I understand that, but ±19 seconds vs <1 second?  Is that the best VC
can do?

> However, even if the file you are visiting is the one modified by the
> last revision, bzr is slower when a file argument is passed.  

I see this too, but it's still very much quicker than VC.  Here are some
timing tests, with emacs -Q:

From /data/steve/bzr/emacs/quickfixes/ typing `M-! time bzr log -r-1':

real	0m0.428s
user	0m0.305s
sys	0m0.053s

From outside of this branch typing `M-! time bzr log -r-1
/data/steve/bzr/emacs/quickfixes/':

real	0m0.484s
user	0m0.323s
sys	0m0.044s

From outside of this branch typing `M-! time bzr log -r-1
/data/steve/bzr/emacs/quickfixes/lisp/':

real	0m1.330s
user	0m0.957s
sys	0m0.106s

From outside of this branch typing `M-! time bzr log -r-1
/data/steve/bzr/emacs/quickfixes/lisp/gnus/:

real	0m0.760s
user	0m0.480s
sys	0m0.083s

From outside of this branch typing `M-! time bzr log -r-1
/data/steve/bzr/emacs/quickfixes/lisp/gnus/gnus-group.el' (where this
file is the one modified by the last revision on this branch):

real	0m0.612s
user	0m0.404s
sys	0m0.066s

From outside of this branch typing `M-! time bzr log -r-1
/data/steve/bzr/emacs/quickfixes/lisp/gnus/gnus-agent.el' (where this
file is not the one modified by the last revision on this branch):

real	0m0.557s
user	0m0.384s
sys	0m0.067s

>                                                               I guess
> this is something to report as a bug to bzr bug tracker.
>
> Btw, did you really mean "C-x v l RET RET", or did you mean something
> like "C-u C-x v l RET 1 RET"?

Yes, sorry, I mistakenly omitted the prefix argument (from my posting,
not from the command I typed in Emacs).

Steve Berman

Re: vc-print-log vs. bzr log

[Eli Zaretskii]

> From: Stephen Berman <stephen.berman@gmx.net>
> Date: Sat, 15 Sep 2012 16:56:50 +0200
> 
> I understand that, but ±19 seconds vs <1 second?  Is that the best VC
> can do?

If you see very different times inside and outside Emacs, then indeed
something might be wrong with VC.  But before you conclude that, I'd
suggest to look up the commands that Emacs ran in your ~/.bzr.log, and
then run them, verbatim, from the shell prompt.

Re: vc-print-log vs. bzr log

[Stephen Berman]

On Sat, 15 Sep 2012 18:45:01 +0300 Eli Zaretskii <eliz@gnu.org> wrote:

>> From: Stephen Berman <stephen.berman@gmx.net>
>> Date: Sat, 15 Sep 2012 16:56:50 +0200
>> 
>> I understand that, but ±19 seconds vs <1 second?  Is that the best VC
>> can do?
>
> If you see very different times inside and outside Emacs, then indeed
> something might be wrong with VC.  But before you conclude that, I'd
> suggest to look up the commands that Emacs ran in your ~/.bzr.log, and
> then run them, verbatim, from the shell prompt.

Here's a comparison between the shell command with M-!:

Sat 2012-09-15 16:46:33 +0200
0.182  bazaar version: 2.5.1
0.182  bzr arguments: [u'log', u'-r-1', u'/data/steve/bzr/emacs/quickfixes/lisp/gnus/gnus-group.el']
0.186  looking for plugins in /home/steve/.bazaar/plugins
0.196  looking for plugins in /usr/lib64/python2.7/site-packages/bzrlib/plugins
0.226  looking for plugins in /usr/lib/python2.7/site-packages/bzrlib/plugins
0.240  encoding stdout as osutils.get_user_encoding() 'utf-8'
0.309  opening working tree '/data/steve/bzr/emacs/quickfixes'
0.417  encoding stdout as osutils.get_user_encoding() 'utf-8'
0.480  return code 0

and `C-u C-x v l RET RET' on the same file:

Sat 2012-09-15 17:56:19 +0200
0.167  bazaar version: 2.5.1
0.167  bzr arguments: [u'log', u'-l', u'1', u'gnus-group.el']
0.171  looking for plugins in /home/steve/.bazaar/plugins
0.179  looking for plugins in /usr/lib64/python2.7/site-packages/bzrlib/plugins
0.203  looking for plugins in /usr/lib/python2.7/site-packages/bzrlib/plugins
0.211  encoding stdout as osutils.get_user_encoding() 'utf-8'
0.277  opening working tree '/data/steve/bzr/emacs/quickfixes'
0.359  encoding stdout as osutils.get_user_encoding() 'utf-8'
18.561  return code 0

What is happening between the last two entries that takes 18 seconds?

Steve Berman

Re: vc-print-log vs. bzr log

[Eli Zaretskii]

> From: Stephen Berman <stephen.berman@gmx.net>
> Cc: emacs-devel@gnu.org
> Date: Sat, 15 Sep 2012 18:04:24 +0200
> 
> Here's a comparison between the shell command with M-!:
> 
> Sat 2012-09-15 16:46:33 +0200
> 0.182  bazaar version: 2.5.1
> 0.182  bzr arguments: [u'log', u'-r-1', u'/data/steve/bzr/emacs/quickfixes/lisp/gnus/gnus-group.el']
> 0.186  looking for plugins in /home/steve/.bazaar/plugins
> 0.196  looking for plugins in /usr/lib64/python2.7/site-packages/bzrlib/plugins
> 0.226  looking for plugins in /usr/lib/python2.7/site-packages/bzrlib/plugins
> 0.240  encoding stdout as osutils.get_user_encoding() 'utf-8'
> 0.309  opening working tree '/data/steve/bzr/emacs/quickfixes'
> 0.417  encoding stdout as osutils.get_user_encoding() 'utf-8'
> 0.480  return code 0
> 
> and `C-u C-x v l RET RET' on the same file:
> 
> Sat 2012-09-15 17:56:19 +0200
> 0.167  bazaar version: 2.5.1
> 0.167  bzr arguments: [u'log', u'-l', u'1', u'gnus-group.el']
> 0.171  looking for plugins in /home/steve/.bazaar/plugins
> 0.179  looking for plugins in /usr/lib64/python2.7/site-packages/bzrlib/plugins
> 0.203  looking for plugins in /usr/lib/python2.7/site-packages/bzrlib/plugins
> 0.211  encoding stdout as osutils.get_user_encoding() 'utf-8'
> 0.277  opening working tree '/data/steve/bzr/emacs/quickfixes'
> 0.359  encoding stdout as osutils.get_user_encoding() 'utf-8'
> 18.561  return code 0
> 
> What is happening between the last two entries that takes 18 seconds?

That's when bzr does the actual job of accessing the branch meta-data
and getting the information you asked for.

Do you see the above in "emacs -Q" as well?

What do you see in ~/.bzr.log if you invoke

  bzr log -l1 gnus-group.el

from the shell prompt?  If you see the same 18 sec, does it help to
say

  bzr --no-plugins log -l1 gnus-group.el

instead?

Re: vc-print-log vs. bzr log

[Stephen Berman]

On Sat, 15 Sep 2012 19:28:53 +0300 Eli Zaretskii <eliz@gnu.org> wrote:

>> From: Stephen Berman <stephen.berman@gmx.net>
>> Cc: emacs-devel@gnu.org
>> Date: Sat, 15 Sep 2012 18:04:24 +0200
>> 
>> Here's a comparison between the shell command with M-!:
>> 
>> Sat 2012-09-15 16:46:33 +0200
>> 0.182  bazaar version: 2.5.1
>> 0.182 bzr arguments: [u'log', u'-r-1',
>> u'/data/steve/bzr/emacs/quickfixes/lisp/gnus/gnus-group.el']
>> 0.186  looking for plugins in /home/steve/.bazaar/plugins
>> 0.196  looking for plugins in /usr/lib64/python2.7/site-packages/bzrlib/plugins
>> 0.226  looking for plugins in /usr/lib/python2.7/site-packages/bzrlib/plugins
>> 0.240  encoding stdout as osutils.get_user_encoding() 'utf-8'
>> 0.309  opening working tree '/data/steve/bzr/emacs/quickfixes'
>> 0.417  encoding stdout as osutils.get_user_encoding() 'utf-8'
>> 0.480  return code 0
>> 
>> and `C-u C-x v l RET RET' on the same file:
>> 
>> Sat 2012-09-15 17:56:19 +0200
>> 0.167  bazaar version: 2.5.1
>> 0.167  bzr arguments: [u'log', u'-l', u'1', u'gnus-group.el']
>> 0.171  looking for plugins in /home/steve/.bazaar/plugins
>> 0.179  looking for plugins in /usr/lib64/python2.7/site-packages/bzrlib/plugins
>> 0.203  looking for plugins in /usr/lib/python2.7/site-packages/bzrlib/plugins
>> 0.211  encoding stdout as osutils.get_user_encoding() 'utf-8'
>> 0.277  opening working tree '/data/steve/bzr/emacs/quickfixes'
>> 0.359  encoding stdout as osutils.get_user_encoding() 'utf-8'
>> 18.561  return code 0
>> 
>> What is happening between the last two entries that takes 18 seconds?
>
> That's when bzr does the actual job of accessing the branch meta-data
> and getting the information you asked for.
>
> Do you see the above in "emacs -Q" as well?

Yes, and the difference is even a bit larger:

Sat 2012-09-15 19:21:08 +0200
0.170  bazaar version: 2.5.1
0.171  bzr arguments: [u'log', u'-r-1', u'/data/steve/bzr/emacs/quickfixes/lisp/gnus/gnus-group.el']
0.174  looking for plugins in /home/steve/.bazaar/plugins
0.182  looking for plugins in /usr/lib64/python2.7/site-packages/bzrlib/plugins
0.206  looking for plugins in /usr/lib/python2.7/site-packages/bzrlib/plugins
0.217  encoding stdout as osutils.get_user_encoding() 'utf-8'
0.278  opening working tree '/data/steve/bzr/emacs/quickfixes'
0.367  encoding stdout as osutils.get_user_encoding() 'utf-8'
0.419  return code 0

Sat 2012-09-15 19:21:50 +0200
0.203  bazaar version: 2.5.1
0.203  bzr arguments: [u'log', u'-l', u'1', u'gnus-group.el']
0.207  looking for plugins in /home/steve/.bazaar/plugins
0.215  looking for plugins in /usr/lib64/python2.7/site-packages/bzrlib/plugins
0.239  looking for plugins in /usr/lib/python2.7/site-packages/bzrlib/plugins
0.247  encoding stdout as osutils.get_user_encoding() 'utf-8'
0.309  opening working tree '/data/steve/bzr/emacs/quickfixes'
0.395  encoding stdout as osutils.get_user_encoding() 'utf-8'
19.272  return code 0


> What do you see in ~/.bzr.log if you invoke
>
>   bzr log -l1 gnus-group.el
>
> from the shell prompt?  

Sat 2012-09-15 19:26:14 +0200
0.127  bazaar version: 2.5.1
0.127  bzr arguments: [u'log', u'-l1', u'gnus-group.el']
0.131  looking for plugins in /home/steve/.bazaar/plugins
0.139  looking for plugins in /usr/lib64/python2.7/site-packages/bzrlib/plugins
0.163  looking for plugins in /usr/lib/python2.7/site-packages/bzrlib/plugins
0.171  encoding stdout as sys.stdout encoding 'UTF-8'
0.228  opening working tree '/data/steve/bzr/emacs/quickfixes'
0.312  encoding stdout as sys.stdout encoding 'UTF-8'
18.968  Transferred: 0kB (0.0kB/s r:0kB w:0kB)
18.968  return code 0

>                         If you see the same 18 sec, does it help to
> say
>
>   bzr --no-plugins log -l1 gnus-group.el
>
> instead?

No, it's even worse:

Sat 2012-09-15 19:26:56 +0200
0.155  bazaar version: 2.5.1
0.155  bzr arguments: [u'--no-plugins', u'log', u'-l1', u'gnus-group.el']
0.168  encoding stdout as sys.stdout encoding 'UTF-8'
0.243  opening working tree '/data/steve/bzr/emacs/quickfixes'
0.328  encoding stdout as sys.stdout encoding 'UTF-8'
19.122  Transferred: 0kB (0.0kB/s r:0kB w:0kB)
19.122  return code 0

In any case, obviously this is a bzr issue, not an Emacs one.  Or can we
make VC also get the quicker bzr -r-1 results?

Steve Berman

Re: vc-print-log vs. bzr log

[Andreas Schwab]

Stephen Berman <stephen.berman@gmx.net> writes:

> make VC also get the quicker bzr -r-1 results?

-r-1 and -l1 are quite different.  The first only looks at the last
commit (so you get no output for files not modified there), whereas the
latter always outputs one commit (if the file is tracked at all).

Andreas.

-- 
Andreas Schwab, schwab@linux-m68k.org
GPG Key fingerprint = 58CA 54C7 6D53 942B 1756  01D3 44D5 214B 8276 4ED5
"And now for something completely different."

Re: vc-print-log vs. bzr log

[Eli Zaretskii]

> From: Stephen Berman <stephen.berman@gmx.net>
> Cc: emacs-devel@gnu.org
> Date: Sat, 15 Sep 2012 19:36:01 +0200
> 
> > What do you see in ~/.bzr.log if you invoke
> >
> >   bzr log -l1 gnus-group.el
> >
> > from the shell prompt?  
> 
> Sat 2012-09-15 19:26:14 +0200
> 0.127  bazaar version: 2.5.1
> 0.127  bzr arguments: [u'log', u'-l1', u'gnus-group.el']
> 0.131  looking for plugins in /home/steve/.bazaar/plugins
> 0.139  looking for plugins in /usr/lib64/python2.7/site-packages/bzrlib/plugins
> 0.163  looking for plugins in /usr/lib/python2.7/site-packages/bzrlib/plugins
> 0.171  encoding stdout as sys.stdout encoding 'UTF-8'
> 0.228  opening working tree '/data/steve/bzr/emacs/quickfixes'
> 0.312  encoding stdout as sys.stdout encoding 'UTF-8'
> 18.968  Transferred: 0kB (0.0kB/s r:0kB w:0kB)
> 18.968  return code 0

So it's bzr itself, not VC.  I guess a bug report to the bzr bug
tracker is in order, after all.

Re: vc-print-log vs. bzr log

[Eli Zaretskii]

> From: Stephen Berman <stephen.berman@gmx.net>
> Date: Sat, 15 Sep 2012 15:07:03 +0200
> 
> When I'm visiting a file on a local branch of the Emacs bzr trunk and
> type `M-! bzr log -r-1 RET' I see the log entry in less than one second.
> When I type `C-x v l RET RET' ±19 seconds elapse before the log is
> displayed (and the lag time is the same if I limit the display to one
> entry).  Is this time difference expected?

Yes, to some degree, because these two commands do 2 different things.
The first one shows the last commit in the branch.  The second one
shows the commits only to the file you are visiting, which means
digging deeper into the version history.

However, even if the file you are visiting is the one modified by the
last revision, bzr is slower when a file argument is passed.  I guess
this is something to report as a bug to bzr bug tracker.

Btw, did you really mean "C-x v l RET RET", or did you mean something
like "C-u C-x v l RET 1 RET"?  If the former, then by default C-x v l
does not prompt for anything, so I have no opportunity to type RET
twice.