Here is the makefile.  
--Chip Bagwell

Hi Chip:

	Not sure if this is your problem or not, but I can tell you one
thing can cause strange results when you go multi-threaded on SMP and
that is cache thrashing.  If both threads are running on different CPUs
and trying to access the same cache line (which would be true in your
case considering how things are declared), then you end up with 1 + 1 =
10 instead of 2 :>.

If you can set things up so that the individual thread counters and
mutexes are separated by a cache line (maybe by putting a dummy array in
between the declarations), this might change your results.  Not sure
what your cache line size is (usually on order of 32 bytes), so just go
for something biggish. 

   Robert.

-----Original Message-----
From: Chip Bagwell [mailto:community-noreply@qnx.com] 
Sent: Thursday, July 31, 2008 1:24 PM
To: ostech-core_os
Subject: SMP pthread_mutex performance

Hello,
I am trying to test locking (pthread_mutex vs. lock-free using
CAS)algorithms, and started with a simple pthread_mutex test program
that creates either one or two high priority threads.  There are two
counters, each of which may be protected by a pthread_mutex, depending
on the #define in the code.  Here are my results.

One Thread, no protection
Total time:             14997705 ns
Two Threads, no protection
Total time:             17997246 ns
One Thread, mutexes
Total time:             14997705 ns
Two Threads, mutexes
Total time:            755884332 ns

As you can see, running two individual threads, each incrementing its
own counter, protected by its own pthread_mutex is showing an execution
time that is an order of magnatude slower than any of the other three
configurations.

Here is the system this is being compiled and executed on

$ pidin in
CPU:X86 Release:6.3.2  FreeMem:801Mb/1021Mb BootTime:Jul 30 00:37:16 UTC
2008 
Processor1: 1586 Intel ?86 F15M4S4 3213MHz FPU 
Processor2: 1586 Intel ?86 F15M4S4 3206MHz FPU 
Processor3: 1586 Intel ?86 F15M4S4 3211MHz FPU 
Processor4: 1586 Intel ?86 F15M4S4 3207MHz FPU 
$ 

Attached you will find the source code, and the makefile to compile the
program.

Does anyone have any idea why I am seeing these results?

--Chip Bagwell

_______________________________________________
OSTech
http://community.qnx.com/sf/go/post11289

Some questions.

1) Did you try the same test on a uni processor?
2) Did you know that clock_gettime() actually has an accuracy of the timer tick, ie ~1ms?
3) You say you only saw KER_NOP's - you will see this when a thread is forced to schedule onto another CPU.  Did you not

see any SyncMutexLock calls or STATE_MUTEX states?

Chip Bagwell wrote:
> Hello,
> I am trying to test locking (pthread_mutex vs. lock-free using CAS)algorithms, and started with a simple pthread_mutex
 test program that creates either one or two high priority threads.  There are two counters, each of which may be 
protected by a pthread_mutex, depending on the #define in the code.  Here are my results.
> 
> One Thread, no protection
> Total time:             14997705 ns
> Two Threads, no protection
> Total time:             17997246 ns
> One Thread, mutexes
> Total time:             14997705 ns
> Two Threads, mutexes
> Total time:            755884332 ns
> 
> As you can see, running two individual threads, each incrementing its own counter, protected by its own pthread_mutex 
is showing an execution time that is an order of magnatude slower than any of the other three configurations.
> 
> Here is the system this is being compiled and executed on
> 
> $ pidin in
> CPU:X86 Release:6.3.2  FreeMem:801Mb/1021Mb BootTime:Jul 30 00:37:16 UTC 2008 
> Processor1: 1586 Intel ?86 F15M4S4 3213MHz FPU 
> Processor2: 1586 Intel ?86 F15M4S4 3206MHz FPU 
> Processor3: 1586 Intel ?86 F15M4S4 3211MHz FPU 
> Processor4: 1586 Intel ?86 F15M4S4 3207MHz FPU 
> $ 
> 
> Attached you will find the source code, and the makefile to compile the program.
> 
> Does anyone have any idea why I am seeing these results?
> 
> --Chip Bagwell
> 
> _______________________________________________
> OSTech
> http://community.qnx.com/sf/go/post11289
> 

-- 
cburgess@qnx.com

is it possible that the threads are migrating between the two
cpus? Can you try and lock each thread to a different CPU, by
doing a 

