lock contention - what can we do about it?

[Milian Wolff]

On Saturday 05 March 2011 20:24:33 Milian Wolff wrote:
> Milian Wolff, 05.03.2011:
> > David Nolden, 05.03.2011:
> > > If the CPU time is below 100%, then that's for sure not due to lock
> > > contention, but simply due to I/O. Either repeat the test with the
> > > disk-cache better filled, or increase the number of threads.
> > 
> > If that would be the case, wouldn't iotop show lots of disk access? And
> > top's %wa would be high, but it's rarely more than 2% for me (wa is
> > iowait time).
> 
> also interesting:
> 
> top -p $(pidof duchainify) -H # -H for per-thread numbers
> 
>   PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
> 26756 milian    20   0  463m 107m  31m S   38  2.7   0:41.51 duchainify
> 26757 milian    20   0  463m 107m  31m S   32  2.7   0:33.79 duchainify
> 26747 milian    20   0  463m 107m  31m S    0  2.7   0:00.90 duchainify
> 26748 milian    20   0  463m 107m  31m S    0  2.7   0:00.00 duchainify
> 26749 milian    20   0  463m 107m  31m S    0  2.7   0:00.00 duchainify
> 26750 milian    20   0  463m 107m  31m S    0  2.7   0:00.00 duchainify
> 26751 milian    20   0  463m 107m  31m S    0  2.7   0:00.00 duchainify
> 
> instead of both at leas near 50% (better yet 100%)
> 
> I still think this is lock contention. how can we make sure?

I've tried mutrace now but that doesn't tell me much.... if i sum the 
contention totals and divide it by the total time spent, I'm at nearly 1% 
only. either that tool is wrong (see the warnings) or kdev really has other 
problems preventing proper cpu utilization

mutrace: Showing statistics for process duchainify (pid 28816).
mutrace: 25798 mutexes used.

Mutex #16632 (0x0x1136d50) first referenced by:
        mutrace.c:932   pthread_mutex_init()
        ??:0    QThreadStorageData::~QThreadStorageData()

Mutex #521 (0x0x7f334567aaa0) first referenced by:
        mutrace.c:1062  pthread_mutex_timedlock()
        foregroundlock.cpp:69   SimplePThreadMutex::tryLock()
        foregroundlock.cpp:115  (anonymous 
namespace)::tryLockForegroundMutexInternal()
        foregroundlock.cpp:157  KDevelop::ForegroundLock::relock()
        foregroundlock.cpp:143  ForegroundLock()
        parsejob.cpp:221        KDevelop::ParseJob::readContents()
        preprocessjob.cpp:667   PreprocessJob::readContents()
        preprocessjob.cpp:231   PreprocessJob::run()
        ??:0    ThreadWeaver::Job::qt_metacall()

Mutex #22384 (0x0x7f333020b240) first referenced by:
        mutrace.c:932   pthread_mutex_init()
        ??:0    QThreadStorageData::~QThreadStorageData()

Mutex #16195 (0x0x11367d0) first referenced by:
        mutrace.c:932   pthread_mutex_init()
        ??:0    QThreadStorageData::~QThreadStorageData()

Mutex #16858 (0x0xfc3e88) first referenced by:
        mutrace.c:1034  pthread_mutex_lock()
        ??:0    g_main_context_acquire()

Mutex #5676 (0x0x7f3330002de0) first referenced by:
        mutrace.c:932   pthread_mutex_init()
        ??:0    QThreadStorageData::~QThreadStorageData()

Mutex #18539 (0x0xf8a8c0) first referenced by:
        mutrace.c:1034  pthread_mutex_lock()
        ??:0    QWaitCondition::wait()

Mutex #3762 (0x0xf58a00) first referenced by:
        mutrace.c:1034  pthread_mutex_lock()
        ??:0    QWaitCondition::wait()

Mutex #3621 (0x0x10566d0) first referenced by:
        mutrace.c:932   pthread_mutex_init()
        ??:0    QThreadStorageData::~QThreadStorageData()

Mutex #5477 (0x0x7f3330002b80) first referenced by:
        mutrace.c:932   pthread_mutex_init()
        ??:0    QThreadStorageData::~QThreadStorageData()

mutrace: Showing 10 most contended mutexes:

 Mutex #   Locked  Changed    Cont. tot.Time[ms] avg.Time[ms] max.Time[ms]  
Flags
   16632  1846659   327064   173040     2537.984        0.001        5.196 
M-.--.
     521    25116    15901     9916     1754.294        0.070       34.937 
M!.--.
   22384    35298     7772     6046       48.711        0.001        0.676 
M-.--.
   16195   146484     7853     4247      185.195        0.001        6.809 
M-.--.
   16858   204715    21709     3901     3195.062        0.016       18.827 
M-.--.
    5676    60386     8394     3069       80.883        0.001        4.159 
M-.--.
   18539     9818     7938     2231       32.200        0.003        1.996 
M-.--.
    3762    21312    18069     1706       82.479        0.004        1.313 
M-.--.
    3621     4159      881      441        5.758        0.001        0.020 
Mx.--.
    5477     1487      462      291        2.050        0.001        0.013 
M-.--.
     ...      ...      ...      ...          ...          ...          ... 
||||||
                                                                           /|||||
          Object:                                     M = Mutex, W = RWLock 
/||||
           State:                                 x = dead, ! = inconsistent 
/|||
             Use:                                 R = used in realtime thread 
/||
      Mutex Type:                 r = RECURSIVE, e = ERRRORCHECK, a = ADAPTIVE 
/|
  Mutex Protocol:                                      i = INHERIT, p = 
PROTECT /
     RWLock Kind: r = PREFER_READER, w = PREFER_WRITER, W = 
PREFER_WRITER_NONREC 

mutrace: Note that the flags column R is only valid in --track-rt mode!

mutrace: Total runtime is 153297.942 ms.

mutrace: Results for SMP with 2 processors.

mutrace: WARNING: 25113 inconsistent mutex uses detected. Results might not be 
reliable.
mutrace:          Fix your program first!

mutrace: WARNING: 2395 internal hash collisions detected. Results might not be 
as reliable as they could be.
mutrace:          Try to increase --hash-size=, which is currently at 10000.
-- 
Milian Wolff
mail at milianw.de
http://milianw.de
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 198 bytes
Desc: This is a digitally signed message part.
URL: <http://mail.kde.org/pipermail/kdevelop-devel/attachments/20110306/b9d8ed63/attachment-0001.sig>