SYSCALLS


before code changes (run 1)

LEGEND:

TESTS:

OBJECTIVE:

To list and analysis the current results, ie prior to patching lmhd source

Debian Linux FreeBSD NetBSD OS X cygwin x64 (under Windows 10)
continuous response generation : (log)
In the strace log it can be observed that on Debian the following pattern occurs: setsockopt, sendto, setsockopt, setsockopt, setsockopt, setsockopt, setsockopt, setsockopt. This switches the client's socket between the following flags: TCP_CORK -> TCP_CORK -> TCP_NODELAY -> TCP_NODELAY -> TCP_CORK -> TCP_CORK -> TCP_NODELAY. After this, the body of the message is sent. This again is followed after the last message ("\r\n") by 2 setsockopt() calls with the first having the flag TCP_CORK, the second the flag TCP_NODELAY.
continuous response generation : (log)
The log of truss under FreeBSD shows a comparable pattern: setsockopt is called 3 times.
continuous response generation : (log)
The log of ktruss under NetBSD shows that again we have 2 calls to setsockopt after application start.
continuous response generation :
No data.
continuous response generation : (log)
The log of cygwin shows 1 call of main to setsockopt in the beginning (111 279601 [main] a 268 cygwin_setsockopt: 0 = setsockopt(5, 65535, 0x4, 0xFFFFCA10, 4)). After this, MHD-single calls setsockopt 2 times (setsockopt, followed by cygwin_send, followed by another setsockopt call). The pattern in cygwin is comparable to the ktruss log in NetBSD, where we see a setsockopt, sendto, setsockopt at the beginning of the log.
tiny response generation (log): After receiving the GET request, we see 1 setsockopt call (TCP_CORK). The header is send. This is followed by 6 setsockopt calls: TCP_CORK, TCP_NODELAY, TCP_NODELAY, TCP_CORK, TCP_CORK, TCP_NODELAY. The body is send. Then we see 2 final setsockopt calls: TCP_CORK, TCP_NODELAY. tiny response generation (log): There are 2 setsockopt calls. The first sets TCP_NODELAY. It is followed directly by the header being send. The second setsockopt call sets TCP_NODELAY. tiny response generation (log): After receiving the GET request, we see 1 call to setsockopt, followed by sending the header. The header is immediately followed by 2 calls to setsockopt, then the body is send ("b"), immediately follows a call to setsockopt. tiny response generation:
no data
tiny response generation (log): We see 1 call to setsockopt. This is followed by a send of the size 99 (the header). Then follows another setsockopt, followed by another call to send (the body).
modest response generation (log): We see 1 call to setsockopt() after receiving the GET request (TCP_CORK). Then we send the header. We see 6 calls to setsockopt(): TCP_CORK, TCP_NODELAY, TCP_NODELAY, TCP_CORK, TCP_CORK, TCP_NODELAY. Then the body is send, We see 2 more setsockopt() calls: TCP_CORK, TCP_NODELAY. modest response generation (log): After receiving the GET request, we see 1 call to setsockopt() (TCP_NODELAY). Then the header is send. We see 1 call to setsockopt() (TCP_NODELAY). Then the body is send. modest response generation (log): After receiving the GET request, we see 1 setsockopt() call which is followed by sending the header. This is followed by 2 calls to setsockopt(). After this, the body is send, followed by another call to setsockopt(). modest response generation:
no data.
modest response generation (log): We see 2 calls to setsockopt related to the socket we use, each one of them before the respective send() is called.
response generation using sendfile() (log): The test had to be updated for Debian to work, so we are reading a prepared file which exists, contrary to the earlier NetBSD test. After receiving the GET request, we see 1 call to setsockopt (TCP_CORK) immediately before the header is send. Then we see 6 calls to setsockopt: TCP_CORK, TCP_NODELAY, TCP_NODELAY, TCP_CORK, TCP_CORK, TCP_NODELAY. sendfile is called. setsockopt is called to set TCP_NODELAY. the filedescriptor is closed. setsockopt is called with TCP_NODELAY. response generation using sendfile() (log): We see 2 calls to setsockopt. One TCP_NODELAY afer receiving the GET request. One TCP_NODELAY after sending the header. The last one is followed by the body being send. response generation using sendfile() (log): After receiving the GET request, the file with the content "a" is created. We see 1 call to setsockopt just before the header is send. Immediatelly after we see another setsockopt call. The file is read, then we see another setsockopt call followed by a sendto of "a". response generation using sendfile():
no data.
response generation using sendfile() (log): We see 1 call to setsockopt(), followed by a send() with size 99 (the header). This is followed by 1 call to setsockopt(), and one more call to send() with size 1 (the body).
other other other other other

