Re: Any idea about what makes Emacs slow reading on pipes?

[Kim F. Storm]

address@hidden (David Kastrup) writes:

> Here is a more elaborate test file
> 
> (defvar test-pattern nil)
> (defvar test-start nil)
> 
> (defun test-filter (process string)
>   (push (cons (length string) (time-since test-start)) test-pattern)
>   (with-current-buffer (process-buffer process)
>     (insert-before-markers string)))
> 
> (defun make-test nil (interactive)
>   (switch-to-buffer (get-buffer-create "*test*"))
>   (erase-buffer)
>   (setq test-pattern nil test-start (current-time))
>   (set-process-filter (start-process
>                      "test" (current-buffer) "sh"
>                      "-c" "hexdump -v /dev/zero|dd bs=1 count=100k")
>                     #'test-filter))
> 

With your test program, I get the following result on redhat 6.2 on a
650HMz P3 system:

((87 0 2) (1024 0 2) (1024 0 2) (1023 0 2) (1024 0 2) (1024 0 2) (1024
0 2) (1023 0 2) (1024 0 2) (1024 0 2) (1024 0 2) (1023 0 2) (1024 0 2)
(1024 0 2) (1024 0 2) (1023 0 2) (1024 0 2) (1024 0 2) (1024 0 2)
(1023 0 2) (1024 0 2) (1024 0 2) (1024 0 2) (1023 0 2) (1024 0 2)
(1024 0 2) (1024 0 2) (1023 0 2) (1024 0 2) (1024 0 2) (1024 0 2)
(1023 0 2) (1024 0 2) (1024 0 2) (1024 0 1) (1023 0 1) (1024 0 1)
(1024 0 1) (1024 0 1) (1023 0 1) (1024 0 1) (1024 0 1) (1024 0 1)
(1023 0 1) (1024 0 1) (1024 0 1) (1024 0 1) (1023 0 1) (1024 0 1)
(1024 0 1) (1024 0 1) (1023 0 1) (1024 0 1) (1024 0 1) (1024 0 1)
(1023 0 1) (1024 0 1) (1024 0 1) (1024 0 1) (1023 0 1) (1024 0 1)
(1024 0 1) (1024 0 1) (1023 0 1) (1024 0 1) (1024 0 1) (1024 0 1)
(1023 0 1) (1024 0 1) (1024 0 1) (1024 0 1) (1023 0 1) (1024 0 1)
(1024 0 1) (1024 0 1) (1023 0 1) (1024 0 1) (1024 0 1) (1024 0 1)
(1023 0 1) (1024 0 1) (1024 0 1) (1024 0 1) (1023 0 1) (1024 0 1)
(1024 0 1) (1024 0 1) (1023 0 1) (1024 0 1) (1024 0 1) (1024 0 1)
(1024 0 1) (1024 0 1) (1024 0 1) (1024 0 1) (1024 0 0) (1 0 0)
(1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (304 0 0) (1024 0 0) (1 0 0)
(1 0 0) (582 0 0) (1024 0 0) (1024 0 0) (1024 0 0) (1 0 0) (1 0 0)
(1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0)
(1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0)
(1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0)
(1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0)
(1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0)
(1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0)
(1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0)
(1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0)
(1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0)
(1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0)
(1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0)
(1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0)
(1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0) (1 0 0))

So I do see the "1 byte" reads, but not the slowness.

> I don't know _what_ Emacs does do the pipe/pty that causes only single
> characters to gather/be processed, with a sporadic 1024 packet getting
> through from time to time, but I hate it.  Some setting must be on the
> pipe that causes the writer to stall before further writes in many
> cases until Emacs has read the next character.  And after some time
> the pipe gets filled properly now and then, with single characters in
> between.
> 
> I don't get it.

Well, it seems that emacs is FAST enough the keep up with your dd
which actually only writes 1 byte at a time, so basically if your
program writes 1 char at a time, emacs will read 1 char at a time if
it can keep up...  I guess the occasional 1024 read is because of
scheduling of other processes or some such, and because eventually,
emacs cannot keep up anymore (when it has to extend the buffer or some
such).

What happens if you try the following version, which forces
start-process to use a pipe rather than a pty:

(defun make-test nil (interactive)
  (switch-to-buffer (get-buffer-create "*test*"))
  (erase-buffer)
  (setq test-pattern nil test-start (current-time))
  (let ((process-connection-type nil))
    (set-process-filter (start-process
               "test" (current-buffer) "sh"
               "-c" "hexdump -v /dev/zero|dd bs=1 count=100k")
              #'test-filter)))

It has some effect in my setup, but nothing dramatic.

But if you really want to speed up things, use a block size
of 1k like this:

(defun make-test nil (interactive)
  (switch-to-buffer (get-buffer-create "*test*"))
  (erase-buffer)
  (setq test-pattern nil test-start (current-time))
  (let ((process-connection-type nil))
    (set-process-filter (start-process
               "test" (current-buffer) "sh"
               "-c" "hexdump -v /dev/zero|dd bs=1k count=100")
              #'test-filter)))

On my system, it gives the optimal behaviour:

((35 0 2) (1024 0 2) (1024 0 2) ... (1024 0 2))


Based on this, I would conclude that emacs is behaving _correctly_ for
the input you supply it.

-- 
Kim F. Storm <address@hidden> http://www.cua.dk