Subject: write() in nonblocking mode can be slow.
To: None <netbsd-users@netbsd.org>
From: Jorgen Lundman <lundman@lundman.net>
List: netbsd-users
Date: 03/11/2005 11:57:50
NetBSD backup 2.0 NetBSD 2.0 (backup) #0: Wed Feb 16 14:29:13 JST 2005 
root@netbsd:/usr/src/sys/arch/i386/compile/backup i386

P3-450 x 2


I have a socket (TCP) connected where their end is very slow. (~3k/s). 
Everything in my daemon is operating in NONBLOCKING mode, which I confirm before 
and after the call to SSL_write(). For users with fast connections, I see no 
such slowdown.

ktrace will show large delays on write(). Sometimes up to 7 seconds! (Biggest I 
have seen so far anyway).


The sources currently has:

#if 1
	poo = fcntl(SSL_get_fd(ssl), F_GETFL);
	if (!(poo & O_NONBLOCK))
		printf("Warning, %d %d (%d)is blocking.\n",
			   SSL_get_fd(ssl), poo, poo & O_NONBLOCK);
#endif

	status = SSL_write(ssl, (char *)buf, num);
	sslerr = SSL_get_error(ssl, status);

#if 1
  {
	 time_t t;
	 time(&t);
	if (t - lion_global_time >= 2) {
		printf("SSL_write: operation took long time!\n");
		poo = fcntl(SSL_get_fd(ssl), F_GETFL);
		printf("Is nonblock: fd %d %d (%d)\n",
			   SSL_get_fd(ssl), poo, poo & O_NONBLOCK);
		sockets_setnonblocking(SSL_get_fd(ssl));
	}
  }
#endif



SSL_write: operation took long time!
Is nonblock: fd 20 6 (4)
[sockets] fd 20 verified nonblocking 6
SSL_write: operation took long time!
Is nonblock: fd 20 6 (4)
[sockets] fd 20 verified nonblocking 6


So the socket is nonblocking the entire time. It isn't SSL_write that is slow, 
if we ktrace it:



For example:

  15602 lundftpd 0.000036 CALL  fcntl(0x10,3,6)
  15602 lundftpd 0.000026 RET   fcntl 6
  15602 lundftpd 0.000492 CALL  write(0x10,0x8259000,0x1011)
  15602 lundftpd 4.764710 GIO   fd 16 wrote 4088 bytes
  15602 lundftpd 0.000000 GIO   fd 16 wrote 25 bytes
  15602 lundftpd 0.000219 RET   write 4113/0x1011


Other slow calls.

  15602 lundftpd 2.274635 GIO   fd 16 wrote 4088 bytes
  15602 lundftpd 2.326448 GIO   fd 16 wrote 4088 bytes
  15602 lundftpd 2.454948 GIO   fd 16 wrote 4088 bytes
  15602 lundftpd 4.764710 GIO   fd 16 wrote 4088 bytes

  15602 lundftpd 2.552011 GIO   fd 20 wrote 4088 bytes
  15602 lundftpd 2.601062 GIO   fd 20 wrote 4088 bytes
  15602 lundftpd 2.694234 GIO   fd 20 wrote 4088 bytes
  15602 lundftpd 3.206039 GIO   fd 20 wrote 4088 bytes
  15602 lundftpd 3.839058 GIO   fd 20 wrote 4088 bytes



Any particular reasons why nonblocking would block for such a long time? Is this 
related to my other trouble that I eventually run out of SOMAXKVA?

Any feedback would be appreciated.

Lund


-- 
Jorgen Lundman       | <lundman@lundman.net>
Unix Administrator   | +81 (0)3 -5456-2687 ext 1017 (work)
Shibuya-ku, Tokyo    | +81 (0)90-5578-8500          (cell)
Japan                | +81 (0)3 -3375-1767          (home)