after code changes (run 2)

POST-ANALYSIS, run 1

After working through the setsockopt optimization and refactoring, the following results were found. This is on libmicrohttpd commit afe3f5aef4ec0b48b2c7e05f77dba8f8fbfe4243 and 9e8418b943c417b50b0e7ecac868cde3933aba5e. The difference between the commits is removal of commented code, acceptable with no impact on the test results. The results indicate errors with the code, a second analysis has to be done after bug fixes.

Debian Linux FreeBSD NetBSD OS X cygwin x64 (under Windows 10)
continuous response generation: (log)
0 calls to setsockopt.
continuous response generation: (log)
1 setsockopt() TCP_NODELAY before first sendto() (header). 1 setsockopt() TCP_NODELAY after first sendto() (header). 1 setsockopt() TCP_NODELAY before last sendto().
continuous response generation: (log)
1 setsockopt() before first sendto() (header). 1 setsockopt() after first sendto() (header). 1 setsockopt() before last sendto().
continuous response generation:
No data.
continuous response generation: (log)
There appears to be 1 call to setsockopt before a send, 1 after it, and 1 at the end.
tiny response generation (log): 0 calls to setsockopt. tiny response generation (log):
1 setsockopt() TCP_NODELAY before first sendto() (header). 1 setsockopt() TCP_NODELAY after first sendto() (header).
tiny response generation (log):
1 setsockopt() before first sendto() (header). 1 setsockopt() after first sendto() (header).
tiny response generation:
no data
tiny response generation (log):
1 setsockopt() before send, 1 after it.
modest response generation (log):
0 calls to setsockopt.
modest response generation (log):
1 setsockopt() TCP_NODELAY before first sendto() (header). 1 setsockopt() TCP_NODELAY after first sendto() (header).
modest response generation (log):
1 setsockopt() before first sendto() (header). 1 setsockopt() after first sendto() (header).
modest response generation:
no data.
modest response generation (log):
1 setsockopt() before send, 1 after it.
response generation using sendfile() (log):
0 calls to setsockopt.
response generation using sendfile() (log):
1 setsockopt() TCP_NODELAY before first sendto() (header). 1 setsockopt() TCP_NODELAY after first sendto() (header).
response generation using sendfile() (log):
1 setsockopt() before first sendto() (header). 1 setsockopt() second after first sendto().
response generation using sendfile():
no data.
response generation using sendfile() (log):
1 setsockopt call before send(), 1 setsockopt before last send().
other other other other other

Appended Notes

In this itteration the usage of TCP_NOPUSH could still be wrong in the pre and post functions. Before send/sendto/.../ it is ON, after send/sendto/.../ it is OFF. No result changes in cygwin. Debian now uses MSG_MORE, however a real fix to its usage was introduced later and a new analysis is due.

Other observations

The standard testsuite on NetBSD now runs without major delays in some of the ...11 tests. In the releases up to now this wasn't the case.


after code changes (run 3)

POST-ANALYSIS, run 2

Tested on commit 9edfc8f8f7a548e0dad8f3d18f671b822601a384 of dev/ng0/gsoc2019 branch. Excluded this time cygwin. Main fixes since the last test commit:

In summary: MSG_MORE flag works as intended (no setsockopt) on Linux. sendmsg is tested, writev needs an explicit test but should work. GnuTLS started to throw errors in the main test suite. sendfile wrapper appears to be working. More details in a brief summary in the table. Open question: Are we getting back more characters than before in some of the character based tests?

