X-Recipient: archive-cygwin AT delorie DOT com
DomainKey-Signature: a=rsa-sha1; c=nofws; d=sourceware.org; h=list-id
	:list-unsubscribe:list-subscribe:list-archive:list-post
	:list-help:sender:date:from:to:cc:subject:message-id:reply-to
	:references:mime-version:content-type:in-reply-to; q=dns; s=
	default; b=jF6yGzAtNxA8VTWhiRpWs7oWZsaGo7Cg4UjOl5S4c9X5cXXR6qQVX
	TRPe6IoZJQ6CuBpj9GyfYcgmpJBiI6uvR8N0po+M6Y8QROu9e1Wd+uEmta4pycvF
	wBFtUf9NCFpdHbP1s+WXX0hwsykju5WKNt9dS+tY0zl8evv87SVbTA=
DKIM-Signature: v=1; a=rsa-sha1; c=relaxed; d=sourceware.org; h=list-id
	:list-unsubscribe:list-subscribe:list-archive:list-post
	:list-help:sender:date:from:to:cc:subject:message-id:reply-to
	:references:mime-version:content-type:in-reply-to; s=default;
	 bh=icm3+WoMLgStZFJq8bx4fUyxPwo=; b=P0QtkdgQ+dEWkKfXIjAvJudYUdqb
	lKKKPuuHPKDSyRe5So4EGLoTEhkZGFeUehiBobGcazdw7fVfC/6NjJOA9596QCtD
	P1TJiOxPDMW1n1rWzmzGrPgJ+VOfefZ0lJcXpJmb7sWouoY756A0fDGC4nETCd6G
	iz+vj7L3lc6Q28A=
Mailing-List: contact cygwin-help AT cygwin DOT com; run by ezmlm
List-Id: <cygwin.cygwin.com>
List-Subscribe: <mailto:cygwin-subscribe AT cygwin DOT com>
List-Archive: <http://sourceware.org/ml/cygwin/>
List-Post: <mailto:cygwin AT cygwin DOT com>
List-Help: <mailto:cygwin-help AT cygwin DOT com>, <http://sourceware.org/ml/#faqs>
Sender: cygwin-owner AT cygwin DOT com
Mail-Followup-To: cygwin AT cygwin DOT com
Delivered-To: mailing list cygwin AT cygwin DOT com
Authentication-Results: sourceware.org; auth=none
X-Spam-SWARE-Status: No, score=-100.9 required=5.0 tests=BAYES_00,GOOD_FROM_CORINNA_CYGWIN,KAM_LAZY_DOMAIN_SECURITY,RCVD_IN_DNSWL_NONE autolearn=ham version=3.3.2 spammy=500000, H*F:D*cygwin.com, belows, timer
X-HELO: mout.kundenserver.de
Date: Sat, 23 Feb 2019 20:15:42 +0100
From: Corinna Vinschen <corinna-cygwin AT cygwin DOT com>
To: Ken Brown <kbrown AT cornell DOT edu>
Cc: cygwin AT cygwin DOT com
Subject: Re: The timerfd functions slow down emacs
Message-ID: <20190223191542.GS4256@calimero.vinschen.de>
Reply-To: cygwin AT cygwin DOT com
Mail-Followup-To: Ken Brown <kbrown AT cornell DOT edu>, cygwin AT cygwin DOT com
References: <04048cc3-091a-b55c-372b-bde29273d952 AT cornell DOT edu> <1df3d7ce-1427-cbd4-0978-7236b1903440 AT cornell DOT edu>
MIME-Version: 1.0
Content-Type: multipart/signed; micalg=pgp-sha256;	protocol="application/pgp-signature"; boundary="UKsZWh/ZtaJX4ozz"
Content-Disposition: inline
In-Reply-To: <1df3d7ce-1427-cbd4-0978-7236b1903440@cornell.edu>
User-Agent: Mutt/1.10.1 (2018-07-13)

