Re: cygrunsrv + sshd + rsync = 20 times too slow -- throttled?

[Takashi Yano <takashi.yano@nifty.ne.jp>]

[-- Attachment #1: Type: text/plain, Size: 8082 bytes --]

On Thu, 26 Aug 2021 18:18:29 -0400
Ken Brown wrote:
> On 8/26/2021 11:56 AM, Ken Brown via Cygwin wrote:
> > On 8/25/2021 5:29 PM, Takashi Yano wrote:
> >> On Wed, 25 Aug 2021 13:52:19 -0400
> >> Ken Brown wrote:
> >>> On 8/25/2021 7:18 AM, Takashi Yano via Cygwin wrote:
> >>>> On Tue, 24 Aug 2021 12:49:52 -0700
> >>>> Chris Roehrig wrote:
> >>>>> I have a network of Windows, Linux and Mac machines and I use rsync to 
> >>>>> synchronize various directories between them.
> >>>>>
> >>>>> I'm trying to figure out why my rsync transfers are so slow (<4 MB/s) only 
> >>>>> when the remote endpoint is Cygwin rsync over sshd (with both a Linux or 
> >>>>> Cygwin rsync client).   In all other scenarios, I get the full 100MB/s as 
> >>>>> expected from gigabit ethernet.  This has been an ongoing problem for me 
> >>>>> for a couple of years over several Windows and Cygwin versions, and I'd 
> >>>>> like to try to fix it.
> >>>>>
> >>>>> If I run rsync --daemon --no-detach under mintty in the foreground on the 
> >>>>> remote Windows endpoint,  I get the full 100 MB/s transfers, so it seems 
> >>>>> like it has something to do with rsync.exe running in the background under 
> >>>>> the cygrunsrv+sshd service (which was installed normally using 
> >>>>> ssh-host-config).
> >>>>>
> >>>>> If I do:
> >>>>>     pv /dev/zero | ssh $WINHOST "cat > /dev/null"
> >>>>> or even
> >>>>>     pv /dev/urandom | ssh $WINHOST md5sum
> >>>>> I also get the full 100 MB/s transfers, so it doesn't look like sshd itself 
> >>>>> is being throttled by bandwidth or CPU.
> >>>>>
> >>>>> The machines have less than 15% CPU utilization while transferring, with 
> >>>>> each of the 4 cores less than 30%, so it doesn't look to be CPU issue.
> >>>>> In Task Manager, sshd.exe and rsync.exe seem to be running normally using 
> >>>>> only few percent CPU, and show Power Throttling=Disabled, 
> >>>>> Priority=Normal.   Setting their Priority to High doesn't seem to change 
> >>>>> things.
> >>>>>
> >>>>> Looking in Resource Monitor on the remote endpoint, the network usage is 
> >>>>> pretty much a flat horizontal line at about 18 Mbps (2.5 MB/s), so it sure 
> >>>>> looks to me as if rsync is somehow being bandwidth-throttled\b when run in 
> >>>>> the background under cygsshd.
> >>>>>
> >>>>> It's almost as if rsync has an implicit --bwlimit override when it is run 
> >>>>> from cygrunsrv+sshd (I've tried --bwlimit=0 on the client which makes no 
> >>>>> difference).
> >>>>>
> >>>>>
> >>>>> Any ideas?    Not sure where to go from here.
> >>>>
> >>>> In cygwin, just scp is very slow.
> >>>>
> >>>> The transfer speed in my environment is as follows.
> >>>> The tests were done with 100MB of test.dat file.
> >>>>
> >>>> (1-1) From cygwin-PC,
> >>>> [yano@cygwin-PC ~]$ scp test.dat yano@linux-server:.
> >>>> yano@linux-server's password:
> >>>> test.dat                                      100%  100MB   4.0MB/s   00:24
> >>>> [yano@cygwin-PC ~]$ scp yano@linux-server:test.dat .
> >>>> yano@linux-server's password:
> >>>> test.dat                                      100%  100MB   8.0MB/s   00:12
> >>>>
> >>>> (1-2) From linux-server,
> >>>> yano@linux-server:~$ scp yano@cygwin-PC:test.dat .
> >>>> yano@cygwin-PC's password:
> >>>> test.dat                                      100%  100MB   4.0MB/s   00:24
> >>>> yano@linux-server:~$ scp test.dat yano@cygwin-PC:.
> >>>> yano@cygwin-PC's password:
> >>>> test.dat                                      100%  100MB   4.1MB/s   00:24
> >>>>
> >>>>
> >>>> I looked into this problem, and noticed that this is caused
> >>>> by cygwin pipe implementation. Pipe in cygwin is configured
> >>>> with FILE_FLAG_OVERLAPPED.
> >>>>
> >>>> If the pipe is configured without FILE_FLAG_OVERLAPPED,
> >>>> the transfer speed is much improved as follows.
> >>>>
> >>>>
> >>>> (2-1) From cygwin-PC,
> >>>> [yano@cygwin-PC ~]$ scp test.dat yano@linux-server:.
> >>>> yano@linux-server's password:
> >>>> test.dat                                      100%  100MB  85.5MB/s   00:01
> >>>> [yano@cygwin-PC ~]$ scp yano@linux-server:test.dat .
> >>>> yano@linux-server's password:
> >>>> test.dat                                      100%  100MB  69.7MB/s   00:01
> >>>>
> >>>> (2-2) From linux-server,
> >>>> yano@linux-server:~$ scp yano@cygwin-PC:test.dat .
> >>>> yano@cygwin-PC's password:
> >>>> test.dat                                      100%  100MB  80.1MB/s   00:01
> >>>> yano@linux-server:~$ scp test.dat yano@cygwin-PC:.
> >>>> yano@cygwin-PC's password:
> >>>> test.dat                                      100%  100MB  57.7MB/s   00:01
> >>>>
> >>>> I am not sure why this happens and how to fix this.
> >>>
> >>> A couple years ago I had an idea for changing the pipe implementation to avoid
> >>> overlapped I/O:
> >>>
> >>>     https://cygwin.com/pipermail/cygwin-patches/2019q2/009393.html
> >>>     https://cygwin.com/pipermail/cygwin-patches/2019q2/009423.html
> >>>
> >>> I never followed up on it.  But if you think it might help with this problem, I
> >>> could dust it off and try to finish it.
> >>
> >> Interesting.
> >>
> >> It will be also helpfull for:
> >> https://cygwin.com/pipermail/cygwin/2021-March/247987.html
> >> which seems to be the same issue with
> >> https://stackoverflow.com/questions/10385424/good-alternatives-to-cygwin-cygwin-doesnt-support-natively-support-win32-app 
> >>
> >>
> >> However, I wonder why scp dislikes overlapped I/O.
> > 
> > I agree that it would be good to understand this.  When I first proposed the 
> > change, I was thinking in terms of code simplification.  If it also improves 
> > performance (which we don't know yet), it becomes a higher priority, but in that 
> > case it would be nice to understand why it improves performance.
> 
> Hi Takashi,
> 
> In case you want to try out my proposed change, I've just rebased the patches to 
> the current master and pushed them to a new topic/pipe branch.

Hi Ken,

Thanks much! I tested topic/pipe branch.

[yano@cygwin-PC ~]$ scp test.dat yano@linux-server:.
yano@linux-server's password:
test.dat                                      100%  100MB  95.9MB/s   00:01
[yano@cygwin-PC ~]$ scp yano@linux-server:test.dat .
yano@linux-server's password:
test.dat                                      100%  100MB   8.0MB/s   00:12

yano@linux-server:~$ scp yano@cygwin-PC:test.dat .
yano@cygwin-PC's password:
test.dat                                      100%  100MB 109.7MB/s   00:00
yano@linux-server:~$ scp test.dat yano@cygwin-PC:.
yano@cygwin-PC's password:
test.dat                                      100%  100MB  31.4MB/s   00:03

As shown above, outgoing transfer-rate has been improved upto near
theoretical limit. However, incoming transfer-rate is not improved
much.

I digged further and found the first patch attached solves the issue
as follows.

[yano@cygwin-PC ~]$ scp yano@linux-server:test.dat .
yano@linux-server's password:
test.dat                                      100%  100MB 112.8MB/s   00:00

yano@linux-server2:~$ scp test.dat yano@cygwin-PC:.
yano@cygwin-PC's password:
test.dat                                      100%  100MB 102.5MB/s   00:00


I also tested the case:
> >> https://cygwin.com/pipermail/cygwin/2021-March/247987.html
> >> which seems to be the same issue with
> >> https://stackoverflow.com/questions/10385424/good-alternatives-to-cygwin-cygwin-doesnt-support-natively-support-win32-app

Unfortunately, topic/pipe does not help.

I confirmed that applying the second patch attached, which reverts
to create() rather than nt_create(), and setting CYGWIN=pipe_byte
fixes the problem.

What do you think of this alternative implementation which does
not use nt_create()?

-- 
Takashi Yano <takashi.yano@nifty.ne.jp>

[-- Attachment #2: 0001-Cygwin-select-Improve-select-poll-response.patch --]
[-- Type: application/octet-stream, Size: 2460 bytes --]

From c2ececea731fb633a9e10666d7546e1c61c8c4f7 Mon Sep 17 00:00:00 2001
From: Takashi Yano <takashi.yano@nifty.ne.jp>
Date: Fri, 27 Aug 2021 19:54:41 +0900
Subject: [PATCH 1/2] Cygwin: select: Improve select/poll response.

---
 winsup/cygwin/select.cc | 32 ++++++++++++++++++++++++++++----
 1 file changed, 28 insertions(+), 4 deletions(-)

diff --git a/winsup/cygwin/select.cc b/winsup/cygwin/select.cc
index 8ad982c12..83e1c00e0 100644
--- a/winsup/cygwin/select.cc
+++ b/winsup/cygwin/select.cc
@@ -735,6 +735,7 @@ thread_pipe (void *arg)
   select_pipe_info *pi = (select_pipe_info *) arg;
   DWORD sleep_time = 0;
   bool looping = true;
+  DWORD t0 = GetTickCount ();
 
   while (looping)
     {
@@ -754,7 +755,12 @@ thread_pipe (void *arg)
 	break;
       cygwait (pi->bye, sleep_time >> 3);
       if (sleep_time < 80)
-	++sleep_time;
+	{
+	  DWORD t1 = GetTickCount ();
+	  if (t0 != t1)
+	    ++sleep_time;
+	  t0 = t1;
+	}
       if (pi->stop_thread)
 	break;
     }
@@ -930,6 +936,7 @@ thread_fifo (void *arg)
   select_fifo_info *pi = (select_fifo_info *) arg;
   DWORD sleep_time = 0;
   bool looping = true;
+  DWORD t0 = GetTickCount ();
 
   while (looping)
     {
@@ -949,7 +956,12 @@ thread_fifo (void *arg)
 	break;
       cygwait (pi->bye, sleep_time >> 3);
       if (sleep_time < 80)
-	++sleep_time;
+	{
+	  DWORD t1 = GetTickCount ();
+	  if (t0 != t1)
+	    ++sleep_time;
+	  t0 = t1;
+	}
       if (pi->stop_thread)
 	break;
     }
@@ -1125,6 +1137,7 @@ thread_console (void *arg)
   select_console_info *ci = (select_console_info *) arg;
   DWORD sleep_time = 0;
   bool looping = true;
+  DWORD t0 = GetTickCount ();
 
   while (looping)
     {
@@ -1144,7 +1157,12 @@ thread_console (void *arg)
 	break;
       cygwait (ci->bye, sleep_time >> 3);
       if (sleep_time < 80)
-	++sleep_time;
+	{
+	  DWORD t1 = GetTickCount ();
+	  if (t0 != t1)
+	    ++sleep_time;
+	  t0 = t1;
+	}
       if (ci->stop_thread)
 	break;
     }
@@ -1364,6 +1382,7 @@ thread_pty_slave (void *arg)
   select_pipe_info *pi = (select_pipe_info *) arg;
   DWORD sleep_time = 0;
   bool looping = true;
+  DWORD t0 = GetTickCount ();
 
   while (looping)
     {
@@ -1383,7 +1402,12 @@ thread_pty_slave (void *arg)
 	break;
       cygwait (pi->bye, sleep_time >> 3);
       if (sleep_time < 80)
-	++sleep_time;
+	{
+	  DWORD t1 = GetTickCount ();
+	  if (t0 != t1)
+	    ++sleep_time;
+	  t0 = t1;
+	}
       if (pi->stop_thread)
 	break;
     }
-- 
2.33.0


[-- Attachment #3: 0002-Cygwin-pipe-Revert-to-create-rather-than-nt_create.patch --]
[-- Type: application/octet-stream, Size: 2368 bytes --]

From 784892dc272a6b7899de5f89c65bb8cfab79591d Mon Sep 17 00:00:00 2001
From: Takashi Yano <takashi.yano@nifty.ne.jp>
Date: Fri, 27 Aug 2021 20:06:04 +0900
Subject: [PATCH 2/2] Cygwin: pipe: Revert to create() rather than nt_create().

---
 winsup/cygwin/fhandler_pipe.cc | 24 +++++++++++++++++++++++-
 1 file changed, 23 insertions(+), 1 deletion(-)

diff --git a/winsup/cygwin/fhandler_pipe.cc b/winsup/cygwin/fhandler_pipe.cc
index 2dec0a848..b3af4a0a0 100644
--- a/winsup/cygwin/fhandler_pipe.cc
+++ b/winsup/cygwin/fhandler_pipe.cc
@@ -234,6 +234,24 @@ fhandler_pipe::raw_read (void *ptr, size_t& len)
       return;
     }
 
+  if (is_nonblocking ())
+    {
+      DWORD n;
+      BOOL ret = PeekNamedPipe (get_handle (), NULL, 0, NULL, &n, NULL);
+      if (!ret)
+	{
+	  __seterrno ();
+	  len = (size_t) -1;
+	  return;
+	}
+      if (n == 0)
+	{
+	  set_errno (EAGAIN);
+	  len = (size_t) -1;
+	  return;
+	}
+    }
+
   do
     {
       len = orig_len;
@@ -571,6 +589,7 @@ fhandler_pipe::create (LPSECURITY_ATTRIBUTES sa_ptr, PHANDLE r, PHANDLE w,
   return 0;
 }
 
+#if 0
 /* The next version of fhandler_pipe::create used to call the previous
    version.  But the read handle created by the latter doesn't have
    FILE_WRITE_ATTRIBUTES access unless the pipe is created with
@@ -588,6 +607,7 @@ fhandler_pipe::create (LPSECURITY_ATTRIBUTES sa_ptr, PHANDLE r, PHANDLE w,
 
 static int nt_create (LPSECURITY_ATTRIBUTES, PHANDLE, PHANDLE, DWORD,
 		      int64_t *);
+#endif
 
 int
 fhandler_pipe::create (fhandler_pipe *fhs[2], unsigned psize, int mode)
@@ -597,7 +617,7 @@ fhandler_pipe::create (fhandler_pipe *fhs[2], unsigned psize, int mode)
   int res = -1;
   int64_t unique_id;
 
-  int ret = nt_create (sa, &r, &w, psize, &unique_id);
+  int ret = create (sa, &r, &w, psize, NULL, 0, &unique_id);
   if (ret)
     __seterrno_from_win_error (ret);
   else if ((fhs[0] = (fhandler_pipe *) build_fh_dev (*piper_dev)) == NULL)
@@ -624,6 +644,7 @@ fhandler_pipe::create (fhandler_pipe *fhs[2], unsigned psize, int mode)
   return res;
 }
 
+#if 0
 static int
 nt_create (LPSECURITY_ATTRIBUTES sa_ptr, PHANDLE r, PHANDLE w,
 		DWORD psize, int64_t *unique_id)
@@ -755,6 +776,7 @@ nt_create (LPSECURITY_ATTRIBUTES sa_ptr, PHANDLE r, PHANDLE w,
   /* Success. */
   return 0;
 }
+#endif
 
 int
 fhandler_pipe::ioctl (unsigned int cmd, void *p)
-- 
2.33.0