Debian Linux FreeBSD NetBSD OS X cygwin x64 (under Windows 10)
continuous response generation: (log)
No calls to setsockopt, MSG_MORE flag is seen in the first and last sendto call.
continuous response generation: (log)
TCP_NODELAY in first setsockopt call, sendto. same on second setsockopt call, followed by sendto. A last setsockopt call with TCP_NODELAY before the last sendto call.
continuous response generation: (log)
setsockopt, sendto (header). setsockopt, sendto. A final setsockopt before the very last sendto call.
continuous response generation:
continuous response generation: (log)
tiny response generation (log):
I am not too familiar with the expected reading of sendmsg in combination with the Linux specific EPOLL, the output indicates that it could be correct. We see a change (EPIPE, ENOTCONN) on the server side compared to the previously runs (they were still using send). No calls to setsockopt.
tiny response generation (log):
setsockopt TCP_NODELAY, sendmsg (header), poll. setsockopt TCP_NODELAY, sendmsg (body). broken pipe, shutdown socket not connected. (see Linux).
tiny response generation (log):
setsockopt, sendmsg (header), poll. setsockopt sendmsg, poll series, closed by the same behavior as seen on the previous 2 platforms (ECONNRESET, EPIPE, EINVAL).
tiny response generation:
tiny response generation (log):
modest response generation (log):
Identical to tiny response generation.
modest response generation (log):
We see a series of setsockopt TCP_NODELAY, sendmsg, poll closing with 2 socket is not connected errors.
modest response generation (log):
setsockopt, sendmsg (header), poll. setsockopt, sendmsg, poll series. Same errors as before (ECONNRESET, EPIPE, EINVAL).
modest response generation:
modest response generation (log):
response generation using sendfile() (log):
sendto, sendfile, close. No setsockopt calls.
response generation using sendfile() (log):
setsockopt TCP_NODELAY, sendto (header). setsockopt TCP_NODELAY, sendfile (body), close. expected, at the end of it (after key press): "socket is not connected" error.
response generation using sendfile() (log):
setsockopt, sendto (header). pread, setsockopt, sendto, close, poll, recvfrom. no errors.
response generation using sendfile():
response generation using sendfile() (log):
other other other other other

Appended Notes

Other observations


POST-ANALYSIS, run 3

Tested on commit 8b1e8793379015ae3ef32e02234467c6e539b448 of dev/ng0/gsoc2019 branch.

Short summary of the results:

Debian Linux FreeBSD NetBSD OS X cygwin x64 (under Windows 10)
continuous response generation: (log)
continuous response generation: (log)
time(1) output shows 6.01 real for the client side action.
continuous response generation: (log)
continuous response generation:
continuous response generation: (log)
tiny response generation (log):
tiny response generation (log):
tiny response generation (log):
tiny response generation:
tiny response generation (log):
modest response generation (log):
modest response generation (log):
modest response generation (log):
modest response generation:
modest response generation (log):
response generation using sendfile() (log):
response generation using sendfile() (log):
response generation using sendfile() (log):
response generation using sendfile():
response generation using sendfile() (log):
other other other other other

Appended Notes

Other observations

Main application Testsuite results and state:


POST-ANALYSIS, run 4

Tested on commit e82de7505f3be8fcee6bd1fc8990893b0a423a40 on the dev/ng0/gsoc2019 branch.

Short summary of the results:

