Re: TCPSocket delay problem

On Wed, 5 Mar 2003, Yukihiro Matsumoto wrote:

> The only workaround I can think of is to use "resolv-replace", which
> is pure Ruby resolver.  It is not fast at all, but at least other
> thread can work during resolving.  Try putting
>
>   require "resolv-replace"

i see the same problem as seth.  when i run this :

  ruby -r socket -e 'p (Time.now); p (TCPSocket.new %q(ad.doubleclick.net), 80); p (Time.now)

it takes around 20 seconds to run.  so i tried

  strace !! > strace 2>&1

and here is where it got interesting.  looking at the strace file i saw :

  247 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 3
  248 connect(3, {sin_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("137.75.132.181")}}, 16) = 0
  249 send(3, "\314Q\1\0\0\1\0\0\0\0\0\0\2ad\vdoubleclick\3net\0"..., 36, 0) = 36
  250 time(NULL)                              = 1046809069

  251 poll([{fd=3, events=POLLIN}], 1, 5000)  = 0
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
	      THIS TIMED OUT!

  252 close(3)                                = 0

so then tried running

  strace dnsquery ad.doubleclick.net > strace 2>&1

and looking at it's strace, which shows :

  36 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 3
  37 connect(3, {sin_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("137.75.132.181")}}, 16)         = 0
  38 send(3, "s\332\1\0\0\1\0\0\0\0\0\0\2ad\vdoubleclick\3net\0"..., 36, 0) = 36
  39 gettimeofday({1046809802, 554050}, NULL) = 0
  40 rt_sigprocmask(SIG_SETMASK, NULL, [], 8) = 0
  41 select(4, [3], NULL, NULL, {5, 0})      = 1 (in [3], left {4, 950000})
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
	      THIS DID *NOT* TIMED OUT!
  42 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
  43 recvfrom(3, "s\332\201\200\0\1\0\1\0\4\0\4\2ad\vdoubleclick\3net\0"..., 8192, 0, {sin_family=AF_        INET, sin_port=htons(53), sin_addr=inet_addr("137.75.132.181")}}, [16]) = 206
  44 close(3)                                = 0



so, ruby sends (via syscalls)

  "\314Q\1\0\0\1\0\0\0\0\0\0\2ad\vdoubleclick\3net\0"

and then polls


while dnsquery sends (via syscalls)

  "s\332\1\0\0\1\0\0\0\0\0\0\2ad\vdoubleclick\3net\0"

and then selects


the problems is that the poll from ruby times out?!  i don't know much about
dns, and so don't understand the meaning of the queries, but perhaps one is
incorrect?  if not, then this seems like it could only be a bug in poll?

hope this helps.

-a




--
  ====================================
  | Ara Howard
  | NOAA Forecast Systems Laboratory
  | Information and Technology Services
  | Data Systems Group
  | R/FST 325 Broadway
  | Boulder, CO 80305-3328
  | Email: [e-mail]
  | Phone:  [phone]
  | Fax:    [phone]
  ====================================