Gonzo Test Results

Thanks for talking the time to read this extended posting. I can be emailed at nawkboy@yahoo.com.

The general shape of the curves below is typical of the connection times to my forking server. (NOT pre-forking) I do not understand the strange behavior that is occuring at approximately 10 simultaneous connections. Although my server children spawn subprocesses when given a proper command, the behavior is the same even when an improper command is sent to the server and the server child never attempts to open a subprocess.

Q: The question is what can/will cause this strange behavior? Is this normal? Is this a kernal configuration issue? etc.

Uname -a returns: SunOS XXX 5.6 Generic_105181-21 sun4u sparc SUNW,Ultra-80


The relevant lines of code that kick off the server are:

#---------
package YYY::Main;

use vars qw($VERSION @ISA);
@ISA = qw();
$VERSION = '0.01';

require 5.005_03;

use strict;
use XXX::Log;
use XXX::Translator;
use IO::Socket;
use Socket;
#----------------------------------------------
sub REAP {
        my $waitedpid = wait();
        $MAIN::SIG{'CHLD'} = \&REAP;
}
#----------------------------------------------
$MAIN::SIG{'CHLD'} = \&REAP;
#----------------------------------------------
sub new {
        my $class=shift;

        my $self=bless {}, ref($class)||$class;

        $self->_init(@_);

        return $self;
}#new
#----------------------------------------------
#blah, blah
#....
#
#----------------------------------------------
sub start {
	my $self=shift;

	#blah, blah


        $main_sock = new IO::Socket::INET (
                                        #'LocalHost' => 'goldengate',
                                        'LocalPort' => $self->{'port'},
                                        'Listen' => 5,
                                        'Proto' => 'tcp',
                                        'Reuse' => 1,
                                  );
        die "Socket could not be created. Reason: $!\n" unless ($main_sock);

        while ($new_sock = $main_sock->accept()) {
                $pid = fork();
                die "Cannot fork: $!" unless defined($pid);
                if ($pid == 0) { 
                        # Child process
                        $translator = XXX::Translator->new({
                                                'log_obj' => $log_obj,
                                                'apiserver_path' => $self->{'apiserver_path'},
                                                'library' => $self->{'library'},
                                                });
INNER_LOOP:             while (defined ($buf = <$new_sock>)) {
                                # do something with $buf ....
                                chomp $buf;
                                $log_obj->log("[MAIN] PID $$ buf is ${buf}\n", 0);
                                $reply=$translator->translate($buf);
                                last unless (defined $reply);
                                chomp $reply;
                                print $new_sock "$reply\015\012";
                        }#while
                        shutdown($new_sock, 2);
                        $new_sock->close();
                        #$new_sock->shutdown(2);
                }## else 'tis the parent process, which goes back to accept()
        }#while
        
        close ($main_sock);

	return;

}#start


The relevant lines of connection time test code are:

        #Create a big pool of socket connections to gonzo
        for ($i=0; $i<$client_count; $i++){
                $t0=gettimeofday();
                $socket=IO::Socket::INET->new(
                                'PeerAddr' => $hostname,
                                'PeerPort' => $self->{'port'},
                                'Proto' => 'tcp',
                                );

                $t1=gettimeofday();
                push(@{$connection_times_AR}, $t1-$t0);

                unless (defined $socket ) {
                        $error="_hammer_gonzo method with a process pid of $$ couldn't ";
                        $error.="create yet another socket connection to ${hostname}:$self->{'port'} :$@\n";
                        return (0, undef, $error);
                }#unless

                $sel->add($socket);
        }#for

The relevant lines of talk time test code are:

        for ($j=0; $j<$cycle_count; $j++) {
                $t0=gettimeofday();

                #Write to every socket created
                $i=0;
                while ($i<$client_count) {
                        foreach $io ( $sel->can_write($self->{'timeout'}) ){
                                $io->print("$gonzo_cmd\n");
                                $i++;
                        }#foreach
                }#while;

                #Read one line from every socket created.
                #It is assumed that only one line can be read from each socket connection.
                $i=0;
                while ($i<$client_count) {
                        foreach $io ( $sel->can_read($self->{'timeout'}) ){
                                $in_line=$io->getline();
                                chomp($in_line);
                                push(@outputs, $in_line);
                                $i++;
                        }#foreach
                }#while;
                
                $t1=gettimeofday();
                push(@{$conversation_times_AR}, $t1-$t0);

                $one_result=$self->_identical_elements(\@outputs);
                unless (defined $one_result) {
                        $error="Results were not identical for ${j}th trial!";
                        return (undef, undef, $error);
                }#unless

        }#for

The mysterious performance plot that is showing such strange behavior at 11 simultaneous connections


Int Time
(connections, int_time(seconds), std_dev)
1	0.00268540382385254	0.00365097835318002
2	0.00112311840057373	0.000188843955382284
3	0.00107872486114502	0.000133064734377605
4	0.0010466992855072	0.000104347678803338
5	0.00102376937866211	0.000132908129334156
6	0.00103745460510254	0.000157207648783618
7	0.0010197503226144	0.000126839681129335
8	0.00102171003818512	0.000131206412474368
9	0.00101917054918077	0.000106301937222023
10	0.0010163140296936	9.61876534146011e-05
11	0.318813384662975	1.0140945812002
12	0.292407224575679	0.974447148722859
13	0.270044158055232	0.939099463149516
14	0.250602231706892	0.906211881403956
15	0.23413986047109	0.877905811247882
20	0.175928362607956	0.766032293467681
30	0.234119118054708	0.8748534346005
40	0.263460919260979	0.923077405619365
50	0.280729802131653	0.950097894119339
60	0.280736508369446	0.949848774814088
70	0.280784632137844	0.949787960807761
80	0.2719849807024		0.935735754997858
90	0.281206092039744	0.949307204722445
100	0.280732091903687	0.949168555391629

Talk Time
(connections, talk_time(seconds), std_dev)
1	0.0141584396362305	0.00447715884194119
2	0.0210402011871338	0.00332526309480636
3	0.0275811910629272	0.00389352297966734
4	0.036872386932373	0.000491734403536839
5	0.0444020509719849	0.00147930652811437
6	0.0549090147018433	0.00333563334021639
7	0.0617681980133057	0.00122601864248517
8	0.0695285797119141	0.00357774762741569
9	0.0761578321456909	0.00386701885946457
10	0.0862689971923828	0.0049914026218433
11	0.0205194234848022	0.0034819862082951
12	0.0359688282012939	0.000791518558326905
13	0.0394474029541016	0.00304175997354709
14	0.0476216077804565	0.00170241488589745
15	0.053122615814209	0.00288756133857106
20	0.0765285968780518	0.00320829456517778
30	0.0739166259765625	0.00473202466632877
40	0.0773057460784912	0.00265899246793384
50	0.0809346199035645	0.00420149742249498
60	0.0854897975921631	0.0230616360607157
70	0.10006000995636	0.0234290297218502
80	0.120056200027466	0.0235365712144055
90	0.122123432159424	0.0179684846826036
100	0.13361759185791	0.0030474179259776