bug#895: slow processing of process output

bug#895: slow processing of process output

[Dan Nicolaescu]

emacs -Q -nw
M-x rgrep RET emacs RET *.el RET PATH_TO_EMACS_SOURCE_TREE/lisp RET

takes a few minutes.  The output is about 9000 lines.

Running the correspondind command:

find . \( -path \*/SCCS -o -path \*/RCS -o -path \*/CVS -o -path \*/MCVS -o -path \*/.svn -o -path \*/.git -o -path \*/.hg -o -path \*/.bzr -o -path \*/_MTN -o -path \*/_darcs -o -path \*/\{arch\} \) -prune -o -type f \( -name *.el \) -print0 | xargs -0 -e grep -i -nH -e emacs

from a shell (and redirecting the output to a file) takes less than one second.

bug#895: slow processing of process output

[Dan Nicolaescu]

Dan Nicolaescu <dann@ics.uci.edu> writes:

  > emacs -Q -nw
  > M-x rgrep RET emacs RET *.el RET PATH_TO_EMACS_SOURCE_TREE/lisp RET
  > 
  > takes a few minutes.  The output is about 9000 lines.
  > 
  > Running the correspondind command:
  > 
  > find . \( -path \*/SCCS -o -path \*/RCS -o -path \*/CVS -o -path \*/MCVS -o -path \*/.svn -o -path \*/.git -o -path \*/.hg -o -path \*/.bzr -o -path \*/_MTN -o -path \*/_darcs -o -path \*/\{arch\} \) -prune -o -type f \( -name *.el \) -print0 | xargs -0 -e grep -i -nH -e emacs
  > 
  > from a shell (and redirecting the output to a file) takes less than one second.

One more data point:

emacs -Q -nw

M-x lgrep RET emacs RET *.el RET PATH_TO_EMACS_SOURCE_TREE/lisp RET

takes 33 seconds.  It runs the command:  grep -i -nH -e emacs *.el

M-x shell RET time grep -i -nH -e emacs *.el
0.087u 0.020s 0:01.60 6.2%      0+0k 0+0io 0pf+0w
              ^^^^^^^
              A lot less than 33 seconds.

bug#895: slow processing of process output on Mac

[mh origin]

