Re: The timerfd functions slow down emacs

[Corinna Vinschen <corinna-cygwin at cygwin dot com>]

On Feb 23 16:05, Ken Brown wrote:
> On 2/21/2019 6:52 PM, Ken Brown wrote:
> > When emacs is built, it detects the timerfd functions and uses them if they're
> > found.  Now that Cygwin has these functions, the resulting build of emacs is
> > very slow to respond to user input.  If I press a key, there is a 1-2 second
> > delay before emacs responds.
> > 
> > I can work around this by configuring emacs with emacs_cv_have_timerfd=no, but
> > it would be nice to find the cause.  I'll try to make an STC, but I thought I'd
> > report it here in the meantime, in case anyone has ideas or debugging suggestions.
> 
> I don't have an STC yet, but if I start emacs and then attach gdb to it at 
> random times, the backtrace always look like this:
> 
> #0  0x00007ffbb192b4f4 in ntdll!ZwWaitForMultipleObjects ()
>     from /c/WINDOWS/SYSTEM32/ntdll.dll
> #1  0x00007ffbadf56099 in WaitForMultipleObjectsEx ()
>     from /c/WINDOWS/System32/KERNELBASE.dll''
> #2  0x00007ffbadf55f8e in WaitForMultipleObjects ()
>     from /c/WINDOWS/System32/KERNELBASE.dll
> #3  0x0000000180159f9d in timerfd_tracker::wait (this=this@entry=0x1803a22c0,
>      nonblocking=false)
>      at /usr/src/debug/cygwin-3.0.1-1/winsup/cygwin/timerfd.cc:448
> #4  0x00000001800a7b0e in fhandler_timerfd::read (this=<optimized out>,
>      ptr=0xffffba30, len=@0xffffb9b0: 8)
>      at /usr/src/debug/cygwin-3.0.1-1/winsup/cygwin/fhandler_timerfd.cc:134
> [...]
> 
> This suggests to me that the slowdown comes from timerfd_tracker::wait.
> 
> The context is that emacs creates a timerfd timer that expires every 2 seconds, 
> 'select' waits for the timer's file descriptor to be ready for reading, and then 
> emacs calls 'read'.

Below's the NSSTC I used to test my timerfd implementation (based on
another STC to show a problem in POSIX timers).  From what I can tell it
works as desired.  If you find a problem, please point it out or send a
patch.


Thanks,
Corinna


#define _GNU_SOURCE 1
#include <sys/timerfd.h>
#include <sys/select.h>
#include <sys/wait.h>
#include <time.h>
#include <unistd.h>
#include <fcntl.h>
#include <stdlib.h>
#include <stdio.h>
#include <stdint.h>		/* Definition of uint64_t */

#define handle_error(msg) \
       do { perror(msg); exit(EXIT_FAILURE); } while (0)

static void
print_elapsed_time (void)
{
  static struct timespec start;
  struct timespec curr;
  static int first_call = 1;
  int secs, nsecs;

  if (first_call)
    {
      first_call = 0;
      if (clock_gettime (CLOCK_REALTIME, &start) == -1)
	handle_error ("clock_gettime");
    }

  if (clock_gettime (CLOCK_REALTIME, &curr) == -1)
    handle_error ("clock_gettime");

  secs = curr.tv_sec - start.tv_sec;
  nsecs = curr.tv_nsec - start.tv_nsec;
  if (nsecs < 0)
    {
      secs--;
      nsecs += 1000000000;
    }
  printf ("%d.%03d: ", secs, (nsecs + 500000) / 1000000);
}

int
main (int argc, char *argv[])
{
  struct itimerspec new_value;
  int max_exp, fd;
  struct timespec now;
  uint64_t exp, tot_exp;
  ssize_t s;
  fd_set fds;
  int status;
  int i;

  if ((argc != 2) && (argc != 4) && argc != 5)
    {
      fprintf (stderr, "%s init-secs [interval-secs max-exp]\n", argv[0]);
      exit (EXIT_FAILURE);
    }

  if (clock_gettime (CLOCK_MONOTONIC, &now) == -1)
    handle_error ("clock_gettime");

  /* Create a CLOCK_MONOTONIC absolute timer with initial
     expiration and interval as specified in command line */

  new_value.it_value.tv_sec = atoi (argv[1]) + now.tv_sec;
  new_value.it_value.tv_nsec = now.tv_nsec;
  if (argc == 2)
    {
      new_value.it_interval.tv_sec = 0;
      max_exp = 1;
    }
  else
    {
      new_value.it_interval.tv_sec = atoi (argv[2]);
      max_exp = atoi (argv[3]);
    }
  new_value.it_interval.tv_nsec = 0;

  if (argc == 5)
    {
#if 1
      char buf[128];
      sprintf (buf, "ls -l /proc/%d/fd", getpid ());
      system (buf);
#endif
      fd = atoi (argv[4]);
      goto machhinne;
    }

  fd = timerfd_create (CLOCK_MONOTONIC, 0);
  if (fd == -1)
    handle_error ("timerfd_create");

  if (timerfd_settime (fd, TFD_TIMER_ABSTIME, &new_value, NULL) == -1)
    handle_error ("timerfd_settime");
#if 0
  switch (fork ())
    {
    case -1:
      perror ("fork");
      break;
    case 0:
      {
	char buf[128];
	sprintf (buf, "ls -l /proc/%d/fd", getpid ());
	system (buf);
      }
      break;
    default:
      break;
    }
#elif 0
  switch (fork ())
    {
    case 0:
      {
	char buf[16];
	printf ("child %d\n", getpid ());
	snprintf (buf, sizeof buf, "%d", fd);
	execl ("./timerfd", argv[0], argv[1], argv[2], argv[3], buf, NULL);
	perror ("execl");
      }
      break;
    case -1:
      perror ("fork");
      return 0;
    default:
      printf ("parent %d\n", getpid ());
      break;
    }
#endif
machhinne:

  print_elapsed_time ();
  printf ("timer started %d\n", getpid ());

  for (i = 0, tot_exp = 0; tot_exp < max_exp; ++i)
    {
#if 1
      int ret;
      FD_ZERO (&fds);
      FD_SET (fd, &fds);
      ret = select (fd + 1, &fds, NULL, NULL, NULL);
      if (ret < 0)
	perror ("select");
      if (!FD_ISSET (fd, &fds))
	continue;

#endif
      s = read (fd, &exp, sizeof (uint64_t));
      if (s != sizeof (uint64_t))
	handle_error ("read");

      tot_exp += exp;
      print_elapsed_time ();
      printf ("%d read: %llu; total=%llu\n",
	      getpid (),
	      (unsigned long long) exp, (unsigned long long) tot_exp);
    }

  wait (&status);
  exit (EXIT_SUCCESS);
}

-- 
Corinna Vinschen
Cygwin Maintainer

Attachment: signature.asc
Description: PGP signature