Subject: bug#20978: closed (Re: 25.0.50; [PATCH 0/7] Emacs can return too fast when reading from any processes)

From: [email-masked] (GNU bug Tracking System)
Date: Mon, 06 Jul 2015 02:30:11 +0000

Your bug report

#20978: 25.0.50; [PATCH 0/7] Emacs can return too fast when reading from any processes

which was filed against the emacs package, has been closed.

The explanation is attached below, along with your original report.
If you require more details, please reply to [email-masked].

-- 
20978: http://debbugs.gnu.org/cgi/bugreport.cgi?bug=20978
GNU Bug Tracking System
Contact [email-masked] with problems

Subject: Re: 25.0.50; [PATCH 0/7] Emacs can return too fast when reading from any processes
From: Paul Eggert <[email-masked]>
To: Ian Kelling <[email-masked]>
Cc: [email-masked]
Date: Sun, 05 Jul 2015 19:28:54 -0700
List-Id: <debbugs-submit.debbugs.gnu.org>

Thanks for the patches; they were very clear and organized, in a difficult code 
area.  I installed them into the Emacs master with minor changes, along with the 
attached further patch, and am marking this bug as done.

As far as patch format goes, I mildly prefer attachments but the form you used 
was fine.  My preference is because I am not on the bug-gnu-emacs mailing list, 
and don't know how to retrieve your email from debbugs.gnu.org or from 
lists.gnu.org -- the best I could come up with was the mbox format of 
lists.gnu.org but that did not apply cleanly.
>From fea99d2d8563334a8c88ec4207064ce49d77dd1f Mon Sep 17 00:00:00 2001
From: Paul Eggert <[email-masked]>
Date: Sun, 5 Jul 2015 19:19:13 -0700
Subject: [PATCH 8/8] Avoid duplicate calls to current_timespec

* src/process.c (wait_reading_process_output):
Cache current_timespec results as long as we're not waiting.
---
 src/process.c | 44 +++++++++++++++++++++++++++++---------------
 1 file changed, 29 insertions(+), 15 deletions(-)

