bug#18626: 24.3.94; communication with subprocess is slow

[stephen_leake]

This may be related to http://debbugs.gnu.org/cgi/bugreport.cgi?bug=18420

I've run into another problem with Emacs communication with external
processes; there seems to be a delay on every task switch. This shows up
both when sending data to the subprocess, and when reading from it.

When sending the contents of an Emacs buffer (source code to be parsed)
to the subprocess, if the read buffer in the subprocess is
large enough to hold the entire contents, no delay is apparent. However,
if the buffer is smaller, so that several reads are needed, then a delay
appears.

Similarly when sending data from the subprocess to Emacs.

To measure the delay:

(defun pipe-torture (exe &rest args)
  ""
  (let ((proc (apply 'start-process "pipe-reader" "pipe-read" exe args))
        start-time)

    (unless (process-live-p proc)
      (error "process died"))

    (setq start-time (time-to-seconds (current-time)))
    (process-send-region proc (point-min) (point-max))
    (message "send time %f" (- (time-to-seconds (current-time)) start-time))
    ))

(find-file "emacs-24.3.94/src/xdisp.c")
(pipe-torture "cat.exe")
    => 11.255173

The time varies slightly with each run. "cat.exe" here is from Cygwin.

For comparison, in a Cygwin bash shell on the same system:

$ cd /tmp
$ time cat < /Projects/emacs/emacs-24.3.94/src/xdisp.c > xdisp.c
real    0m0.051s
user    0m0.000s
sys     0m0.030s

Doing (setq process-adaptive-read-buffering nil) did not change the
timing.

To show the effect of changing the number of subprocess reads, here is a
trivial Ada program that reads from stdin into a buffer whose size is
set from the command line, and does no writes:

with Ada.Command_Line;
with GNAT.OS_Lib;
procedure Debug
is
   use GNAT.OS_Lib;

   Chunk : constant Integer := Integer'Value (Ada.Command_Line.Argument (1));

   File       : constant File_Descriptor := GNAT.OS_Lib.Standin;
   Read_Bytes : Integer;
   Text       : aliased String (1 .. Chunk);
begin
   loop
      Read_Bytes := Read (File, Text'Address, Chunk);
      exit when Read_Bytes < Chunk;
   end loop;
end Debug;


in xdisp.c:

(pipe-torture "debug.exe" "4096")
4.797574

(pipe-torture "debug.exe" "40000")
0.523758

The test with "debug.exe" can also be run in Emacs 24.3.1, since it does
not mix reads and writes (see bug 18420); it gives a time comparable to
the command-line "cat": 0.053000


To show the delay on reading subprocess output:

(defun pipe-torture-read (file)
  ""
  (let ((proc (apply 'start-process "pipe-reader" "pipe-read" (list "bash" "-c" 
(concat "cat < " file))))
        start-time)

    (unless (process-live-p proc)
      (error "process died"))

    (setq start-time (time-to-seconds (current-time)))
    (while (process-live-p proc)
      (accept-process-output proc))

    (message "read time %f" (- (time-to-seconds (current-time)) start-time))
    ))

In emacs 24.3.94:
(pipe-torture-read "/Projects/emacs/emacs-24.3.94/src/xdisp.c")
"read time 11.965184"

In Windows native emacs 24.3.1:
(pipe-torture-read "/Projects/emacs/emacs-24.3.94/src/xdisp.c")
"read time 11.992000"



In GNU Emacs 24.3.94.1 (x86_64-pc-mingw32)
 of 2014-10-04 on TAKVER
Windowing system distributor `Microsoft Corp.', version 6.1.7601
Configured using:
 `configure --prefix=/mingw32'

Important settings:
  value of $LANG: en_US.UTF-8
  locale-coding-system: cp1252

Major mode: Text

Minor modes in effect:
  diff-auto-refine-mode: t
  display-time-mode: t
  delete-selection-mode: t
  tooltip-mode: t
  electric-indent-mode: t
  mouse-wheel-mode: t
  menu-bar-mode: t
  file-name-shadow-mode: t
  global-font-lock-mode: t
  font-lock-mode: t
  auto-composition-mode: t
  auto-encryption-mode: t
  auto-compression-mode: t
  line-number-mode: t
  transient-mark-mode: t

Recent input:
C-s a d a <C-f12> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> M-x b u g - r e p o r t <return>
<M-S-left> <M-S-left> r e p o r <tab> <return>

Recent messages:
Loading c:/Projects/emacs_stephe.work/emacs_stephe/stephe_settings.el 
(source)...done
For information about GNU Emacs and the GNU system, type C-h C-a.
Loading c:/Projects/org.emacs.dvc.stephe/dvc-load.el (source)...done
Loading c:/Projects/emacs_stephe.work/emacs_stephe/dvc-patches.el (source)...
Loading c:/Projects/emacs_stephe.work/emacs_stephe/vc-mode-keys.el 
(source)...done
Loading c:/Projects/emacs_stephe.work/emacs_stephe/dvc-patches.el 
(source)...done
Package iswitchb is obsolete!
Mark saved where search started
Function xmtn-match--generate-branch is already compiled
Function xmtn-match--contains-match-variable-p is already compiled

Load-path shadows:
/Projects/org.emacs.ada-mode.stephe-1/ada-mode hides 
c:/Projects/emacs/emacs-24.3.94/lisp/progmodes/ada-mode

Features:
(shadow sort mail-extr emacsbug sendmail xmtn-dvc dvc-status dvc-diff
dvc-fileinfo diff-mode xmtn-conflicts xmtn-ids xmtn-match xmtn-automate
xmtn-compat parse-time xmtn-run xmtn-basic-io xmtn-base misearch
multi-isearch xgit-core bzr-core xmtn-minimal dvc-log log-edit message
format-spec rfc822 mml mml-sec mm-decode mm-bodies mm-encode mail-parse
rfc2231 rfc2047 rfc2045 ietf-drums mailabbrev mail-utils gmm-utils
mailheader pcvs-util vc vc-dispatcher ediff-merg ediff-wind ediff-diff
ediff-mult ediff-help ediff-init ediff-util ediff dvc-unified dvc-tips
ffap thingatpt url-parse auth-source eieio byte-opt bytecomp
byte-compile cconv eieio-core gnus-util mm-util help-fns mail-prsvr
password-cache url-vars add-log dvc-autoloads dvc-core dvc-lisp
dvc-buffers dvc-ui dvc-register dvc-utils dvc-emacs ewoc dvc-defs
dvc-site time delsel cus-start cus-load color-theme cl-macs edmacro
kmacro wid-edit cl gv cl-loaddefs cl-lib noutline outline easy-mmode
iswitchb whitespace dired-x dired-aux dired compile comint ansi-color
ring info easymenu bbdb-autoloads package epg-config time-date tooltip
electric uniquify ediff-hook vc-hooks lisp-float-type mwheel dos-w32
ls-lisp w32-common-fns disp-table w32-win w32-vars tool-bar dnd fontset
image regexp-opt fringe tabulated-list newcomment lisp-mode prog-mode
register page menu-bar rfn-eshadow timer select scroll-bar mouse
jit-lock font-lock syntax facemenu font-core frame cham georgian
utf-8-lang misc-lang vietnamese tibetan thai tai-viet lao korean
japanese hebrew greek romanian slovak czech european ethiopic indian
cyrillic chinese case-table epa-hook jka-cmpr-hook help simple abbrev
minibuffer 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 make-network-process
w32notify w32 multi-tty emacs)

Memory information:
((conses 8 260868 6068)
 (symbols 32 28706 0)
 (miscs 32 46 139)
 (strings 16 49862 6082)
 (string-bytes 1 1215255)
 (vectors 8 19963)
 (vector-slots 4 495165 5152)
 (floats 8 177 242)
 (intervals 28 289 12)
 (buffers 512 13))