Beefy Boxes and Bandwidth Generously Provided by pair Networks
There's more than one way to do things

Socket slowdown when using two separate print statements

by suaveant (Parson)
on May 06, 2011 at 16:02 UTC ( [id://903408] : perlquestion . print w/replies, xml ) Need Help??

suaveant has asked for the wisdom of the Perl Monks concerning the following question:

I've either found a bug, a quirk, or I'm stupid, but I've been banging my head against this issue for two days now, and I finally at least isolated the cause.

I have a server that allows you to connect and make multiple queries on a single socket connection the main loop decides which function to call, the function prints data to the sock and once we return the main loop basically does print {$client} "__END__\n";

Apparently this is bad, and I've created a simple echoing client server pair which illustrate...

#!/idcom/bin/perl use IO::Socket::INET; use Time::HiRes qw( gettimeofday tv_interval ); use strict; our $PORT = 9990; if(fork) { my $s = IO::Socket::INET->new( LocalPort => $PORT, Listen => 5, Re +use => 1 ); my $c = $s->accept(); while(<$c>) { print {$c} $_; } } else { sleep 1; my $s = IO::Socket::INET->new( PeerAddr => 'localhost:'.$PORT ); for(1..5) { my $t0 = [gettimeofday]; print {$s} "func=mbs_descriptive&type=&secid=313627KM2\n"; print "".<$s>; print tv_interval( $t0, [gettimeofday] ),"\n"; } }
When this runs all is great!
func=mbs_descriptive&type=&secid=313627KM2 0.000259 func=mbs_descriptive&type=&secid=313627KM2 5e-05 func=mbs_descriptive&type=&secid=313627KM2 4.3e-05 func=mbs_descriptive&type=&secid=313627KM2 4.2e-05 func=mbs_descriptive&type=&secid=313627KM2 4.2e-05
But if you change that print to the socket to be:
print {$s} "func=mbs_descriptive&type="; print {$s} "&secid=313627KM2\n";
Then sadness and woe befall the code!
func=mbs_descriptive&type=&secid=313627KM2 0.000181 func=mbs_descriptive&type=&secid=313627KM2 0.040125 func=mbs_descriptive&type=&secid=313627KM2 0.04009 func=mbs_descriptive&type=&secid=313627KM2 0.039891 func=mbs_descriptive&type=&secid=313627KM2 0.040025
ARGH! The first call is fast, and every subsequent one has about .4s tacked on for fun, multiply that by 5000 and it starts to really add up. What am I missing here?

                - Ant
                - Some of my best work - (1 2 3)

Replies are listed 'Best First'.
Re: Socket slowdown when using two separate print statements
by Fletch (Bishop) on May 06, 2011 at 17:04 UTC

    Presuming the OS in question supports it it might be elucidating to use strace or its equivalent (dtruss, what not) to watch the underlying system calls being made with relative timings enabled. I don't know for sure but it sounds like it might be some weird Nagle's algorithm interaction going on.

    The cake is a lie.
    The cake is a lie.
    The cake is a lie.

      Yeah, sorry, Red Hat Enterprise Linux AS release 4, tried Perl 5.10 and 5.8.5

                      - Ant
                      - Some of my best work - (1 2 3)