diff --git a/src/process.c b/src/process.c
index 8a8dad7..9d8fa22 100644
--- a/src/process.c
+++ b/src/process.c
@@ -4591,6 +4591,9 @@ wait_reading_process_output (intmax_t time_limit, int nsecs, int read_kbd,
   int got_some_output = -1;
   ptrdiff_t count = SPECPDL_INDEX ();
 
+  /* Close to the current time if known, an invalid timespec otherwise.  */
+  struct timespec now = invalid_timespec ();
+
   FD_ZERO (&Available);
   FD_ZERO (&Writeok);
 
@@ -4611,8 +4614,8 @@ wait_reading_process_output (intmax_t time_limit, int nsecs, int read_kbd,
   else if (time_limit > 0 || nsecs > 0)
     {
       wait = TIMEOUT;
-      end_time = timespec_add (current_timespec (),
-                               make_timespec (time_limit, nsecs));
+      now = current_timespec ();
+      end_time = timespec_add (now, make_timespec (time_limit, nsecs));
     }
   else
     wait = INFINITY;
@@ -4637,7 +4640,8 @@ wait_reading_process_output (intmax_t time_limit, int nsecs, int read_kbd,
       /* Exit if already run out.  */
       if (wait == TIMEOUT)
 	{
-	  struct timespec now = current_timespec ();
+	  if (!timespec_valid_p (now))
+	    now = current_timespec ();
 	  if (timespec_cmp (end_time, now) <= 0)
 	    break;
 	  timeout = timespec_sub (end_time, now);
@@ -4830,7 +4834,6 @@ wait_reading_process_output (intmax_t time_limit, int nsecs, int read_kbd,
 	}
       else
 	{
-
 	  /* Set the timeout for adaptive read buffering if any
 	     process has non-zero read_output_skip and non-zero
 	     read_output_delay, and we are not reading output for a
@@ -4876,17 +4879,21 @@ wait_reading_process_output (intmax_t time_limit, int nsecs, int read_kbd,
 	      && timespec_valid_p (timer_delay)
 	      && timespec_cmp (timer_delay, timeout) < 0)
 	    {
-	      struct timespec timeout_abs = timespec_add (current_timespec (),
-							  timeout);
+	      if (!timespec_valid_p (now))
+		now = current_timespec ();
+	      struct timespec timeout_abs = timespec_add (now, timeout);
 	      if (!timespec_valid_p (got_output_end_time)
-		  || timespec_cmp (timeout_abs,
-				   got_output_end_time) < 0)
+		  || timespec_cmp (timeout_abs, got_output_end_time) < 0)
 		got_output_end_time = timeout_abs;
 	      timeout = timer_delay;
 	    }
 	  else
 	    got_output_end_time = invalid_timespec ();
 
+	  /* NOW can become inaccurate if time can pass during pselect.  */
+	  if (timeout.tv_sec > 0 || timeout.tv_nsec > 0)
+	    now = invalid_timespec ();
+
 #if defined (HAVE_NS)
           nfds = ns_select
 #elif defined (HAVE_GLIB)
@@ -4965,14 +4972,21 @@ wait_reading_process_output (intmax_t time_limit, int nsecs, int read_kbd,
              haven't lowered our timeout due to timers or SIGIO and
              have waited a long amount of time due to repeated
              timers.  */
-	  struct timespec now = current_timespec ();
-          if (wait < TIMEOUT
-	      || (wait == TIMEOUT && timespec_cmp (end_time, now) <= 0)
-	      || (!process_skipped && got_some_output > 0
-		  && (!timespec_valid_p (got_output_end_time)
-		      || timespec_cmp (got_output_end_time, now) <= 0)
-		  && (timeout.tv_sec > 0 || timeout.tv_nsec > 0)))
+	  if (wait < TIMEOUT)
 	    break;
+	  struct timespec cmp_time
+	    = (wait == TIMEOUT
+	       ? end_time
+	       : (!process_skipped && got_some_output > 0
+		  && (timeout.tv_sec > 0 || timeout.tv_nsec > 0))
+	       ? got_output_end_time
+	       : invalid_timespec ());
+	  if (timespec_valid_p (cmp_time))
+	    {
+	      now = current_timespec ();
+	      if (timespec_cmp (cmp_time, now) <= 0)
+		break;
+	    }
 	}
 
       if (nfds < 0)
-- 
2.1.0

Subject: 25.0.50; [PATCH 0/7] Emacs can return too fast when reading from any processes
From: Ian Kelling <[email-masked]>
To: [email-masked]
Date: Sat, 04 Jul 2015 05:34:33 -0700
List-Id: <debbugs-submit.debbugs.gnu.org>

In GNU Emacs 25.0.50.63 (x86_64-unknown-linux-gnu, GTK+ Version 3.10.8)
 of 2015-07-04
Repository revision: 5c36788e76b22587e554960ed837f724473597a9
Windowing system distributor `The X.Org Foundation', version 11.0.11501000
System Description:	Ubuntu 14.04.2 LTS

Configured using:
 `configure 'CFLAGS=-O0 -g3''

Configured features:
XPM JPEG TIFF GIF PNG RSVG IMAGEMAGICK SOUND GPM DBUS GCONF GSETTINGS
NOTIFY ACL LIBSELINUX GNUTLS LIBXML2 FREETYPE M17N_FLT LIBOTF XFT ZLIB
TOOLKIT_SCROLL_BARS GTK3 X11

Overview:

The patch for debbugs:17647 causes emacs to return too fast sometimes
when reading from any processes. It made adaptive read buffering be
mostly dead code and caused readline-complete package to break. Instead,
limit timeout less aggressively.

Reproducing the problem:

emacs -Q -l repro.el

;; repro.el
(progn
  (setq explicit-bash-args '("--norc"))
  (setenv "EMACS" "")
  (setq comint-process-echoes t)
  (shell)
  (let* ((proc (get-buffer-process (current-buffer)))
         (filter-orig (process-filter proc))
         accumulated-output)
    (process-send-string proc "stty echo\n")
    (set-process-query-on-exit-flag proc nil)
    (dotimes (unused 10)
      (sleep-for .05))
    (set-process-filter proc (lambda (proc string) (push (list string) accumulated-output)))
    (process-send-string proc "echo a bit of text for testing\n")
    (dotimes (unused 100)
      (sleep-for .03))
    (message "waiting for any process: %s" (reverse accumulated-output))
    (switch-to-buffer "*Messages*")
    nil))

Output without my patches:

waiting for any process:
((ech) (o a ) (bi) (t ) (o) (f ) (t) (e) (x) (t) ( ) (f) (o) (r) ( ) (t) (e) (s) (t) (i) (n) (g) (
) (a bit of text for testing
) (bash-4.3$ ))

Output with my patches (also the same same output as before the
debbugs:17647 patch, aka git 05d2821):

waiting for any process:
((ec) (ho a bit of text for testing
a bit of text for testing
bash-4.3$ ))

Background:

The 17647 patch had a few things bundled in and the root problem and fix
was not documented. The problem was that we got output, and we
subsequently got a pselect of 0, but we have set
timeout_reduced_for_timers, so we don't break when we should. This is
the relevant condition:

if ((time_limit || nsecs) && nfds == 0 && ! timeout_reduced_for_timers)
  break;

This was fixed by setting the timeout to 0 if we've attempted to read
process output. However, that was too big a hammer.

What we actually want is what the original code tried to do, but had
some logic problems: read data, and stop if there is no more to read in
a reasonable amount of time or we've reached the requested timeout.

There is a reference to someone else having this issue as well, without
figuring out anything about it
http://lists.gnu.org/archive/html/bug-gnu-emacs/2014-06/msg00958.html
And there is a resulting workaround in flymake-tests.el.

About the patches:

The first 4 are refactoring and not necessarily dependent on any others,
but independent patches would conflict and they make the code clearer so
I included them. I can separate any of them if needed.

Patch 3 depends on the patch for debbugs:20976, which is a simple fix
and I expect no problem for it be applied first.

I was careful to not squash unrelated changes as the function is rather
complicated and I could have saved a fair amount of time if there
weren't unrelated changes in the patch that introduced this bug.

The last 2 patches are probably easier to understand squashed together,
but the last one one fixes a different avenue for the same bug to
manifest (SIGIO), which I haven't tried to reproduce, and includes more
circumstances (reading from a specific process and before we've gotten
any output), and I'm not sure if some code might depend on it's behavior
so I broke it out.

Make check succeeds on all the patches.

Ian Kelling (7):
  ; Minor cleanup of wait_reading_process_output
  ; Remove ADAPTIVE_READ_BUFFERING ifdef
  ; Rename local var to match function name
  ; Rename local var nsecs to adaptive_nsecs
  : Refactor timeouts in wait_reading_process_output
  Don't return as fast reading any process output
  Avoid returning early reading process output due to SIGIO

 src/process.c | 211 +++++++++++++++++++++++++++-------------------------------
 1 file changed, 98 insertions(+), 113 deletions(-)

--
2.4.5