【问题标题】:Measuring mutex contention / interpreting mutrace output测量互斥量争用/解释 mutrace 输出
【发布时间】:2012-07-27 23:21:33
【问题描述】:

我正在尝试使用 mutrace 在我的程序中测量互斥量争用,但我不知道如何使用它输出的报告。

mutrace: Showing statistics for process test (PID: 5924).
mutrace: 1223 mutexes used.

Mutex #362 (0x0x1a23750) first referenced by:
        /usr/local/lib/libmutrace.so(pthread_mutex_init+0x1b2) [0x7fb6b14129b4]
        ./test() [0x500042]

Mutex #390 (0x0x1a23ac0) first referenced by:
        /usr/local/lib/libmutrace.so(pthread_mutex_init+0x1b2) [0x7fb6b14129b4]
        ./test() [0x500042]

Mutex #965 (0x0x1a3a600) first referenced by:
        /usr/local/lib/libmutrace.so(pthread_mutex_init+0x1b2) [0x7fb6b14129b4]
        ./test() [0x500042]

Mutex #502 (0x0x1abbc90) first referenced by:
        /usr/local/lib/libmutrace.so(pthread_mutex_init+0x1b2) [0x7fb6b14129b4]
        ./test() [0x500042]

Mutex #241 (0x0x7fb6af9019c0) first referenced by:
        /usr/local/lib/libmutrace.so(pthread_mutex_lock+0x116) [0x7fb6b1412da6]
        /lib/libgcc_s.so.1(_Unwind_Find_FDE+0x2a) [0x7fb6af6fe3ea]
        [(nil)]

Mutex #704 (0x0x7fb6afe85020) first referenced by:
        /usr/local/lib/libmutrace.so(pthread_mutex_lock+0x116) [0x7fb6b1412da6]
        /usr/lib/libstdc++.so.6(_ZNSt6localeC1Ev+0x2f) [0x7fb6afbf021f]

Mutex #452 (0x0x1a240b0) first referenced by:
        /usr/local/lib/libmutrace.so(pthread_mutex_init+0x1b2) [0x7fb6b14129b4]
        ./test() [0x500042]

Mutex #981 (0x0x1a3a770) first referenced by:
        /usr/local/lib/libmutrace.so(pthread_mutex_init+0x1b2) [0x7fb6b14129b4]
        ./test() [0x500042]

Mutex #626 (0x0x73daa8) first referenced by:
        /usr/local/lib/libmutrace.so(pthread_mutex_init+0x1b2) [0x7fb6b14129b4]
        ./test(_ZN7threads5mutexC2Eb+0x5e) [0x50675e]

Mutex #801 (0x0x1ab6798) first referenced by:
        /usr/local/lib/libmutrace.so(pthread_mutex_init+0x1b2) [0x7fb6b14129b4]
        ./test(_ZN7threads5mutexC1Eb+0x5e) [0x50643e]

mutrace: Showing 10 mutexes in order of (write) contention count:

 Mutex #   Locked  Changed    Cont. cont.Time[ms] tot.Time[ms] avg.Time[ms] Flags
     362   517216   163871    70638       619.184      138.933        0.000 M-.--.
     390   180589    61197    31681      5926.827      463.255        0.003 M-.--.
     965    38679    24052    10646       661.639      718.836        0.019 M-.--.
     502    35394    19012     1540       153.286      134.116        0.004 M-.--.
     241     3481     2715     1378       135.624        1.189        0.000 M-.--.
     704    20902     3879       70         0.594        6.702        0.000 M-.--.
     452      892      158       49        21.401      125.918        0.141 M-.--.
     981     2369     2361       12         0.229       12.984        0.005 M-.--.
     626      598      270        4         0.139        8.417        0.014 Mx.r-.
     801      125        2        1         0.012        0.270        0.002 Mx.r-.
     ...      ...      ...      ...           ...          ...          ... ||||||
                                                                            /|||||
          Object:                                      M = Mutex, W = RWLock /||||
           State:                                  x = dead, ! = inconsistent /|||
             Use:                                  R = used in realtime thread /||
      Mutex Type:                   r = RECURSIVE, e = ERRORCHECK, a = ADAPTIVE /|
  Mutex Protocol:                                       i = INHERIT, p = PROTECT /
     RWLock Kind:  r = PREFER_READER, w = PREFER_WRITER, W = PREFER_WRITER_NONREC 

mutrace: Note that rwlocks are shown as two lines: write locks then read locks.

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

mutrace: 275 condition variables used.

Condvar #235 (0x0x7fb6a039d5c8) first referenced by:
        /usr/local/lib/libmutrace.so(pthread_cond_init+0x120) [0x7fb6b14134be]
        ./test(_ZN7threads4condC1Ev+0x17) [0x5051b7]

Condvar #153 (0x0x7fb6a8259978) first referenced by:
        /usr/local/lib/libmutrace.so(pthread_cond_init+0x120) [0x7fb6b14134be]
        ./test(_ZN7threads4condC1Ev+0x17) [0x5051b7]

Condvar #42 (0x0x7fb6a03e8188) first referenced by:
        /usr/local/lib/libmutrace.so(pthread_cond_init+0x120) [0x7fb6b14134be]
        ./test(_ZN7threads4condC1Ev+0x17) [0x5051b7]

Condvar #222 (0x0x7fb6a019b7c8) first referenced by:
        /usr/local/lib/libmutrace.so(pthread_cond_init+0x120) [0x7fb6b14134be]
        ./test(_ZN7threads4condC1Ev+0x17) [0x5051b7]