[-- Attachment #1: Type: text/plain, Size: 799 bytes --]

I see this with matlab-shell, when trying to tab-complete, in Emacs 23 and
emacs 24 on the Mac, both on Lion and on Snow Leopard.  I fired this up in
the debugger and it looks like it gets stuck on a system call but I'm
afraid I couldn't figure out any more than that.

At first start, Matlab returns completions just fine, but after about an
hour it starts hanging when tab is pressed.

The function called on completion is here:
https://github.com/ruediger/matlab-emacs/blob/master/matlab.el#L4831

And the accept-process-output call that hangs is here:
https://github.com/ruediger/matlab-emacs/blob/master/matlab.el#L5304

I'm using Emacs 24.0.93 from here:
http://emacsformacosx.com/emacs-builds/Emacs-pretest-24.0.93-universal-10.6.8.dmg

Can I do anything else to help people track this down?

[-- Attachment #2: Type: text/html, Size: 1168 bytes --]

bug#895: slow processing of process output

[Richard Copley]

I tested in current master with mingw-w64 on Windows. The rgrep
command given in the OP takes 29 s in Emacs, but the corresponding
shell command[1] takes over a minute in Windows cmd.exe (at a guess,
that's because cmd.exe scrolls line-by-line so has to push a lot of
pixels).

Likewise, building Emacs is faster with "M-x compile" than it is on
the shell (from a clean checkout on my configuration it takes 7 min 43
seconds in Emacs and 9 minutes 15 seconds in cmd.exe).

I'm tempted to conclude that this bug has been fixed.

[1] G:\usr\bin\find.exe . -type d "(" -path "*/SCCS" -o -path "*/RCS"
-o -path "*/CVS" -o -path "*/MCVS" -o -path "*/.src" -o -path "*/.svn"
-o -path "*/.git" -o -path "*/.hg" -o -path "*/.bzr" -o -path "*/_MTN"
-o -path "*/_darcs" -o -path "*/{arch}" ")" -prune -o ^"^!^" -type d
"(" -name ".#*" -o -name "*.o" -o -name "*~" -o -name "*.bin" -o -name
"*.bak" -o -name "*.obj" -o -name "*.map" -o -name "*.ico" -o -name
"*.pif" -o -name "*.lnk" -o -name "*.a" -o -name "*.ln" -o -name
"*.blg" -o -name "*.bbl" -o -name "*.dll" -o -name "*.drv" -o -name
"*.vxd" -o -name "*.386" -o -name "*.elc" -o -name "*.lof" -o -name
"*.glo" -o -name "*.idx" -o -name "*.lot" -o -name "*.fmt" -o -name
"*.tfm" -o -name "*.class" -o -name "*.fas" -o -name "*.lib" -o -name
"*.mem" -o -name "*.x86f" -o -name "*.sparcf" -o -name "*.dfsl" -o
-name "*.pfsl" -o -name "*.d64fsl" -o -name "*.p64fsl" -o -name
"*.lx64fsl" -o -name "*.lx32fsl" -o -name "*.dx64fsl" -o -name
"*.dx32fsl" -o -name "*.fx64fsl" -o -name "*.fx32fsl" -o -name
"*.sx64fsl" -o -name "*.sx32fsl" -o -name "*.wx64fsl" -o -name
"*.wx32fsl" -o -name "*.fasl" -o -name "*.ufsl" -o -name "*.fsl" -o
-name "*.dxl" -o -name "*.lo" -o -name "*.la" -o -name "*.gmo" -o
-name "*.mo" -o -name "*.toc" -o -name "*.aux" -o -name "*.cp" -o
-name "*.fn" -o -name "*.ky" -o -name "*.pg" -o -name "*.tp" -o -name
"*.vr" -o -name "*.cps" -o -name "*.fns" -o -name "*.kys" -o -name
"*.pgs" -o -name "*.tps" -o -name "*.vrs" -o -name "*.pyc" -o -name
"*.pyo" ")" -prune -o  -type f "(" -iname "*.el" ")" -exec
G:\usr\bin\grep.exe --color=always -i -nH -e "emacs" {} +


In GNU Emacs 25.0.50.1 (x86_64-w64-mingw32)
 of 2016-01-02 built on MACHINE
Repository revision: 372d00a981942a5da868a33372eb29d5806f2ab3
Windowing system distributor 'Microsoft Corp.', version 10.0.10586
Configured using:
 'configure --prefix /c/emacs/emacs-20160101-122333
 --without-imagemagick --disable-dependency-tracking
 --enable-locallisppath=%emacs_dir%/../site-lisp 'CFLAGS=-Og -g -ggdb''

Configured features:
XPM JPEG TIFF GIF PNG RSVG SOUND DBUS NOTIFY ACL GNUTLS LIBXML2 ZLIB
TOOLKIT_SCROLL_BARS

Important settings:
  value of $LANG: ENG
  locale-coding-system: cp1252

Major mode: Lisp Interaction

Minor modes in effect:
  tooltip-mode: t
  global-eldoc-mode: t
  electric-indent-mode: t
  mouse-wheel-mode: t
  tool-bar-mode: t
  menu-bar-mode: t
  file-name-shadow-mode: t
  global-font-lock-mode: t
  font-lock-mode: t
  blink-cursor-mode: t
  auto-composition-mode: t
  auto-encryption-mode: t
  auto-compression-mode: t
  line-number-mode: t
  transient-mark-mode: t

Recent messages:
For information about GNU Emacs and the GNU system, type C-h C-a.

Load-path shadows:
None found.

Features:
(shadow sort gnus-util mail-extr emacsbug message dired format-spec
rfc822 mml mml-sec mm-decode mm-bodies mm-encode mail-parse rfc2231
mailabbrev gmm-utils mailheader sendmail rfc2047 rfc2045 ietf-drums
mm-util help-fns help-mode easymenu cl-loaddefs pcase cl-lib mail-prsvr
mail-utils time-date mule-util tooltip eldoc electric uniquify
ediff-hook vc-hooks lisp-float-type mwheel dos-w32 ls-lisp disp-table
w32-win w32-vars term/common-win tool-bar dnd fontset image regexp-opt
fringe tabulated-list newcomment elisp-mode lisp-mode prog-mode register
page menu-bar rfn-eshadow timer select scroll-bar mouse jit-lock
font-lock syntax facemenu font-core frame cl-generic cham georgian
utf-8-lang misc-lang vietnamese tibetan thai tai-viet lao korean
japanese eucjp-ms cp51932 hebrew greek romanian slovak czech european
ethiopic indian cyrillic chinese charscript case-table epa-hook
jka-cmpr-hook help simple abbrev minibuffer cl-preloaded nadvice
loaddefs button faces cus-face macroexp files text-properties overlay
sha1 md5 base64 format env code-pages mule custom widget
hashtable-print-readable backquote w32notify dbusbind w32 multi-tty
make-network-process emacs)

Memory information:
((conses 16 83465 5112)
 (symbols 56 19008 0)
 (miscs 48 36 86)
 (strings 32 14081 5015)
 (string-bytes 1 386417)
 (vectors 16 11288)
 (vector-slots 8 408630 5027)
 (floats 8 139 4)
 (intervals 56 239 22)
 (buffers 976 11))

bug#895: slow processing of process output

[Eli Zaretskii]

> From: Richard Copley <rcopley@gmail.com>
> Date: Fri, 8 Jan 2016 01:24:08 +0000
> 
> I tested in current master with mingw-w64 on Windows. The rgrep
> command given in the OP takes 29 s in Emacs, but the corresponding
> shell command[1] takes over a minute in Windows cmd.exe (at a guess,
> that's because cmd.exe scrolls line-by-line so has to push a lot of
> pixels).
> 
> Likewise, building Emacs is faster with "M-x compile" than it is on
> the shell (from a clean checkout on my configuration it takes 7 min 43
> seconds in Emacs and 9 minutes 15 seconds in cmd.exe).
> 
> I'm tempted to conclude that this bug has been fixed.

Thanks.

I think we need to try reproducing this on a Posix host before we can
conclude the bug is fixed.  The original problem was reported on
GNU/Linux, AFAICT, and the machinery used on Windows for communicating
with subprocesses is very different from that used on Unix.

Would someone please try reproducing this on GNU or Unix system?

TIA

bug#895: slow processing of process output

[Alexis]

Eli Zaretskii <eliz@gnu.org> writes:

> I think we need to try reproducing this on a Posix host before 
> we can conclude the bug is fixed.  The original problem was 
> reported on GNU/Linux, AFAICT, and the machinery used on Windows 
> for communicating with subprocesses is very different from that 
> used on Unix.
>
> Would someone please try reproducing this on GNU or Unix system?

Compiled from current master, running the rgrep command as per the 
OP successfully returns a buffer of ~17000 lines almost instantly 
on my Debian Jessie system.

bug#895: slow processing of process output

[Eli Zaretskii]

> From: Alexis <flexibeast@gmail.com>
> Cc: Richard Copley <rcopley@gmail.com>, 895@debbugs.gnu.org
> Date: Fri, 08 Jan 2016 20:53:59 +1100
> 
> Eli Zaretskii <eliz@gnu.org> writes:
> 
> > I think we need to try reproducing this on a Posix host before 
> > we can conclude the bug is fixed.  The original problem was 
> > reported on GNU/Linux, AFAICT, and the machinery used on Windows 
> > for communicating with subprocesses is very different from that 
> > used on Unix.
> >
> > Would someone please try reproducing this on GNU or Unix system?
> 
> Compiled from current master, running the rgrep command as per the 
> OP successfully returns a buffer of ~17000 lines almost instantly 
> on my Debian Jessie system.

Thanks, I guess this does mean we fixed it somehow.

bug#895: slow processing of process output

[Dmitry Gutov]

On 01/08/2016 12:30 PM, Eli Zaretskii wrote:

> Would someone please try reproducing this on GNU or Unix system?

Looks fixed:

With warm cache, the original commands takes 4 seconds in Emacs, also 4 
seconds in my shell (fish inside terminator), and produces the output of 
17000 lines.

It's still <1 second when redirected to a file, but that's to be 
expected, I think.

bug#895: slow processing of process output

[Eli Zaretskii]

> Cc: 895@debbugs.gnu.org
> From: Dmitry Gutov <dgutov@yandex.ru>
> Date: Fri, 8 Jan 2016 13:07:22 +0300
> 
> On 01/08/2016 12:30 PM, Eli Zaretskii wrote:
> 
> > Would someone please try reproducing this on GNU or Unix system?
> 
> Looks fixed:
> 
> With warm cache, the original commands takes 4 seconds in Emacs, also 4 
> seconds in my shell (fish inside terminator), and produces the output of 
> 17000 lines.
> 
> It's still <1 second when redirected to a file, but that's to be 
> expected, I think.

Thanks.

bug#895: slow processing of process output

[Richard Copley]

tags 685872 unreproducible

bug#895: slow processing of process output

[Noam Postavsky]

Dmitry Gutov <dgutov <at> yandex.ru> wrote:
>
> Looks fixed:
>
> With warm cache, the original commands takes 4 seconds in Emacs, also 4
> seconds in my shell (fish inside terminator), and produces the output of
> 17000 lines.
>
> It's still <1 second when redirected to a file, but that's to be
> expected, I think.

Closing.

bug#895: slow processing of process output

[Markus Triska]

I can reproduce the problem on OSX, and could significantly improve the
running time by setting process-connection-type to nil before doing the
rgrep. Let rgrep.el consist of:

   (grep-compute-defaults)
   (setq process-connection-type nil)
   (rgrep "emacs" "*.el" "~/emacs/lisp/")

   (while (process-status "grep")
     (sit-for 0.1))

and do:

   $ time emacs -Q --script rgrep.el

Then contrast this with retaining t for process-connection-type.

I have seen that using a pty can be a major performance problem also
when communicating with other external programs, and I recommend to
let-bind it to nil before starting the process when a pipe suffices.

bug#895: slow processing of process output

[Lars Magne Ingebrigtsen]

Markus Triska <markus.triska@gmx.at> writes:

> I can reproduce the problem on OSX, and could significantly improve the
> running time by setting process-connection-type to nil before doing the
> rgrep. Let rgrep.el consist of:
>
>    (grep-compute-defaults)
>    (setq process-connection-type nil)
>    (rgrep "emacs" "*.el" "~/emacs/lisp/")
>
>    (while (process-status "grep")
>      (sit-for 0.1))

I've now bound `process-connection-type' to nil in `rgrep' for Emacs 24.

-- 
(domestic pets only, the antidote for overdose, milk.)
  bloggy blog http://lars.ingebrigtsen.no/

bug#895: slow processing of process output

[Stefan Monnier]

>> I can reproduce the problem on OSX, and could significantly improve the
>> running time by setting process-connection-type to nil before doing the
>> rgrep. Let rgrep.el consist of:
>> 
>> (grep-compute-defaults)
>> (setq process-connection-type nil)
>> (rgrep "emacs" "*.el" "~/emacs/lisp/")
>> 
>> (while (process-status "grep")
>> (sit-for 0.1))

> I've now bound `process-connection-type' to nil in `rgrep' for Emacs 24.

What makes it faster?
Could it be that with process-connection-type set to nil grep doesn't emit
the color escape sequences?


        Stefan

bug#895: slow processing of process output

[Lars Magne Ingebrigtsen]

Stefan Monnier <monnier@iro.umontreal.ca> writes:

>> I've now bound `process-connection-type' to nil in `rgrep' for Emacs 24.
>
> What makes it faster?
> Could it be that with process-connection-type set to nil grep doesn't emit
> the color escape sequences?

Yes.

I've now reverted the change and reopened this bug report.

-- 
(domestic pets only, the antidote for overdose, milk.)
  bloggy blog http://lars.ingebrigtsen.no/

bug#895: slow processing of process output

[Lars Magne Ingebrigtsen]

I wonder whether (in the long term) it would make more sense to have the
`M-x grep' command be less...  shell-script-ey.

That is, if we instead prompted for the regexp we wanted to match
explicitly, then we could highlight it ourselves instead of relying on
grep to do it.

However, `M-x grep' as it is is pretty neat, because you can fiddle with
all the options and do

grep ... | grep -v | etc

So providing something that is as flexible as `M-x grep' is today, but
allow Emacs greater control of the output sounds difficult.

Ok, here's one other possibility off the top of my head: What about if
Emacs parsed the command line?  :-)

That is, if you're typing

grep -nH -e foo.*bar *.el

then the grep syntax isn't that impossible to parse.  I mean, finding
the regexp, and highlighting the matching bits.

It isn't difficult to imagine more complex command lines that Emacs
wouldn't be able to parse, though.  And you'd lose highlighting of the
matches there...

-- 
(domestic pets only, the antidote for overdose, milk.)
  bloggy blog http://lars.ingebrigtsen.no/

bug#895: slow processing of process output

[Drew Adams]

> That is, if we instead prompted for the regexp we wanted to match
> explicitly, then we could highlight it ourselves instead of relying on
> grep to do it.

I did that (without prompting), for Emacs 20 & 21.  See:
http://www.emacswiki.org/emacs/download/compile%2b20.el

It was I who proposed that vanilla Emacs itself highlight the matches.  That
idea was adopted, but Emacs Dev decided to do the highlighting using escape
chars provided by (some) external `grep' commands.

(So I adjusted my code too to use that approach:
http://www.emacswiki.org/emacs/download/grep%2b.el)

> However, `M-x grep' as it is is pretty neat, because you can 
> fiddle with all the options and do
> grep ... | grep -v | etc

Absolutely.  But there is no reason to conflate "[having] the `M-x grep' command
be less...shell-script-ey" with doing the highlighting in Lisp.  Why do you want
less shell-script-ey?

My code did the highlighting in Lisp, but it should not in any way interfere
with piping etc.  (However, for unrelated reasons piping with Emacs `grep' is
not available until Emacs 22, and it was Emacs 22 that introduced
external-`grep' highlighting.)

> So providing something that is as flexible as `M-x grep' is today, but
> allow Emacs greater control of the output sounds difficult.

Not at all (IIUYC).

> Ok, here's one other possibility off the top of my head: What about if
> Emacs parsed the command line?  :-) That is, if you're typing
> grep -nH -e foo.*bar *.el
> then the grep syntax isn't that impossible to parse.  I mean, finding
> the regexp, and highlighting the matching bits.

That is what I did, IIUYC.  The relevant bit of the compile+20.el code:

;; Remember `grep-pattern' for highlighting, if highlighting is possible.
(cond (;; Quoted pattern (either "..." or '...')
       (string-match
        (concat
         grep-program
         "[ \t]*\\(-[a-zA-Z]+\\s-+\\)*[ \t]*\\('[^']+'\\|\"[^\"]+\"\\)") ;"
        command-args)
       (setq grep-pattern
             (substring command-args
                        (1+ (match-beginning 2)) (1- (match-end 2)))))
      (;; Unquoted pattern.
       (string-match
        (concat grep-program
                "[ \t]*\\(-[a-zA-Z]+\\s-+\\)*[ \t]*\\([^ \n\t'\"]+\\)") ; "
        command-args)
       (setq grep-pattern
             (substring command-args (match-beginning 2) (match-end 2))))
      (t;; Bad pattern.
       (setq grep-pattern nil)))

;; Account for a case-insensitivity option.
(when (and (not (string= "" grep-case-insensitive-option))
           (string-match grep-case-insensitive-option command-args))
  (setq grep-pattern (mapconcat
                      (lambda (char)
                        (if (or (and (>= char ?a) (<= char ?z))
                                (and (>= char ?A) (<= char ?Z)))
                            (concat "["  (char-to-string (downcase char))
                                    (char-to-string (upcase char)) "]")
                          (char-to-string char)))
                      grep-pattern "")))

This is a quick hack that works well in general (for Emacs 20/21).  But note
that the `grep-pattern' highlighting is not anchored after the file name and
line number, so if the file name itself matches the `grep-pattern' then it
doesn't highlight the latter.

Someone could work out the code to anchor the pattern match properly.  I didn't
bother to try, since it is good enough as is, for my use.

> It isn't difficult to imagine more complex command lines that Emacs
> wouldn't be able to parse, though.  And you'd lose highlighting of the
> matches there...

Yes.

FWIW, I think the Emacs Dev approach of using external `grep' highlighting is
generally not bad (but there have been a few bugs that needed to be fixed along
the way).

bug#895: slow processing of process output

[Lars Magne Ingebrigtsen]

"Drew Adams" <drew.adams@oracle.com> writes:

> Absolutely.  But there is no reason to conflate "[having] the `M-x
> grep' command be less...shell-script-ey" with doing the highlighting
> in Lisp.  Why do you want less shell-script-ey?

For the very simple use cases, having "grep -nH -e " seems like a
distraction.  But I usually want it more shell-script-ey than less --
that `M-x grep' adds "/dev/null" at the end has often annoyed me
greatly, because you can't then say "grep foo *.el | grep -v bar".

> That is what I did, IIUYC.  The relevant bit of the compile+20.el code:
>
> ;; Remember `grep-pattern' for highlighting, if highlighting is possible.
> (cond (;; Quoted pattern (either "..." or '...')

Yeah, That's what I was thinking of.  :-)

> FWIW, I think the Emacs Dev approach of using external `grep'
> highlighting is generally not bad (but there have been a few bugs that
> needed to be fixed along the way).

Yes, it's a good idea, but there are these corner cases where it doesn't
work quite well.  Like when you have some (implicit) commands in the
pipeline that reacts badly to being run in a terminal, like the guy who
did a "git log" (or something?), and git then started "less", because it
thought it was in a terminal.

So to me it looks like the best long-term general solution is to bind
`process-connection-type' to nil in compile.el, and fix the highlighting
in Emacs Lisp, like your code does.

Perhaps.  :-)

-- 
(domestic pets only, the antidote for overdose, milk.)
  bloggy blog http://lars.ingebrigtsen.no/

bug#895: slow processing of process output

[Stefan Monnier]

> I wonder whether (in the long term) it would make more sense to have the
> `M-x grep' command be less...  shell-script-ey.

There are other commands that do that that (e.g. rgrep).
I like grep specifically because the Emacs wrapper is shallow which lets
me do anything I fancy so long as the output has the expected format.

> That is, if we instead prompted for the regexp we wanted to match
> explicitly, then we could highlight it ourselves instead of relying on
> grep to do it.

Actually doing this reliably can be tricky because of slight divergence
in the syntax and features of regular expressions accepted by Emacs and
by the various greps out there.

> Ok, here's one other possibility off the top of my head: What about if
> Emacs parsed the command line?  :-)

You go boy!


        Stefan

bug#895: slow processing of process output

[Dan Nicolaescu]

Lars Magne Ingebrigtsen <larsi@gnus.org> writes:

> Markus Triska <markus.triska@gmx.at> writes:
>
>> I can reproduce the problem on OSX, and could significantly improve the
>> running time by setting process-connection-type to nil before doing the
>> rgrep. Let rgrep.el consist of:
>>
>>    (grep-compute-defaults)
>>    (setq process-connection-type nil)
>>    (rgrep "emacs" "*.el" "~/emacs/lisp/")
>>
>>    (while (process-status "grep")
>>      (sit-for 0.1))
>
> I've now bound `process-connection-type' to nil in `rgrep' for Emacs 24.

This might solve the specific `rgrep' case, but that was only a specific
easy to reproduce example.
Processing process output is slow for other things too.
For example compare the time to run
make bootstrap
when using M-x compile

vs doing it in an xterm.

bug#895: slow processing of process output

[Stefan Monnier]

> For example compare the time to run make bootstrap when using M-x
> compile vs doing it in an xterm.

Agreed.  I encourage people to try and look into this problem.
First thing is to profile to figure out where the time is spent.


        Stefan