I thought it curious that every write() call issued two lines in ktrace. So I 
lowered the buffer IO size from 4088 to 4000, and I no longer see slow write() 
calls, nor the double take.

Seems a ok work around, but I still feel nonblocking is broken for large writes.

Lund


Jorgen Lundman wrote:
> 
> 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)