Poor upload performance in Windows

[jay]

User Jeffrey McKay has reported on the curl-library mailing list that after upgrading to 7.73.0 the upload performance decreased drastically. What was typically a 10 second upload took over 5 minutes.

(Click to expand his report) In summary, he describes it as "large chunks of data seem to be taking 1 second to upload".

I maintain a Windows application (written in VC 2017) that basically
uploads thousands of email messages into Microsoft Exchange/Ofice 365,
via their EWS protocol. I have been successfully using libcurl 7.64 for
a while.

Recently we did have some problem with logging in to some servers, and I
determined that the issue could be fixed by updating to libcurl 7.71
(not sure why). However I ran into some other problem with this version,
where for some reason after several thousand messages, libcurl seemed to
be returning null data in response to a GET. However I am *not* asking
about that problem in this message.

The above problem went away when I switched to libcurl 7.73. However,
this version has its own problem, a serious performance issue, where
large chunks of data seem to be taking 1 second to upload, vs a fraction
of a second seen with the previous version.

Take a look at the attached two log files, slow_upload.txt and
fast_upload.txt. These are logs of the debug function after I do a POST.
In the slow version, each 64k chunk of data is taking approximately 1
second. In the fast version, each chunk is a fraction of a second or not
even measurable. These results are consistent when doing multiple tests
at different times of the day. I don't think it is related to EWS server
variability.

Keep in mind that the exact same main program binary executable code is
running in each test, only the libcurl.dll has been changed.

Any idea what could be causing this? I've also included some of my code
that performs the POST operation (cleaned up of a lot of extraneous
stuff). Hopefully there is some curl option that I can set or change
that fixes this.

I am able to reproduce in Windows and bisected it to d2a7d7c with the PostUpload example.

17f58c8 (parent of d2a7d7c)
Transfer rate: 4103 KB/sec (52429310 bytes in 12 seconds)
Transfer rate: 4121 KB/sec (52429310 bytes in 12 seconds)
Transfer rate: 4067 KB/sec (52429310 bytes in 13 seconds)
Transfer rate: 4078 KB/sec (52429310 bytes in 13 seconds)
Transfer rate: 4074 KB/sec (52429310 bytes in 13 seconds)
Transfer rate: 4100 KB/sec (52429310 bytes in 12 seconds)

d2a7d7c ("multi: implement wait using winsock events")
Transfer rate: 503 KB/sec (52429310 bytes in 102 seconds)
Transfer rate: 503 KB/sec (52429310 bytes in 102 seconds)
Transfer rate: 971 KB/sec (52429310 bytes in 53 seconds)
Transfer rate: 503 KB/sec (52429310 bytes in 102 seconds)
Transfer rate: 507 KB/sec (52429310 bytes in 101 seconds)
Transfer rate: 503 KB/sec (52429310 bytes in 102 seconds)

curl 7.73.0-DEV (i386-pc-win32) libcurl/7.73.1-DEV OpenSSL/1.0.2t nghttp2/1.40.0

The 1 second delay is coming from this call to WSAWaitForMultipleEvents in multi_wait:

curl/lib/multi.c

Lines 1278 to 1282 in 315ee3f

	#ifdef USE_WINSOCK
	WSAWaitForMultipleEvents(1, &multi->wsa_event, FALSE, timeout_ms, FALSE);
	#else
	int pollrc = Curl_poll(ufds, nfds, timeout_ms);
	#endif

Debug code:

diff --git a/lib/multi.c b/lib/multi.c
index c8bba47..d71a573 100644
--- a/lib/multi.c
+++ b/lib/multi.c
@@ -1275,7 +1275,17 @@ static CURLMcode Curl_multi_wait(struct Curl_multi *multi,
 #ifdef USE_WINSOCK
     if(already_writable > 0)
       timeout_ms = 0;
-    WSAWaitForMultipleEvents(1, &multi->wsa_event, FALSE, timeout_ms, FALSE);
+    {
+      DWORD ret;
+      struct curltime before, after;
+      before = Curl_now();
+      ret = WSAWaitForMultipleEvents(1, &multi->wsa_event, FALSE, timeout_ms,
+                                     FALSE);
+      after = Curl_now();
+      fprintf(stderr,
+        "WSAWaitForMultipleEvents timeout_ms: %d, ret: %d, elapsed: %I64d\n",
+        timeout_ms, ret, Curl_timediff(after, before));
+    }
 #else
     int pollrc = Curl_poll(ufds, nfds, timeout_ms);
 #endif

Debug output (ret 258 is WSA_WAIT_TIMEOUT):

WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 1000, ret: 0, elapsed: 2
WSAWaitForMultipleEvents timeout_ms: 1000, ret: 258, elapsed: 1000
  4% uploaded...WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 1000, ret: 0, elapsed: 2
WSAWaitForMultipleEvents timeout_ms: 1000, ret: 258, elapsed: 1000
  6% uploaded...WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0
WSAWaitForMultipleEvents timeout_ms: 1000, ret: 0, elapsed: 4
WSAWaitForMultipleEvents timeout_ms: 1000, ret: 258, elapsed: 1000
  8% uploaded...WSAWaitForMultipleEvents timeout_ms: 0, ret: 258, elapsed: 0

If that WSAWaitForMultipleEvents line is commented out then the transfer completes in the expected time (but then of course eats CPU in the interim since there's no poll wait).

According to the commit message in d2a7d7c, a previous version of that commit patch would erroneously wait the full timeout for the socket to become writable. It looks like that issue may not be fully fixed?

Ref: #5397
Ref: #5631
Ref: #5634

/cc @rcombs @mback2k @MarcelRaad @Togtja @ngg @rmja

[gvanem]

Trying Jay's PostUpload example I noted there were 3202 calls to:

WSAIoctl(sockfd, SIO_IDEAL_SEND_BACKLOG_QUERY ...);
setsockopt (784, SOL_SOCKET, SO_SNDBUF, ...);

The Ideal Send Backlog value started at 64kB, a few at 130kB and the remaining at 256 kB. Simply disabling the win_update_buffer_size() call, the transfer speed increased a bit. Somewhat related?

But I got around 9.3 MBit/s which IMHO is very good speed. In Google Chrome it reports 10.2 MBit/s blank to the same Frankfurt, DE server at https://testmy.net/upload. Using a 50 MByte test file for each test.

[jay]

The Ideal Send Backlog value started at 64kB, a few at 130kB and the remaining at 256 kB. Simply disabling the win_update_buffer_size() call, the transfer speed increased a bit. Somewhat related?

I see the opposite, performance suffers without it.

17f58c8 (parent of d2a7d7c) with win_update_buffer_size (build default)
Transfer rate: 3886 KB/sec (52429310 bytes in 13 seconds)
Transfer rate: 3182 KB/sec (52429310 bytes in 16 seconds)
Transfer rate: 4103 KB/sec (52429310 bytes in 12 seconds)

17f58c8 (parent of d2a7d7c) without win_update_buffer_size
Transfer rate: 1871 KB/sec (52429310 bytes in 27 seconds)
Transfer rate: 1934 KB/sec (52429310 bytes in 26 seconds)
Transfer rate: 1908 KB/sec (52429310 bytes in 27 seconds)

d2a7d7c with win_update_buffer_size (build default)
Transfer rate: 197 KB/sec (52429310 bytes in 260 seconds)
Transfer rate: 502 KB/sec (52429310 bytes in 102 seconds)
Transfer rate: 255 KB/sec (52429310 bytes in 201 seconds)

d2a7d7c without win_update_buffer_size
Transfer rate: 63 KB/sec (52429310 bytes in 815 seconds)
Transfer rate: 63 KB/sec (52429310 bytes in 813 seconds)
Transfer rate: 63 KB/sec (52429310 bytes in 816 seconds)

curl 7.73.0-DEV (i386-pc-win32) libcurl/7.73.1-DEV OpenSSL/1.0.2t nghttp2/1.40.0

Edit: When I run the 50MB test via the browser I get mbps results similar to what I get from 17f58c8, which is expected.

[mback2k]

If the 1 second delay comes from the timeout, the main question should be: why does it run into that timeout?

[mback2k]

@jay would you mind performing the same tests for the follow up commits to multi.c which should actually have already improved the situation?

1. 3334ee6
2. 003e81e
3. 1060955

Especially the code section regarding already_writable was replaced after the commits you identified.

[jay]

All of them are slow. I think we should work from master for further testing.

If the 1 second delay comes from the timeout, the main question should be: why does it run into that timeout?

That is the question alright and I don't know the answer. I assume the event is supposed to be signaled at that point since there is data, which would mean no wait. One strange thing I've noticed is in some of the results the speed is sometimes doubled or halved. For example, usually 100 seconds but sometimes 50 or 200.

• 3334ee6

Transfer rate: 489 KB/sec (52429310 bytes in 105 seconds)
Transfer rate: 503 KB/sec (52429310 bytes in 102 seconds)
Transfer rate: 503 KB/sec (52429310 bytes in 102 seconds)

• 003e81e

Transfer rate: 255 KB/sec (52429310 bytes in 201 seconds)
Transfer rate: 503 KB/sec (52429310 bytes in 102 seconds)
Transfer rate: 968 KB/sec (52429310 bytes in 53 seconds)

• 1060955

Transfer rate: 255 KB/sec (52429310 bytes in 201 seconds)
Transfer rate: 503 KB/sec (52429310 bytes in 102 seconds)
Transfer rate: 503 KB/sec (52429310 bytes in 102 seconds)

5c8849c (master 2020-11-22)

Transfer rate: 497 KB/sec (52429310 bytes in 103 seconds)
Transfer rate: 503 KB/sec (52429310 bytes in 102 seconds)
Transfer rate: 968 KB/sec (52429310 bytes in 53 seconds)

[mback2k]

I had one idea for an alternative implementation of this waiting in multi.c for Windows which could potentially improve the situation again, but avoid the fake socket pairs being created:

1. revert back to using Curl_poll also on Windows, but just use it for polling with no timeout and exclude the wakeup socket here.
2. check if any of the sockets in Curl_poll are already ready and skip the next part if that is the case.
3. if nothing is ready yet, use the new implementation to wait on the sockets including the new wakeup event.

This way we should be able to reduce again the overall number of syscalls, by doing one Curl_poll as readiness pre-check with the old logic and then just perform the waiting with the new logic including the new wakeup event instead of the old wakeup socket pair. This could potentially also reduce the number of ifdef's in the code again.

[bagder]

How does that reduce the number of syscalls? It'd either be poll or objectwait, right?

More importantly: that logic doesn't work if there's a timeout:

In state (1) it only waits for socket and let's say we have a 1000ms timeout. During this period the wakeup event isn't checked and thus doesn't work. We delay the wakeup with this time.

[mback2k]

As I said, step 1 (" with no timeout") wouldn't use a timeout, it would just poll with a timeout of 0 as a pre-check. At the moment a pre-check is done with Curl_socket_check per socket in the wait setup loop, but we could also just use the final poll structure (which is currently disabled for Windows) to do the pre-check without caring for the wakeup socket/event. The wakeup event would only be checked in case of actually waiting. To summarize:

1. poll with timeout 0 as pre-check on sockets
2. if nothing ready yet: objectwait with timeout on sockets and wakeup event

[bagder]

We're only 6 days from release now. Can we revert this regression and work on a proper fix long-term? The only PR is still draft...