--UKsZWh/ZtaJX4ozz
Content-Type: text/plain; charset=utf-8
Content-Disposition: inline
Content-Transfer-Encoding: quoted-printable

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 ema=
cs is
> > very slow to respond to user input.  If I press a key, there is a 1-2 s=
econd
> > delay before emacs responds.
> >=20
> > I can work around this by configuring emacs with emacs_cv_have_timerfd=
=3Dno, but
> > it would be nice to find the cause.  I'll try to make an STC, but I tho=
ught I'd
> > report it here in the meantime, in case anyone has ideas or debugging s=
uggestions.
>=20
> I don't have an STC yet, but if I start emacs and then attach gdb to it a=
t=20
> random times, the backtrace always look like this:
>=20
> #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=3Dthis AT entry=3D0x18=
03a22c0,
>      nonblocking=3Dfalse)
>      at /usr/src/debug/cygwin-3.0.1-1/winsup/cygwin/timerfd.cc:448
> #4  0x00000001800a7b0e in fhandler_timerfd::read (this=3D<optimized out>,
>      ptr=3D0xffffba30, len=3D AT 0xffffb9b0: 8)
>      at /usr/src/debug/cygwin-3.0.1-1/winsup/cygwin/fhandler_timerfd.cc:1=
34
> [...]
>=20
> This suggests to me that the slowdown comes from timerfd_tracker::wait.
>=20
> The context is that emacs creates a timerfd timer that expires every 2 se=
conds,=20
> 'select' waits for the timer's file descriptor to be ready for reading, a=
nd then=20
> 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 =3D 1;
  int secs, nsecs;

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

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

  secs =3D curr.tv_sec - start.tv_sec;
  nsecs =3D curr.tv_nsec - start.tv_nsec;
  if (nsecs < 0)
    {
      secs--;
      nsecs +=3D 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 !=3D 2) && (argc !=3D 4) && argc !=3D 5)
    {
      fprintf (stderr, "%s init-secs [interval-secs max-exp]\n", argv[0]);
      exit (EXIT_FAILURE);
    }

  if (clock_gettime (CLOCK_MONOTONIC, &now) =3D=3D -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 =3D atoi (argv[1]) + now.tv_sec;
  new_value.it_value.tv_nsec =3D now.tv_nsec;
  if (argc =3D=3D 2)
    {
      new_value.it_interval.tv_sec =3D 0;
      max_exp =3D 1;
    }
  else
    {
      new_value.it_interval.tv_sec =3D atoi (argv[2]);
      max_exp =3D atoi (argv[3]);
    }
  new_value.it_interval.tv_nsec =3D 0;

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

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

  if (timerfd_settime (fd, TFD_TIMER_ABSTIME, &new_value, NULL) =3D=3D -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 =3D 0, tot_exp =3D 0; tot_exp < max_exp; ++i)
    {
#if 1
      int ret;
      FD_ZERO (&fds);
      FD_SET (fd, &fds);
      ret =3D select (fd + 1, &fds, NULL, NULL, NULL);
      if (ret < 0)
	perror ("select");
      if (!FD_ISSET (fd, &fds))
	continue;

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

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

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

--=20
Corinna Vinschen
Cygwin Maintainer

--UKsZWh/ZtaJX4ozz
Content-Type: application/pgp-signature; name="signature.asc"

-----BEGIN PGP SIGNATURE-----

iQIzBAEBCAAdFiEEoVYPmneWZnwT6kwF9TYGna5ET6AFAlxxm94ACgkQ9TYGna5E
T6AGdA/9FDofPFulCDu2vN56qi1iQmmW5MiZNRL42mBTJxNAQp5EKktYxOSQ60iZ
VL+yeXKmEmQx1nFKml8IdYMij3i2up/twcubRHsMAtIqGaGUlJYhoXmII6SB9A0/
sDl9ZkGK6EwKPTL+WRW1jaB3baC5J2WfFF87jx+6yVr0+NvpS7Zf27Qqg0Sa948U
pwQ9VfH5SQOqiN9MBHbnCHwmw7OH9tnQUmTGGr/iXC+6iKIpLIybjr1IDf4zeRdh
ftD0lopHFT7QqZ/VqFxe940Tl6nkKX1t17gxcDiG3SAuPOF+cufw58XNl2OKf2ty
2AWuCgTWIMWYWbVhkDjiHbuQd5z4/sJY1dj8uVHlCwW1g+hI17Hci6Uyju1R55j8
6UQULYEUeB0HlNdOtJdgiZHqTGqsICaBqK7q/p+pPtbF5q1ArcY6Rd7htnjdWdBz
ohBJisepTkRKXTNS2EkscSnyZBQ/j+dbzgP767ZgWpRkAnlz+Lbl2z6f3MLObP2n
hVhtUBhd4+/U1HpcKaAVOft/bPnzFSYewjN0jvErYyRxHoxUrijuLEjXvpXgeJgg
/i70Afci2dcTqagBN44TrDQckrSRI7+zMJWr3jx/2dmAUgyZBQZl3dP5Fk8+OKrM
RsNI70xvxSCbbdjOu4EDWAqI13dGxRzFW93FTya9GUeCc6GBTRQ=
=sbN3
-----END PGP SIGNATURE-----

--UKsZWh/ZtaJX4ozz--