Re: performance....

"Richard Seaman, Jr." <[email protected]> Mon, 15 Apr 2002 17:40:18 -0500
Newsgroups gmane.linux.ngpt.user
Message-ID <[email protected]>
On Mon, Apr 15, 2002 at 01:39:06PM -0500, Richard Seaman, Jr. wrote:
> On Mon, Apr 15, 2002 at 09:52:03AM -0400, Bill Abt wrote:
> 
> > Most of our benchmarking and testing has involved the same test cases that
> > are included in the LinuxThreads package.  In these tests, NGPT is faster
> > in virtually every area.
> 
> Since you're able to do thread context switches in userland, as compared to
> Linuxthreads that does thread context switches in the kernel, your context
> switches *ought* to be much more efficient.  But I haven't measured this 
> directly.
> 
> It also appears to me that things like syscalls that can block, mutex locking,
> and pthread_self among others, are likely to be less efficient in NGPT than
> Linuxthreads.
> 
> I would guess that benchmarks that are dominated by the cost of context switches
> would favor NGPT.  Other benchmarks might show the opposite, depending on the
> mix of code.

Well, I was very wrong about the context switching.  NGPT is very slow.
I'm attaching some very simple and very crude benchmark code.

Basically, I started 10 threads each doing 1,000,000 yields simultaneously,
as a very crude measure of context switch overhead. The results (average of
3 runs, details attached):

        NGPT          44.1 secs
        Linuxthreads   7.3 secs

Or, NGPT is slower by a factor of 6! By all logic, NGPT should be faster.

I also did some read/write comparisons.  Basically I did 10 threads each
doing 100,000 reads and writes, yielding after each read and write.  The results
(average of 3 runs, details attached):

        NGPT          59.3 secs
        Linuxthreads  40.3 secs

Or, NGPT is close to 50% slower.  This might be expected based on the overhead
in the read/write wrappers in the NGPT code.
   
-- 
Richard Seaman, Jr.        email:    [email protected]
5182 N. Maple Lane         phone:    262-367-5450
Nashotah WI 53058            fax:    262-367-5852
test1.c (text/plain, 4.1 KB)
#include <sys/time.h>
#include <stdlib.h>
#include <stdio.h>
#include <string.h>
#include <fcntl.h>
#include <unistd.h>
#include <pthread.h>
#include <assert.h>

#define MYBUFSIZ 10000

typedef struct _mythreaddata {
   int r;
   int l;
   int revs;
   pthread_t thr;
   struct timeval tstart;
   struct timeval tend;
} mythreaddata, *pmythreaddata;

void yield_thread (pmythreaddata ptd);
void disk_io_thread (pmythreaddata ptd);

mythreaddata td[100];
int          reps;
pthread_t    lastth;
pthread_mutex_t start_mutex;
pthread_cond_t  start_cond;
int          allstarted;
int          numthreads;

extern int
main(int argc, char *argv[])
{
    int             i;
    struct timeval  tstart, tend;
    int             testtime;
    int             tstarttime, tendtime;
    void (*fn)(pmythreaddata);
    
    if (argc > 1) 
	reps = atoi (argv[1]);
    else
	reps = 100000;
    
    if (argc > 2) 
	numthreads = atoi (argv[2]);
    else 
	numthreads = 10;
    
    fn = yield_thread;
    if (argc > 3 && (*(argv[3]) == 'i' || *(argv[3]) == 'I'))
	fn = disk_io_thread;
    
    if (pthread_mutex_init (&start_mutex, NULL))
	exit(1);
    if (pthread_cond_init (&start_cond, NULL))
	exit(1);
    
    gettimeofday (&tstart, NULL);
    for (i= 0; i < numthreads; i++) {
	gettimeofday (&(td[i].tstart), NULL);
	if (pthread_create(&(td[i].thr), 
			   NULL,
			   (void *)fn,
			   (void *) &(td[i])) != 0)
	    perror("pthread_create"); 
    }
    
    if (pthread_mutex_lock (&start_mutex))
	abort();
    allstarted = 1;
    if (pthread_cond_broadcast (&start_cond))
	abort();
    if (pthread_mutex_unlock(&start_mutex))
	abort();
    
    for (i = 0; i < numthreads; i++) {
	if (pthread_join(td[i].thr, NULL) != 0)
	    perror("pthread_join:");
    }
    
    gettimeofday (&tend, NULL);
    
    
    printf ("Thread     Count Start Time   End Time  Reverses\n");
    printf ("------   ------- ----------   --------  --------\n");
    for (i = 0; i < numthreads; i++) {
	tstarttime  = (td[i].tstart.tv_sec - tstart.tv_sec) * 1000000 +
	    (td[i].tstart.tv_usec - tstart.tv_usec);
	tendtime    = (td[i].tend.tv_sec   - tstart.tv_sec) * 1000000 +
	    (td[i].tend.tv_usec   - tstart.tv_usec);
	printf ("%i     %10i %10.5f %10.5f  %8i\n", i, td[i].r,
		(double)tstarttime / 1000000.0,
		(double)tendtime   / 1000000.0, td[i].revs);
    }
    
    testtime  = (tend.tv_sec - tstart.tv_sec) * 1000000 +
	(tend.tv_usec - tstart.tv_usec);
    printf ("Total elapsed time is %10.5f seconds\n",
	    (double)testtime / 1000000.0);
    return 0; 
}

