performance analysis producer_consumer.cc TEST_T5
Will Cohen
wcohen@redhat.com
Fri Feb 13 17:10:00 GMT 2004
I ran some experiments for stdc++-v3 "make check-performance" on a Dual
processor Pentium III machine, 256KB L2 cache, 256MB RAM with Red Hat
Enterprise Linux 3 and a uniprocessor Pentium M machine. The dual
processor Pentium III was much slower than the run on a 1.6GHz
uniprocessor Pentium M machine, with 1MB L2 cache, and 512MB RAM. The
uniprocessor machine is about a factor of 30 faster than the dual
processor machine. There seems to be a problem with threading code.
On Dual Pentium III
$ time make check-performance >& results
real 166m21.354s
user 306m30.280s
sys 1m7.360s
On uniprocessor Pentium M
$ time make check-performance >& results
real 10m51.442s
user 7m45.600s
sys 2m50.960s
Collected data on the dual processor Pentium III machine with
OProfile. Sample rate was set to approximately 2,000 samples per
processor per second.
op_time -r|more
15005322 39.2892 0.0000
/dunes/wcohen/gcc/gcc-current/obj/i686-pc-linux-gnu/libstdc++-v3/testsuite/producer_consumer.cc-TEST_T5
12086196 31.6459 0.0000
/dunes/wcohen/gcc/gcc-current/obj/i686-pc-linux-gnu/libstdc++-v3/testsuite/producer_consumer.cc-TEST_T6
7158530 18.7436 0.0000
/dunes/wcohen/gcc/gcc-current/obj/i686-pc-linux-gnu/libstdc++-v3/testsuite/producer_consumer.cc-TEST_T7
1216430 3.1850 0.0000 /boot/vmlinux-2.4.21-9.ELsmp
...
Taking a closer look at producer_consuer.cc-TEST_T5 (will assume that
T6 and T7 have a similar problem). All three tests uses list containers.
oprofpp --smart-demangle -l -r -k
/dunes/wcohen/gcc/gcc-current/obj/i686-pc-linux-gnu/libstdc++-v3/testsuite/producer_consumer.cc-TEST_T5|more
Cpu type: PIII
Cpu speed was (MHz estimation) : 731.49
Counter 0 counted CPU_CLK_UNHALTED events (clocks processor is not
halted) with
a unit mask of 0x00 (No unit mask) count 365500
vma samples % symbol name image name
0804a660 14987420 99.8996 Queue<__gnu_norm::list<int,
__gnu_cxx::malloc_allocator<int>>>::push_back(int const&)
/dunes/wcohen/gcc/gcc-current/obj/i686-pc-linux-gnu/libstdc++-v3/testsuite/producer_consumer.cc-TEST_T5
00070a80 5826 0.0388336 __malloc /lib/tls/libc-2.3.2.so
00071690 1599 0.0106582 _int_malloc /lib/tls/libc-2.3.2.so
000068f0 1457 0.00971173 __pthread_mutex_unlock_usercnt
/lib/tls/libpthread-0.60.so
00006970 1289 0.00859191 __pthread_mutex_unlock_internal
/lib/tls/libpthread-0.60.so
00006700 1146 0.00763874 __pthread_mutex_lock_internal
/lib/tls/libpthread-0.60.so
0804a6f0 907 0.00604567 ProducerConsumer<__gnu_norm::list<int,
__gnu_cxx::malloc_allocator<int>>>::operator()()
/dunes/wcohen/gcc/gcc-current/obj/i686-pc-linux-gnu/libstdc++-v3/testsuite/producer_consumer.cc-TEST_T5
...
What is going on in push_back()? 99.9% of the runtime in that one
function certinaly does not look normal. Below is the annotation of
the assembly code for the problem funtion. There is a very tight loop
in the code (804a6b0 to 804a6b8) that has the vast majority of the samples.
Extracted annotated assembly language from output of:
op_to_source -a
/dunes/wcohen/gcc/gcc-current/obj/i686-pc-linux-gnu/libstdc++-v3/testsuite/producer_consumer.cc-TEST_T5
> /tmp/T5.anna
0804a660
<_ZN5QueueIN10__gnu_norm4listIiN9__gnu_cxx16malloc_allocatorIiEEEEE9push_backERKi>:
/*
_ZN5QueueIN10__gnu_norm4listIiN9__gnu_cxx16malloc_allocatorIiEEEEE9push_backERKi
total: 14987420 99.98% */
9 0.000% : 804a660: push %ebp
25 0.000% : 804a661: mov %esp,%ebp
: 804a663: push %esi
9 0.000% : 804a664: push %ebx
5 0.000% : 804a665: sub $0x30,%esp
: 804a668: mov 0x8(%ebp),%esi
7 0.000% : 804a66b: lea 0x30(%esi),%eax
: 804a66e: lea 0x48(%esi),%ebx
: 804a671: mov %eax,0xffffffe8(%ebp)
2 0.000% : 804a674: mov %eax,(%esp,1)
13 0.000% : 804a677: call 80495a8 <_init+0x188>
10 0.000% : 804a67c: mov %ebx,0x8(%esp,1)
1 0.000% : 804a680: mov 0xc(%ebp),%eax
5 0.000% : 804a683: lea 0xffffffe4(%ebp),%edx
: 804a686: mov %ebx,0x4(%esp,1)
23 0.000% : 804a68a: mov %edx,(%esp,1)
6 0.000% : 804a68d: mov %eax,0xc(%esp,1)
8 0.000% : 804a691: call 804a610
<_ZN10__gnu_norm4listIiN9__gnu_cxx16malloc_allocatorIiEEE6insertENS_14_List_iteratorIiEERKi>
30 0.000% : 804a696: mov 0x48(%esi),%eax
: 804a699: sub $0x4,%esp
: 804a69c: xor %edx,%edx
7 0.000% : 804a69e: mov %eax,0xffffffe0(%ebp)
3 0.000% : 804a6a1: cmp %ebx,%eax
7 0.000% : 804a6a3: je 804a6bd
<_ZN5QueueIN10__gnu_norm4listIiN9__gnu_cxx16malloc_allocatorIiEEEEE9push_backERKi+0x5d>
: 804a6a5: lea 0x0(%esi,1),%esi
: 804a6a9: lea 0x0(%edi,1),%edi
19334 0.128% : 804a6b0: mov (%eax),%eax
14557564 97.12% : 804a6b2: inc %edx
76 0.000% : 804a6b3: cmp %ebx,%eax
409243 2.730% : 804a6b5: mov %eax,0xffffffe0(%ebp)
102 0.000% : 804a6b8: jne 804a6b0
<_ZN5QueueIN10__gnu_norm4listIiN9__gnu_cxx16malloc_allocatorIiEEEEE9push_backERKi+0x50>
3 0.000% : 804a6ba: dec %edx
58 0.000% : 804a6bb: je 804a6e5
<_ZN5QueueIN10__gnu_norm4listIiN9__gnu_cxx16malloc_allocatorIiEEEEE9push_backERKi+0x85>
11 0.000% : 804a6bd: mov 0xffffffe8(%ebp),%eax
779 0.005% : 804a6c0: mov %eax,(%esp,1)
33 0.000% : 804a6c3: call 8049718 <_init+0x2f8>
32 0.000% : 804a6c8: lea 0xfffffff8(%ebp),%esp
: 804a6cb: pop %ebx
3 0.000% : 804a6cc: pop %esi
1 0.000% : 804a6cd: pop %ebp
11 0.000% : 804a6ce: ret
: 804a6cf: nop
: 804a6d0: mov %eax,%ebx
: 804a6d2: mov 0xffffffe8(%ebp),%eax
: 804a6d5: mov %eax,(%esp,1)
: 804a6d8: call 8049718 <_init+0x2f8>
: 804a6dd: mov %ebx,(%esp,1)
: 804a6e0: call 80496f8 <_init+0x2d8>
: 804a6e5: mov %esi,(%esp,1)
: 804a6e8: call 80495e8 <_init+0x1c8>
: 804a6ed: jmp 804a6bd
<_ZN5QueueIN10__gnu_norm4listIiN9__gnu_cxx16malloc_allocatorIiEEEEE9push_backERKi+0x5d>
: 804a6ef: nop
Using a script from Benjamin Koznik to compile the code so I get the
matching processed c++ code (and assembly language) of producer_consumer.cc:
COMP.sh "-O2 -save-temps -g -DTEST_T5" producer_consumer.cc >& problems
I think the following code in the producer_consumer.ii results in the
assembly language above:
template<typename Container>
void
Queue<Container>::push_back(const typename Container::value_type& value)
{
AutoLock auto_lock(lock);
queue.insert(queue.end(), value);
if (queue.size() == 1) pthread_cond_signal(&condition);
}
It looks like something is going wrong when there two real processors
running the code. Both threads can be active.
-Will
More information about the Libstdc++
mailing list