On 10/03/12 11:10, Martin Sebor wrote:
[...]
I was just thinking of a few simple loops along the lines of:


tl;dr: I consider the results of the multi-threaded performance tests (12S, 
Intel/AMD multicores) as coming from heavy contention in copying of 
reference-counted std::string objects.

The long version: I went back to the original test case (attached, t.cpp). As a 
reminder, the program is a simplification of the library numpunct facet 
creation process, which can be compiled either with data caching enabled or 
disabled.

I ran the perf tool (https://perf.wiki.kernel.org/index.php/Main_Page) on the 
program, and I noticed marked differences in the number of instructions and 
cycles (an order of magnitude) and also in the number of CPU-migrations and 
context-switches (way larger for the cached version):

 Performance counter stats for './t':

      121168.026301  task-clock-msecs         #      3.778 CPUs
            6133377  context-switches         #      0.051 M/sec
              35457  CPU-migrations           #      0.000 M/sec
                298  page-faults              #      0.000 M/sec
       338006437277  cycles                   #   2789.568 M/sec
       136554855096  instructions             #      0.404 IPC
        31298346444  branches                 #    258.305 M/sec
         2305761092  branch-misses            #      7.367 %
         1592157186  cache-references         #     13.140 M/sec
            1729755  cache-misses             #      0.014 M/sec

       32.070381363  seconds time elapsed

vs.

 Performance counter stats for './t':

       16194.235282  task-clock-msecs         #      3.883 CPUs
               7491  context-switches         #      0.000 M/sec
                 47  CPU-migrations           #      0.000 M/sec
                311  page-faults              #      0.000 M/sec
        45210281987  cycles                   #   2791.752 M/sec
        76784904688  instructions             #      1.698 IPC
        18891711522  branches                 #   1166.570 M/sec
         3162251552  branch-misses            #     16.739 %
            3332839  cache-references         #      0.206 M/sec
             119424  cache-misses             #      0.007 M/sec

        4.170904279  seconds time elapsed


Then, I have run more detailed reports on the runs. I noticed that the report 
for the cached version contains what appears to be thread synchronization 
overhead, whereas the non-cached version doesn't:

# Events: 134K cycles
#
# Overhead  Command       Shared Object                               Symbol
# ........  .......  ..................  ...................................
#
    50.69%        t  [kernel.kallsyms]   [k] _raw_spin_lock
     5.46%        t  libpthread-2.13.so  [.] pthread_mutex_lock
     4.16%        t  libpthread-2.13.so  [.] __pthread_mutex_unlock
     3.65%        t  libpthread-2.13.so  [.] __lll_lock_wait
     3.35%        t  [kernel.kallsyms]   [k] copy_user_generic_string
     3.09%        t              40395b  [.]           40395b
     2.91%        t  [kernel.kallsyms]   [k] hash_futex
     2.87%        t  [kernel.kallsyms]   [k] futex_wake
     2.67%        t  t                   [.] f
     2.37%        t  [kernel.kallsyms]   [k] futex_wait_setup
     1.61%        t  [kernel.kallsyms]   [k] system_call
     1.00%        t  [kernel.kallsyms]   [k] system_call_after_swapgs
     0.98%        t  [kernel.kallsyms]   [k] __switch_to
     0.96%        t  libpthread-2.13.so  [.] __lll_unlock_wake
     0.95%        t  [kernel.kallsyms]   [k] get_futex_key
     0.92%        t  libc-2.13.so        [.] __strlen_sse42
     [...]


vs.


# Events: 15K cycles
#
# Overhead  Command       Shared Object                                         
                                                                                
 Symbol
# ........  .......  ..................  
..............................................................................................................................
#
    49.55%   :29571        7f1ed3830a86  [.]     7f1ed3830a86
     8.67%        t  libc-2.13.so        [.] __malloc
     8.03%        t  libc-2.13.so        [.] cfree
     4.88%        t  t                   [.] std::basic_string<char, std::char_traits<char>, 
std::allocator<char> >::basic_string(char const*, std::allocator<char> const&)
     4.67%        t  libc-2.13.so        [.] __strlen_sse42
     4.14%        t  libpthread-2.13.so  [.] __pthread_mutex_unlock
     3.62%        t  libpthread-2.13.so  [.] pthread_mutex_lock
     2.64%        t  t                   [.] f
     2.40%        t  libc-2.13.so        [.] _int_malloc
     2.10%        t  libc-2.13.so        [.] _int_free
     1.53%        t  libpthread-2.13.so  [.] __pthread_mutex_init_internal
     1.33%        t  t                   [.] operator new(unsigned long)
     1.08%        t  t                   [.] X::numpunct::do_grouping() const
     1.04%        t  libc-2.13.so        [.] __memcpy_sse2
     0.89%        t  t                   [.] X::get_data(X::facet*)
     0.51%        t  t                   [.] __rw::__rw_allocate(unsigned long, 
int)
     0.45%        t  t                   [.] strlen@plt
     0.33%        t  t                   [.] __rw::__rw_deallocate(void*, 
unsigned long, int)
     0.32%        t  libpthread-2.13.so  [.] pthread_mutex_destroy
     0.21%        t  t                   [.] pthread_mutex_unlock@plt
     0.21%        t  t                   [.] pthread_mutex_init@plt
     0.18%        t  t                   [.] pthread_mutex_destroy@plt
     0.17%        t  t                   [.] operator delete(void*)
     0.17%        t  t                   [.] malloc@plt
     0.16%        t  t                   [.] memcpy@plt
     0.15%   :29571  [kernel.kallsyms]   [k] hpet_msi_next_event
     0.12%        t  libc-2.13.so        [.] __strrchr_sse2
     0.12%        t  t                   [.] pthread_mutex_lock@plt
     0.11%        t  t                   [.] free@plt
     [...]


Now, if you remember from previous measurements, the performance of the two 
versions of the program was reversed for the case of one thread, i.e., 
one-threaded programs performed better in the cached version. Here is the 
report for a run with one thread, the cached version (running one thread in 
1000M loops, otherwise it does not register anything):

# Events: 36K cycles
#
# Overhead  Command       Shared Object                    Symbol
# ........  .......  ..................  ........................
#
    37.68%        t  libpthread-2.13.so  [.] __pthread_mutex_unlock
    31.04%        t  libpthread-2.13.so  [.] pthread_mutex_lock
    11.87%        t  t                   [.] f
     9.64%   :27362        7fd94e2ebd6d  [.]     7fd94e2ebd6d
     3.21%        t  libc-2.13.so        [.] __strlen_sse42
     2.38%        t  t                   [.] pthread_mutex_unlock@plt
     2.27%        t  t                   [.] pthread_mutex_lock@plt
     1.61%        t  t                   [.] strlen@plt
     [...]

The one-threaded run for the non-cached version yields a report identical with 
the multi-threaded run.


There are two things which I take from this round of measurements: first, that 
performance suffers on multicores in heavy contention, possibly as a direct 
result of std::string object copying and I'll follow up with direct 
measurements. Second, that perhaps we should not focus on this particular use 
model for the numpunct facet, because it may not be very representative for 
`normal' usage.


HTH

Liviu
* With caching

** Stats counters

*** Contended run 

16, 10000000

 Performance counter stats for './t':

      121168.026301  task-clock-msecs         #      3.778 CPUs 
            6133377  context-switches         #      0.051 M/sec
              35457  CPU-migrations           #      0.000 M/sec
                298  page-faults              #      0.000 M/sec
       338006437277  cycles                   #   2789.568 M/sec
       136554855096  instructions             #      0.404 IPC  
        31298346444  branches                 #    258.305 M/sec
         2305761092  branch-misses            #      7.367 %    
         1592157186  cache-references         #     13.140 M/sec
            1729755  cache-misses             #      0.014 M/sec

       32.070381363  seconds time elapsed

** Report

# Events: 134K cycles
#
# Overhead  Command       Shared Object                               Symbol
# ........  .......  ..................  ...................................
#
    50.69%        t  [kernel.kallsyms]   [k] _raw_spin_lock
     5.46%        t  libpthread-2.13.so  [.] pthread_mutex_lock
     4.16%        t  libpthread-2.13.so  [.] __pthread_mutex_unlock
     3.65%        t  libpthread-2.13.so  [.] __lll_lock_wait
     3.35%        t  [kernel.kallsyms]   [k] copy_user_generic_string
     3.09%        t              40395b  [.]           40395b
     2.91%        t  [kernel.kallsyms]   [k] hash_futex
     2.87%        t  [kernel.kallsyms]   [k] futex_wake
     2.67%        t  t                   [.] f
     2.37%        t  [kernel.kallsyms]   [k] futex_wait_setup
     1.61%        t  [kernel.kallsyms]   [k] system_call
     1.00%        t  [kernel.kallsyms]   [k] system_call_after_swapgs
     0.98%        t  [kernel.kallsyms]   [k] __switch_to
     0.96%        t  libpthread-2.13.so  [.] __lll_unlock_wake
     0.95%        t  [kernel.kallsyms]   [k] get_futex_key
     0.92%        t  libc-2.13.so        [.] __strlen_sse42
     [...]

*** Uncontended run 

1, 100000000

# Events: 3K cycles
#
# Overhead  Command      Shared Object                 Symbol
# ........  .......  .................  .....................
#
    99.35%   :15870       7f082cdda456  [.]     7f082cdda456
     0.46%        t  [kernel.kallsyms]  [k] recalc_sigpending_tsk
     0.19%   :15870  [kernel.kallsyms]  [k] hpet_msi_next_event
     0.01%        t  [kernel.kallsyms]  [k] __free_pipe_info
     0.00%        t  [kernel.kallsyms]  [k] intel_pmu_enable_all


* Without caching

** Stats counters

16, 10000000

 Performance counter stats for './t':

       16194.235282  task-clock-msecs         #      3.883 CPUs 
               7491  context-switches         #      0.000 M/sec
                 47  CPU-migrations           #      0.000 M/sec
                311  page-faults              #      0.000 M/sec
        45210281987  cycles                   #   2791.752 M/sec
        76784904688  instructions             #      1.698 IPC  
        18891711522  branches                 #   1166.570 M/sec
         3162251552  branch-misses            #     16.739 %    
            3332839  cache-references         #      0.206 M/sec
             119424  cache-misses             #      0.007 M/sec

        4.170904279  seconds time elapsed

** Report

# Events: 15K cycles
#
# Overhead  Command       Shared Object                                         
                                                                                
 Symbol
# ........  .......  ..................  
..............................................................................................................................
#
    49.55%   :29571        7f1ed3830a86  [.]     7f1ed3830a86
     8.67%        t  libc-2.13.so        [.] __malloc
     8.03%        t  libc-2.13.so        [.] cfree
     4.88%        t  t                   [.] std::basic_string<char, 
std::char_traits<char>, std::allocator<char> >::basic_string(char const*, 
std::allocator<char> const&)
     4.67%        t  libc-2.13.so        [.] __strlen_sse42
     4.14%        t  libpthread-2.13.so  [.] __pthread_mutex_unlock
     3.62%        t  libpthread-2.13.so  [.] pthread_mutex_lock
     2.64%        t  t                   [.] f
     2.40%        t  libc-2.13.so        [.] _int_malloc
     2.10%        t  libc-2.13.so        [.] _int_free
     1.53%        t  libpthread-2.13.so  [.] __pthread_mutex_init_internal
     1.33%        t  t                   [.] operator new(unsigned long)
     1.08%        t  t                   [.] X::numpunct::do_grouping() const
     1.04%        t  libc-2.13.so        [.] __memcpy_sse2
     0.89%        t  t                   [.] X::get_data(X::facet*)
     0.51%        t  t                   [.] __rw::__rw_allocate(unsigned long, 
int)
     0.45%        t  t                   [.] strlen@plt
     0.33%        t  t                   [.] __rw::__rw_deallocate(void*, 
unsigned long, int)
     0.32%        t  libpthread-2.13.so  [.] pthread_mutex_destroy
     0.21%        t  t                   [.] pthread_mutex_unlock@plt
     0.21%        t  t                   [.] pthread_mutex_init@plt
     0.18%        t  t                   [.] pthread_mutex_destroy@plt
     0.17%        t  t                   [.] operator delete(void*)
     0.17%        t  t                   [.] malloc@plt
     0.16%        t  t                   [.] memcpy@plt
     0.15%   :29571  [kernel.kallsyms]   [k] hpet_msi_next_event
     0.12%        t  libc-2.13.so        [.] __strrchr_sse2
     0.12%        t  t                   [.] pthread_mutex_lock@plt
     0.11%        t  t                   [.] free@plt
     [...]
#include <iostream>
#include <locale>

#include <cstdio>
#include <cstdlib>
#include <cstring>

#include <pthread.h>
#include <unistd.h>

#define MAX_THREADS 128

static long nloops = 10000000, nthreads = 16;
static bool volatile pwait = true;

////////////////////////////////////////////////////////////////////////

namespace X {

struct guard 
{
    guard (pthread_mutex_t* ptr) : lock_ (ptr) { 
        pthread_mutex_lock (lock_);
    }

    ~guard () { 
        pthread_mutex_unlock (lock_); 
    }

private:

    guard (guard const&);
    guard& operator= (guard const&);

private:

    pthread_mutex_t* lock_;
};

struct facet
{
    facet () {
        pthread_mutex_init (&_C_mutex, 0);
    }

    void* _C_data () {
        return _C_impsize ? _C_impdata : _C_get_data ();
    }

    void* _C_get_data ();

    size_t _C_impsize;
    void*  _C_impdata;

    pthread_mutex_t _C_mutex;
};

void* facet::_C_get_data ()
{
    if (_C_impsize)
        return _C_impdata;

    guard g (&_C_mutex);

    if (_C_impsize)
        return _C_impdata;

#if !defined (NO_STDCXX_LOCALES)
    _C_impdata = (void*)"\3\3";
#endif // NO_STDCXX_LOCALES
    _C_impsize = (size_t)(-1);

    return _C_impdata;
}

void* get_data (facet*);

struct numpunct : facet
{
    numpunct () : _C_flags () { }

    virtual std::string do_grouping () const;

    std::string grouping () const {
        numpunct* const __self = const_cast< numpunct* > (this);

#if !defined (NO_CACHE)
        if (!(_C_flags & 1)) {
            __self->_C_flags  |= 1;
            __self->_C_grouping = do_grouping ();
        }

        return _C_grouping;
#else
        return do_grouping ();
#endif // NO_CACHE
    }

private:

    int          _C_flags;
    std::string  _C_grouping;
};

std::string numpunct::do_grouping () const
{
    return (const char*)get_data (const_cast<numpunct*>(this));
}

void* get_data (facet* pfacet)
{
    void* pdata = pfacet->_C_data ();

    if (pdata) 
        return pdata;

    // __rw_setlocale loc (...); <- other mutex

    if (pfacet->_C_data ())
        return get_data (pfacet);

    pfacet->_C_impdata = const_cast<char*>("\4\4");
    pfacet->_C_impsize = (size_t)(-1);

    return 0;
}

} // namespace X

////////////////////////////////////////////////////////////////////////

typedef X::numpunct Numpunct;

extern "C" {

static void* 
f (void* pv)
{
    Numpunct const& fac = *reinterpret_cast< Numpunct* > (pv);

    volatile unsigned long n = 0;

    while (pwait) ;
    
    for (int i = 0; i < nloops; ++i) {
        const std::string grouping = fac.grouping ();
        n += strlen (grouping.c_str ());
    }

    return (void*)n;
}

} // extern "C"

int
main (int argc, char** argv)
{
    switch (argc) {
    case 3:
        nloops = atol (argv [2]);
    case 2:
        nthreads = atol (argv [1]);
        break;
    }

    pthread_t tid [MAX_THREADS] = { 0 };

    if (nthreads > MAX_THREADS)
        nthreads = MAX_THREADS;

    printf ("%ld, %ld\n", nthreads, nloops);

    pthread_setconcurrency (nthreads);

    Numpunct fac;
    fac.grouping ();
    
    for (int i = 0; i < nthreads; ++i) {
        if (pthread_create (tid + i, 0, f, const_cast<Numpunct*> (&fac)))
            exit (-1);
    }

    usleep (50);
    pwait = false;

    for (int i = 0; i < nthreads; ++i) {
        if (tid [i])
            pthread_join (tid [i], 0);
    }

    return 0;
}

Reply via email to