Condvar #118 (0x0x7fb6a0223ca8) first referenced by:
        /usr/local/lib/libmutrace.so(pthread_cond_init+0x120) [0x7fb6b14134be]
        ./test(_ZN7threads4condC1Ev+0x17) [0x5051b7]

Condvar #8 (0x0x7fb6a820d748) first referenced by:
        /usr/local/lib/libmutrace.so(pthread_cond_init+0x120) [0x7fb6b14134be]
        ./test(_ZN7threads4condC1Ev+0x17) [0x5051b7]

Condvar #171 (0x0x7fb69c04d9d8) first referenced by:
        /usr/local/lib/libmutrace.so(pthread_cond_init+0x120) [0x7fb6b14134be]
        ./test(_ZN7threads4condC1Ev+0x17) [0x5051b7]

Condvar #0 (0x0x7fb69c22a2e8) first referenced by:
        /usr/local/lib/libmutrace.so(pthread_cond_init+0x120) [0x7fb6b14134be]
        ./test(_ZN7threads4condC1Ev+0x17) [0x5051b7]

Condvar #75 (0x0x7fb6a81a65f8) first referenced by:
        /usr/local/lib/libmutrace.so(pthread_cond_init+0x120) [0x7fb6b14134be]
        ./test(_ZN7threads4condC1Ev+0x17) [0x5051b7]

Condvar #142 (0x0x7fb6a001c308) first referenced by:
        /usr/local/lib/libmutrace.so(pthread_cond_init+0x120) [0x7fb6b14134be]
        ./test(_ZN7threads4condC1Ev+0x17) [0x5051b7]

mutrace: Showing 10 condition variables in order of wait contention count:

  Cond #    Waits  Signals    Cont. tot.Time[ms] cont.Time[ms] avg.Time[ms] Flags
     235      271        0        0     1370.469         0.000        0.000     x.
     153      190        0        0      960.142         0.000        0.000     x.
      42       65        0        0      328.264         0.000        0.000     x.
     222       52        0        0      262.584         0.000        0.000     x.
     118       51        0        0      261.869         0.000        0.000     x.
       8       48        0        0      242.422         0.000        0.000     x.
     171       41        0        0      207.044         0.000        0.000     x.
       0       38        0        0      191.881         0.000        0.000     x.
      75       37        0        0      186.835         0.000        0.000     x.
     142       35        0        0      176.704         0.000        0.000     x.
     ...      ...      ...      ...          ...           ...          ...     ||
                                                                                /|
           State:                                     x = dead, ! = inconsistent /
             Use:                                     R = used in realtime thread 

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

mutrace: Total runtime is 3701.228 ms.

mutrace: Results for SMP with 8 processors.

看来我肯定有互斥争用问题,但我不知道如何将其与我的源代码相关联。我希望有比这更好的回溯。

已根据 mutrace 的网站使用 -rdynamic 编译了可执行文件(以及 -g -gdb 也是)。

我在 stackoverflow 上发现了 mutrace,所以希望有一些有经验的人!

谢谢。

【问题讨论】:

  • 短版:遍历输出中出现的每个互斥锁。考虑一下该互斥体的作用以及您可以合理预期的争用量。对于任何显示比您合理预期的更多争用的互斥锁,请确定该争用是否重要,如果是,请分析该互斥锁的使用情况,看看是否有一些简单的方法可以最大限度地减少争用。
  • 是的,但是使用如此有限的回溯,我如何确定哪个互斥锁是哪个?显然它正在使用地址,但这不是我以前必须做的事情。我该怎么办?
  • 我不确定你为什么得到如此有限的回溯。最坏的情况是,您可以添加代码来记录互斥锁的地址。

标签: c++ multithreading profiling pthreads contention


【解决方案1】:

从未使用过 mutrace,但可以通过以下方式完成地址到符号的转换: addr2line

例如:

addr2line -e sysopview 0x5051b7

在此示例中,“sysopview”是地址应该位于的二进制文件的路径,0x5051b7 是示例地址。然后 Addr2line 将发出它认为应该映射到它的名称。也适用于回溯。

示例输出:

folkert@belle:~/Projects/entropybroker/trunk$ addr2line -e ./entropy_broker 0x0000000000406968 /home/folkert/Projects/entropybroker/trunk/handle_client.cpp:761

在本例中,地址 0x406968 映射到文件 handle_client.cpp 的第 761 行。

在 Debian 上,这个程序可以在“binutils”包中找到。

【讨论】:

    【解决方案2】:

    我在我的发布版本中保留了调试标志,所以 -g -gdb -rdynamic 都启用了。我想这会没事的。切换回我的调试版本后,删除 -O2 使回溯更加有用。仍然损坏,但好多了。

    我发现我所有争用最高的互斥锁都用于 gnutls 使用的 gcrypt 库中的同步。可能必须进行试验,看看是否回到 openssl 可以改善它,或者可能是 cyassl!

    谢谢。

    【讨论】:

    • 确实删除优化(即使用 -O0)使堆栈跟踪更加“冗长”
    猜你喜欢
    • 1970-01-01
    • 2010-11-17
    • 2012-09-01
    • 2016-08-30
    • 2023-03-24
    • 1970-01-01
    • 1970-01-01
    • 1970-01-01
    • 2012-05-07
    相关资源
    最近更新 更多