void yield_thread (pmythreaddata ptd)
{
    int i;
    pthread_t self;
    
    gettimeofday (&(ptd->tstart), NULL);
    if (pthread_mutex_lock(&start_mutex))
	abort();
    while (allstarted == 0) {
	if (pthread_cond_wait (&start_cond, &start_mutex))
	    abort();
    }
    if (pthread_mutex_unlock(&start_mutex))
	abort();
    
    for (i = 0;  i < reps; i++) {
	sched_yield();
	
	/* A crude and possibly inaccurate measure of our concurrency */
	self = pthread_self();
	if (self != lastth)
	    ptd->revs++;
	lastth = self;
	
	ptd->r++;
    }
    gettimeofday (&(ptd->tend), NULL);
}

void disk_io_thread (pmythreaddata ptd)
{
    int i;
    pthread_t self;
    int fd;
    char filename[20];
    char *buffer;
    
    gettimeofday (&(ptd->tstart), NULL);
    sprintf (filename, "testfile.%i", (int)ptd->thr);
    fd = open (filename, O_RDWR | O_CREAT | O_TRUNC, 0666);
    assert (fd >= 0);
    buffer = malloc (MYBUFSIZ);
    assert (buffer != NULL);
    memset (buffer, 'A', MYBUFSIZ);
    if (pthread_mutex_lock(&start_mutex))
	abort();
    while (allstarted == 0) {
	if (pthread_cond_wait (&start_cond, &start_mutex))
	    abort();
    }
    if (pthread_mutex_unlock(&start_mutex))
	abort();
    
    for (i = 0;  i < reps; i++) {
	
	lseek (fd, 0, SEEK_SET);
	write (fd, buffer, MYBUFSIZ);
	
	sched_yield();
	
	/* A crude and possibly inaccurate measure of our concurrency
	 */
	self = pthread_self();
	if (self != lastth)
	    ptd->revs++;
	lastth = self;
	ptd->r++;
	
	lseek (fd, 0, SEEK_SET);
	read (fd, buffer, MYBUFSIZ);
	sched_yield();
    }
    close (fd);
    unlink (filename);
    gettimeofday (&(ptd->tend), NULL);
}
results (text/plain, 9.6 KB)
With NGPT:
------------------------------------------------
[dick@tbird testthreads]$ ./test1 1000000 10
Thread     Count Start Time   End Time  Reverses
------   ------- ----------   --------  --------
0        1000000    0.00065   45.07216   1000000
1        1000000    0.00066   45.07220   1000000
2        1000000    0.00066   45.07220   1000000
3        1000000    0.00067   45.07221   1000000
4        1000000    0.00067   45.07221   1000000
5        1000000    0.00068   45.07222   1000000
6        1000000    0.00068   45.07222   1000000
7        1000000    0.00069   45.07223   1000000
8        1000000    0.00069   45.07223   1000000
9        1000000    0.00070   45.07231   1000000
Total elapsed time is   45.07246 seconds

[dick@tbird testthreads]$ ./test1 1000000 10
Thread     Count Start Time   End Time  Reverses
------   ------- ----------   --------  --------
0        1000000    0.00066   43.92228   1000000
1        1000000    0.00067   43.92232   1000000
2        1000000    0.00068   43.92232   1000000
3        1000000    0.00068   43.92233   1000000
4        1000000    0.00069   43.92233   1000000
5        1000000    0.00069   43.92234   1000000
6        1000000    0.00070   43.92234   1000000
7        1000000    0.00071   43.92235   1000000
8        1000000    0.00071   43.92235   1000000
9        1000000    0.00072   43.92242   1000000
Total elapsed time is   43.92257 seconds