ThreadCtl(_NTO_TCTL_RUNMASK, ....)

and setting the runmask for each thread to be on a different cpu?

thanks
shiv
Thu Jul 31 22:22:42 EDT 2008

 --> According to Chip Bagwell <--
	Hello,
	I am trying to test locking (pthread_mutex vs. lock-free using CAS)algorithms, and started with a simple pthread_mutex 
test program that creates either one or two high priority threads.  There are two counters, each of which may be 
protected by a pthread_mutex, depending on the #define in the code.  Here are my results.
	
	One Thread, no protection
	Total time:             14997705 ns
	Two Threads, no protection
	Total time:             17997246 ns
	One Thread, mutexes
	Total time:             14997705 ns
	Two Threads, mutexes
	Total time:            755884332 ns
	
	As you can see, running two individual threads, each incrementing its own counter, protected by its own pthread_mutex 
is showing an execution time that is an order of magnatude slower than any of the other three configurations.
	
	Here is the system this is being compiled and executed on
	
	$ pidin in
	CPU:X86 Release:6.3.2  FreeMem:801Mb/1021Mb BootTime:Jul 30 00:37:16 UTC 2008 
	Processor1: 1586 Intel ?86 F15M4S4 3213MHz FPU 
	Processor2: 1586 Intel ?86 F15M4S4 3206MHz FPU 
	Processor3: 1586 Intel ?86 F15M4S4 3211MHz FPU 
	Processor4: 1586 Intel ?86 F15M4S4 3207MHz FPU 
	$ 
	
	Attached you will find the source code, and the makefile to compile the program.
	
	Does anyone have any idea why I am seeing these results?
	
	--Chip Bagwell
	
	_______________________________________________
	OSTech
	http://community.qnx.com/sf/go/post11289

Content-Description: Sourceforge Attachment
	#include <iostream>
	#include <stdlib.h>
	#include <pthread.h>
	#include <sched.h>
	#include <semaphore.h>
	#include <time.h>
	
	#define LOOP_ITERATIONS 10000000
	#define TWO_THREADS() 1
	#define USE_MUTEX()   1
	
	sem_t thread1sem;
	sem_t thread2sem;
	
	#if USE_MUTEX()
	pthread_mutex_t thread1mutex;
	pthread_mutex_t thread2mutex;
	#endif
	
	unsigned long counter1;
	unsigned long counter2;
	
	unsigned long long startTime1;
	unsigned long long endTime1;
	unsigned long long startTime2;
	unsigned long long endTime2;
	
	extern "C" long long timespec_to_nanosecond(struct timespec const *ts)
	{
	    long long nanosecond = ts->tv_sec;
	    nanosecond *= 1000000000;
	    nanosecond += ts->tv_nsec;
	    return nanosecond;
	}
	
	void * thread1(void *arg)
	{
	    struct timespec currentTime;
	    
	    sem_wait(&thread1sem);  // Wait on signal from parent.
	    
	    sleep(1);  // Sleep to make sure this thread doesn't
	               // finish before the parent has a chance
	               // to create the other thread(s)
	    
	    clock_gettime(CLOCK_REALTIME, ¤tTime);
	    startTime1 = timespec_to_nanosecond(¤tTime);
	    
	    for(unsigned long long i = 0; i < LOOP_ITERATIONS; ++i);
	    {
	#if USE_MUTEX()
	        pthread_mutex_lock(&thread1mutex);
	#endif
	        ++counter1;
	#if USE_MUTEX()
	        pthread_mutex_unlock(&thread1mutex);
	#endif
	
	#if TWO_THREADS() == 0
	
	#if USE_MUTEX()
	        pthread_mutex_lock(&thread2mutex);
	#endif
	        ++counter2;
	#if USE_MUTEX()
	        pthread_mutex_unlock(&thread2mutex);
	#endif
	
	#endif        
	    }
	
	    clock_gettime(CLOCK_REALTIME, ¤tTime);
	    endTime1 = timespec_to_nanosecond(¤tTime);
	
	}
	
	#if TWO_THREADS()
	void * thread2(void *arg)
	{
	    struct timespec currentTime;
	
	    sem_wait(&thread2sem);  // Wait on signal from parent.
	
	    sleep(1);  // Sleep to make sure this thread doesn't
	               // finish before the parent has a chance
	               // to create the other thread(s)
	
	   ...