response generation using sendfile():
Debian Linux FreeBSD NetBSD OS X cygwin x64 (under Windows 10)
continuous response generation: (log)
setsockopt(5, SOL_TCP, TCP_NODELAY, [1], 4) = 0
before header is send. sendto() header:
sendto(5, "HTTP/1.1 200 OK\r\nConnection: Kee"..., 108, MSG_NOSIGNAL|MSG_MORE, NULL, 0) = 108
followed by a pattern of
sendto(5, "1\r\nb\r\n", 6, MSG_NOSIGNAL, NULL, 0) = 6
epoll_wait((4, [], 128, 0) = 0
No other setsockopt() calls.
continuous response generation: (log)
setsockopt(4,IPPROTO_TCP,TCP_NODELAY,0x7fffdfffdecc,4) = 0 (0x0)
setsockopt(4,SOL_SOCKET,SO_NOSIGPIPE,0x800249f94,4) = 0 (0x0)

Before header is send:
setsockopt(4,IPPROTO_TCP,TCP_FASTOPEN_MIN_COOKIE_LEN,0x7fffdfffde5c,4) = 0 (0x0)
header:
sendto(4,"HTTP/1.1 200 OK\r\nConnection: K"...,108,MSG_NOSIGNAL,NULL,0) = 108 (0x6c)
followed by a pattern of:
sendto(4,"1\r\nb\r\n",6,MSG_NOSIGNAL,NULL,0) = 6 (0x6)
poll({ 3/POLLIN 4/POLLPRI|POLLOUT|POLLRDBAND },2,-1) = 1 (0x1)
Ends with another setsockopt call:
setsockopt(4,IPPROTO_TCP,TCP_FASTOPEN_MIN_COOKIE_LEN,0x7fffdfffde5c,4) = 0 (0x0)
continuous response generation: (log)
before receiving the GET request:
9366 2 inc setsockopt(0xa, 0xffff, 0x800, 0x7e25e041a1bc, 0x4) = 0
After receiving the GET request:
9366 2 inc setsockopt(0xa, 0x6, 0x1, 0x7e25dcbffec8, 0x4) = 0
9366 2 inc sendto(0xa, 0x7e25e067f800, 0x6c, 0x400, 0, 0) = 108
"HTTP/1.1 200 OK\r\nConnection: Keep-Alive\r\nTransfer-Encoding: chunk"
9366 2 inc sendto(0xa, 0x7e25e067f807, 0x6, 0x400, 0, 0) = 6
"1\r\nb\r\n"
9366 2 inc setsockopt(0xa, 0x6, 0x1, 0x7e25dcbffecc, 0x4) = 0
9366 2 inc poll(0x7e25e067a000, 0x2, 0xffffffff) = 1
9366 2 inc sendto(0xa, 0x7e25e067f807, 0x6, 0x400, 0, 0) = 6
"1\r\nb\r\n"
9366 2 inc poll(0x7e25e067a000, 0x2, 0xffffffff) = 1
9366 2 inc sendto(0xa, 0x7e25e067f807, 0x6, 0x400, 0, 0) = 6
"1\r\nb\r\n"

and so forth. At the end one last setsockopt() call:
9366 2 inc setsockopt(0xa, 0x6, 0x1, 0x7e25dcbffec8, 0x4) = 0
continuous response generation:
continuous response generation: (log)
984 87672678 [MHD-single] inc 1643 __set_winsock_errno: setsockopt:1689 - winsock error 10042 -> errno 109
885 87673563 [MHD-single] inc 1643 cygwin_setsockopt: -1 = setsockopt(6, 6, 0x4, 0xFFDFCB5C, 4), errno 109
1166 87674729 [MHD-single] inc 1643 cygwin_send: 108 = send(6, 0x6000790A0, 108, 0x20)
4218 87678947 [MHD-single] inc 1643 cygwin_send: 6 = send(6, 0x6000790A7, 6, 0x20)
1126 87680073 [MHD-single] inc 1643 __set_errno: void __set_winsock_errno(const char*, int):203 setting errno 109
886 87680959 [MHD-single] inc 1643 __set_winsock_errno: setsockopt:1689 - winsock error 10042 -> errno 109
898 87681857 [MHD-single] inc 1643 cygwin_setsockopt: -1 = setsockopt(6, 6, 0x4, 0xFFDFCB58, 4), errno 109

and at the end:
1265 207154601 [MHD-single] inc 1643 __set_winsock_errno: setsockopt:1689 - winsock error 10042 -> errno 109
1220 207155821 [MHD-single] inc 1643 cygwin_setsockopt: -1 = setsockopt(6, 6, 0x4, 0xFFDFCB5C, 4), errno 109
tiny response generation (log):
setsockopt(5, SOL_TCP, TCP_NODELAY, [1], 4) = 0
before the header is send.
No further setsockopt() calls.
tiny response generation (log):
setsockopt(4,IPPROTO_TCP,TCP_NODELAY,0x7fffdfffdecc,4) = 0 (0x0)
setsockopt(4,SOL_SOCKET,SO_NOSIGPIPE,0x800249f94,4) = 0 (0x0)

before the header is send.
No further setsockopt() calls.
tiny response generation (log):
before GET request:
9118 2 trg setsockopt(0xa, 0xffff, 0x800, 0x7986b2e1a1bc, 0x4) = 0
No other setsockopt() call.
tiny response generation:
tiny response generation (log):
1476 4507184 [MHD-single] trg 1653 fhandler_socket_inet::setsockopt: setsockopt optval=1
1178 4508362 [MHD-single] trg 1653 cygwin_setsockopt: 0 = setsockopt(6, 6, 0x1, 0xFFDFCBFC, 4)
modest response generation (log):
setsockopt(5, SOL_TCP, TCP_NODELAY, [1], 4) = 0
before the header is send.
No further setsockopt calls.
modest response generation (log):
setsockopt(4,IPPROTO_TCP,TCP_NODELAY,0x7fffdfffdecc,4) = 0 (0x0)
setsockopt(4,SOL_SOCKET,SO_NOSIGPIPE,0x800249f94,4) = 0 (0x0)

before the header is send.
No further setsockopt() calls.
modest response generation (log):
before receiving the GET request:
1447 2 mrg setsockopt(0xa, 0xffff, 0x800, 0x7efa1c01a1bc, 0x4) = 0
No other setsockopt() calls.
modest response generation:
modest response generation (log):
1545 2274915 [main] mrg 1649 fhandler_socket_inet::setsockopt: setsockopt optval=1
1990 2276905 [main] mrg 1649 cygwin_setsockopt: 0 = setsockopt(5, 65535, 0x4, 0xFFFFCA10, 4)
1476 6905021 [MHD-single] mrg 1649 fhandler_socket_inet::setsockopt: setsockopt optval=1
1018 6906039 [MHD-single] mrg 1649 cygwin_setsockopt: 0 = setsockopt(6, 6, 0x1, 0xFFDFCBFC, 4)
response generation using sendfile() (log):
setsockopt(5, SOL_TCP, TCP_NODELAY, [1], 4) = 0
before the header is send.
No further setsockopt() calls.
response generation using sendfile() (log):
setsockopt(4,IPPROTO_TCP,TCP_NODELAY,0x7fffdfffdecc,4) = 0 (0x0)
setsockopt(4,SOL_SOCKET,SO_NOSIGPIPE,0x800249f94,4) = 0 (0x0)

before the header is send.
setsockopt(4,IPPROTO_TCP,TCP_FASTOPEN_MIN_COOKIE_LEN,0x7fffdfffde5c,4) = 0 (0x0)
before the HTTP/1.1 200 OK is send.
response generation using sendfile() (log):
before receiving the GET request:
16857 2 response_generat setsockopt(0xa, 0xffff, 0x800, 0x723db1e1a1bc, 0x4) = 0
After receiving the GET request:
setsockopt(0xa, 0x6, 0x1, 0x723dae5ffec8, 0x4) = 0
sendto(0xa, 0x723db21052c0, 0x63, 0x400, 0, 0) = 99
"HTTP/1.1 200 OK\r\nConnection: Keep-Alive\r\nContent-Length: 1\r\nDat"
pread(0xb, 0x723db20fb0a0, 0x1, 0, 0) = 1
"a"
sendto(0xa, 0x723db20fb0a0, 0x1, 0x400, 0, 0) = 1
"a"
setsockopt(0xa, 0x6, 0x1, 0x723dae5ffecc, 0x4) = 0
close(0xb) = 0
response generation using sendfile() (log):
1219 1903187 [main] response_generation_sendfile 1657 fhandler_socket_inet::setsockopt: setsockopt optval=1
1066 1904253 [main] response_generation_sendfile 1657 cygwin_setsockopt: 0 = setsockopt(5, 65535, 0x4, 0xFFFFC9E0, 4)
1322 4700154 [MHD-single] response_generation_sendfile 1657 fhandler_socket_inet::setsockopt: setsockopt optval=1
1090 4701244 [MHD-single] response_generation_sendfile 1657 cygwin_setsockopt: 0 = setsockopt(6, 6, 0x1, 0xFFDFCBFC, 4)

where the more relevant part seems to follow later:
2165 4870751 [MHD-single] response_generation_sendfile 1657 __set_winsock_errno: setsockopt:1689 - winsock error 10042 -> errno 109
1750 4872501 [MHD-single] response_generation_sendfile 1657 cygwin_setsockopt: -1 = setsockopt(6, 6, 0x4, 0xFFDFCB5C, 4), errno 109
3739 4876240 [MHD-single] response_generation_sendfile 1657 cygwin_send: 99 = send(6, 0x6000790C0, 99, 0x20)
3696 4879936 [MHD-single] response_generation_sendfile 1657 fhandler_disk_file::prw_open: 0x0 = NtOpenFile (0x264, 0x80100000, \??\C:\cygwin64\home\ng0\src\gsoc2019\a.txt, io, 0x7, 0x4020)
1749 4881685 [MHD-single] response_generation_sendfile 1657 fhandler_disk_file::pread: 1 = pread(0x60007D148, 1, 0, 0x0)
1146 4882831 [MHD-single] response_generation_sendfile 1657 pread: 1 = pread(7, 0x60007D148, 1, 0)
2882 4885713 [MHD-single] response_generation_sendfile 1657 cygwin_send: 1 = send(6, 0x60007D148, 1, 0x20)
1718 4887431 [MHD-single] response_generation_sendfile 1657 __set_errno: void __set_winsock_errno(const char*, int):203 setting errno 109
1143 4888574 [MHD-single] response_generation_sendfile 1657 __set_winsock_errno: setsockopt:1689 - winsock error 10042 -> errno 109
1155 4889729 [MHD-single] response_generation_sendfile 1657 cygwin_setsockopt: -1 = setsockopt(6, 6, 0x4, 0xFFDFCB58, 4), errno 109
4058 4893787 [MHD-single] response_generation_sendfile 1657 close: close(7)
other other other other other

Appended Notes

Other observations