[dick@tbird testthreads]$ ./test1 1000000 10
Thread     Count Start Time   End Time  Reverses
------   ------- ----------   --------  --------
0        1000000    0.00136   43.47483   1000000
1        1000000    0.00137   43.47487   1000000
2        1000000    0.00137   43.47488   1000000
3        1000000    0.00138   43.47488   1000000
4        1000000    0.00138   43.47489   1000000
5        1000000    0.00139   43.47489   1000000
6        1000000    0.00139   43.47490   1000000
7        1000000    0.00140   43.47490   1000000
8        1000000    0.00140   43.47491   1000000
9        1000000    0.00141   43.47497   1000000
Total elapsed time is   43.47513 seconds

[dick@tbird testthreads]$ ./test1 100000 10 i
Thread     Count Start Time   End Time  Reverses
------   ------- ----------   --------  --------
0         100000    0.00067   59.82260    100000
1         100000    0.00101   59.82268    100000
2         100000    0.00154   59.82273    100000
3         100000    0.00171   59.82278    100000
4         100000    0.00190   59.82283    100000
5         100000    0.00208   59.82288    100000
6         100000    0.00226   59.82293    100000
7         100000    0.00243   59.82298    100000
8         100000    0.00261   59.82303    100000
9         100000    0.00280   59.82314    100000
Total elapsed time is   59.82330 seconds

[dick@tbird testthreads]$ ./test1 100000 10 i
Thread     Count Start Time   End Time  Reverses
------   ------- ----------   --------  --------
0         100000    0.00069   62.12406    100000
1         100000    0.00109   62.12417    100000
2         100000    0.00130   62.12423    100000
3         100000    0.00149   62.12428    100000
4         100000    0.00169   62.12434    100000
5         100000    0.00188   62.12439    100000
6         100000    0.00208   62.12445    100000
7         100000    0.00227   62.12450    100000
8         100000    0.00248   62.12455    100000
9         100000    0.00267   62.12466    100000
Total elapsed time is   62.12482 seconds
[dick@tbird testthreads]$ ./test1 100000 10 i
Thread     Count Start Time   End Time  Reverses
------   ------- ----------   --------  --------
0         100000    0.00065   56.08229    100000
1         100000    0.00103   56.08237    100000
2         100000    0.00123   56.08242    100000
3         100000    0.00142   56.08247    100000
4         100000    0.00162   56.08252    100000
5         100000    0.00180   56.08257    100000
6         100000    0.00199   56.08262    100000
7         100000    0.00217   56.08266    100000
8         100000    0.00237   56.08271    100000
9         100000    0.00256   56.08282    100000
Total elapsed time is   56.08298 seconds

With Linuxthreads:
------------------------------------------------
[dick@tbird testthreads]$ ./test1 1000000 10
Thread     Count Start Time   End Time  Reverses
------   ------- ----------   --------  --------
0        1000000    0.00517    4.62141    837815
1        1000000    0.00519    6.00342    999939
2        1000000    0.00520    7.20941    999959
3        1000000    0.00520    7.17491    949797
4        1000000    0.00521    7.26293    867593
5        1000000    0.00578    7.10903    999939
6        1000000    0.00578    7.02585    999959
7        1000000    0.00579    6.57823    999959
8        1000000    0.00579    6.93197    837493
9        1000000    0.00583    7.13715    999959
Total elapsed time is    7.26298 seconds

[dick@tbird testthreads]$ ./test1 1000000 10
Thread     Count Start Time   End Time  Reverses
------   ------- ----------   --------  --------
0        1000000    0.00039    7.01766    999958
1        1000000    0.00041    6.31445    833242
2        1000000    0.00041    6.81689    984169
3        1000000    0.00057    7.36270    999939
4        1000000    0.00058    6.84657    972968
5        1000000    0.00059    7.41851    953944
6        1000000    0.00059    7.40082    999959
7        1000000    0.00070    7.37546    999959
8        1000000    0.00071    7.07064    999959
9        1000000    0.00072    6.44507    999959
Total elapsed time is    7.41856 seconds

[dick@tbird testthreads]$ ./test1 1000000 10
Thread     Count Start Time   End Time  Reverses
------   ------- ----------   --------  --------
0        1000000    0.00041    6.62849    999959
1        1000000    0.00042    7.23092    919659
2        1000000    0.00042    7.20070    976557
3        1000000    0.00058    4.83178    808174
4        1000000    0.00058    5.96431    999959
5        1000000    0.00059    6.99252    999959
6        1000000    0.00060    6.81943    999959
7        1000000    0.00071    7.19242    999959
8        1000000    0.00072    6.83366    916379
9        1000000    0.00072    6.50407    971621
Total elapsed time is    7.23098 seconds

[dick@tbird testthreads]$ ./test1 100000 10 i
Thread     Count Start Time   End Time  Reverses
------   ------- ----------   --------  --------
0         100000    0.00038   42.54205     96700
1         100000    0.00062   39.46475     94520
2         100000    0.00087   42.57878     96843
3         100000    0.00107   38.46055     96803
4         100000    0.00108   40.91414     98774
5         100000    0.00110   42.09619     98483
6         100000    0.00130   41.98226     96071
7         100000    0.00132   42.43740     92784
8         100000    0.00133   40.82377     96997
9         100000    0.00134   42.18131     98720
Total elapsed time is   42.57885 seconds

[dick@tbird testthreads]$ ./test1 100000 10 i
Thread     Count Start Time   End Time  Reverses
------   ------- ----------   --------  --------
0         100000    0.00042   37.81490     96744
1         100000    0.00067   39.73409     90964
2         100000    0.00076   39.41164     95918
3         100000    0.00103   38.62456     93904
4         100000    0.00112   39.62172     98646
5         100000    0.00122   39.02020     97635
6         100000    0.00130   39.43046     98135
7         100000    0.00151   39.22059     95709
8         100000    0.00180   36.03183     96516
9         100000    0.00199   37.90286     98615
Total elapsed time is   39.73415 seconds

[dick@tbird testthreads]$ ./test1 100000 10 i
Thread     Count Start Time   End Time  Reverses
------   ------- ----------   --------  --------
0         100000    0.00040   36.82923     97766
1         100000    0.00062   35.34030     95559
2         100000    0.00070   38.71222     97179
3         100000    0.00096   34.53568     93615
4         100000    0.00105   36.47596     97280
5         100000    0.00114   38.29908     99121
6         100000    0.00122   38.27763     99149
7         100000    0.00143   37.76335     96565
8         100000    0.00172   37.75153     95508
9         100000    0.00191   38.65580     96446
Total elapsed time is   38.71229 seconds

[dick@tbird testthreads]$ /lib/libc.so.6
GNU C Library stable release version 2.2.4, by Roland McGrath et al.
Copyright (C) 1992-1999, 2000, 2001 Free Software Foundation, Inc.
This is free software; see the source for copying conditions.
There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
PARTICULAR PURPOSE.
Compiled by GNU CC version 2.96 20000731 (Red Hat Linux 7.2 2.96-108.1).
Compiled on a Linux 2.4.9-31smp system on 2002-04-02.
Available extensions:
        GNU libio by Per Bothner
        crypt add-on version 2.1 by Michael Glad and others
        The C stubs add-on version 2.1.2.
        linuxthreads-0.9 by Xavier Leroy
        BIND-8.2.3-T5B
        NIS(YP)/NIS+ NSS modules 0.19 by Thorsten Kukuk
        Glibc-2.0 compatibility add-on by Cristian Gafton
        libthread_db work sponsored by Alpha Processor Inc
Report bugs using the `glibcbug' script to <[email protected]>.

[dick@tbird testthreads]$ uname -a
Linux tbird.internal.seaman.net 2.4.18-0.16custom #2 Sun Apr 7 15:18:17 CDT 2002 i686 unknown

Apr  7 15:29:20 tbird kernel: Initializing CPU#0
Apr  7 15:29:20 tbird kernel: Detected 1000.075 MHz processor.
Apr  7 15:29:20 tbird kernel: Calibrating delay loop... 1992.29 BogoMIPS
Apr  7 15:29:20 tbird kernel: Memory: 772404k/786368k available (1248k kernel code, 13576k reserved, 836k data, 296k init, 0k highmem)
Apr  7 15:29:20 tbird kernel: CPU: L1 I Cache: 64K (64 bytes/line), D cache 64K (64 bytes/line)
Apr  7 15:29:20 tbird kernel: CPU: L2 Cache: 256K (64 bytes/line)
Apr  7 15:29:20 tbird kernel: CPU: AMD Athlon(tm) Processor stepping 02