 |
| Взято тут. |
Для вирішення описаних раніше задач (та багато яких інших!) існує ряд
хороших готових інструментів. З тих чи інших причин вони для задачі, згаданої в попередньому пості, не підходять, зокрема -- через складність автоматизації і не
завжди присутню можливість фіксувати фрагменти коду, що досліджуються. Але знати про них слід -- вони дозволяють детально, іноді -- майже інтерактивно, подивитися, як паралельна програма функціонує. Та й автоматизація, в принципі, можлива.
MS Windows - Concurrency Visualizer
Інструмент, власне, візуалізації роботи багатопоточної програми. Може використовуватися як додаток до Visual Studio або самостійно.
- Інсталяція: "Concurrency Visualizer для Visual Studio 2015".
- Використання консольних утиліт: "Concurrency Visualizer Command-Line Utility (CVCollectionCmd)".
- Використання GUI Visual Studio 2015: "Profiling an application with Visual Studio – Concurrency"
Приклад
Не
маючи можливості писати детальний огляд, розгляну використання
GUI-інтерфейсу разом із Visual Studio 2015 на прикладі наступної
програми (поточний її код -- тут, правда, з того часу він не раз змінювався):
- Один потік читає дисковий файл, кладе блоки в чергу (id 3084 на скрішнотах нижче).
- Три потоки беруть блоки із неї, опрацьовують їх, кладуть результат в іншу чергу.
- Ще один потік (насправді, головний потік програми -- Main Thread) бере їх звідти і об'єднує для отримання кінцевого результату.
Відкриваємо проект, обираємо Start with Current Project:
 |
| (клікабельно) |
Чекаємо, поки програма відпрацює. Іноді -- довго, працюватиме вона помітно повільніше, ніж без аналізу. Потребує багато оперативної пам'яті. Коли закінчили, побачимо, в якій мірі 4 фізичних ядра мого комп'ютера були зайняті роботою над над цією задачею:
На вкладці Cores можна побачити деталізацію по ядрах:
Внизу екрану показано, скільки переключень контексту відбулося, та скільки із них привели до зміни ядра, на якому потік виконувався. Дивно, чого потоки, (особливо -- той, що займається вводом-виводом, 3084), помітно мігрують між ядрами...
Діаграму
зайнятості ядер можна масштабувати, отримуючи внизу підсумок для тієї
частини виконання, що зараз вмістилася на екрані.
Однак, найцікавіше -- на середній вкладці, Threads:
 |
| Зелений -- потік виконується, червоний -- синхронізація, жовтий -- preemption, диспетчер забрав процесор в потоку. |
Перша ж діаграма,
"Per Thread Summery", містить дуже цінну інформацію -- видно, що
більшу частину часу потоки витрачають, очікуючи на мютекси та умовні
змінні (воно каже -- чекають на синхронізацію, що це саме
мютекси та умовні змінні знаю із власного коду :-). Жовтим показано
"preemption" -- час, поки потік взагалі не виконувався, бо диспетчер ОС
забрав у нього процесор -- ота систематична похибка, боротьбі із якою
присвячена помітна частина тексту попереднього поста.
Однак,
не всі ділянки програми нам цікаві -- вона спершу проводить
ініціалізацію, потім -- зберігає результат і виконує різноманітні
перевірки його правильності. Тому корисною буде можливість обмежити час аналізу -- нижня вкладка
дає підсумок для області, видимої у верхній. (Підхід трішки незвичний -- замість явно виділяти регіон, але якщо звикнути, виявився зручним).
Concurrency Visualizer підтримує відповідне API ("Concurrency Visualizer SDK"), яке дозволяє вставляти в код маркери, видимі візуалізатору:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 | #if defined _WIN32 && defined USE_WINDOWS_CONCURRENCY_VIS_FLAGS #include <cvmarkersobj.h> using namespace Concurrency::diagnostic; #endif ..................... #if defined _WIN32 && defined USE_WINDOWS_CONCURRENCY_VIS_FLAGS marker_series series; span *flagSpanStart = new span(series, 1, _T("Working")); //-V799 series.write_flag(_T("Working flag.")); #endif .......................... #if defined _WIN32 && defined USE_WINDOWS_CONCURRENCY_VIS_FLAGS span *flagSpanStartCounting = new span(series, 1, _T("Started counting")); //-V799 series.write_flag(_T("Started counting flag.")); #endif .......................... #if defined _WIN32 && defined USE_WINDOWS_CONCURRENCY_VIS_FLAGS span *flagSpanStartmergin = new span(series, 1, _T("Started merging")); //-V799 series.write_flag(_T("Started merging flag.")); #endif .......................... #if defined _WIN32 && defined USE_WINDOWS_CONCURRENCY_VIS_FLAGS delete flagSpanStart; delete flagSpanStartCounting; delete flagSpanStartmergin; #endif |
Щоб кодом вище можна було
скористатися, слід додати SDK до проекту: Analyze -> "Concurrency
Visualizer" -> "Add SDK to Project...". На загал, робота із ним виглядає так: створюється об'єкт marker_series, який займатиметься записом прапорців,
повідомлень, тощо. Тоді, створення прив'язаного до нього об'єкту span починає інтервал,
знищення -- закінчує. Детальніше див. "How To: Use the Concurrency Visualizer Markers SDK".
Тепер можна бачити таке:
Крім підсумку по потоках, можна побачити деталізацію, наприклад:
Але
перейдемо до верхньої частини -- вона, зазвичай, наочніша. Наблизимо сильно
сильно. Тоді, Disk Reads дає інформацію про ввід-вивід. Внизу видно, що
відбувається читання з файлу (ім'я можна побачити, розтягнувши
відповідне поле).
Дивлячись
на інші потоки, видно (1), що вони, після короткого спалаху активності,
чекають на дані для роботи (2), (очікування синхронізації для потоку
14188 всередині інтервалу 1 -- стосується нутрощів ядра), а головний
потік чекає на їх результати (3) і реагує на них (4):
Зокрема, можна побачити, як, за допомогою умовних змінних "перекидається м'яч" між потоками:
 |
| Чорна вертикальна риска -- виведена Concurrency Visualizer, показує пробудження потоку нотифікацією умовної змінної, на яку він чекав. Червона стрілочка і синя лінія -- намальовані мною. Зокрема, синя показує, як потік 3084 завершує читання (хвиляста частина), опрацьовує прочитане, перекидає потоку 13200, який, закінчивши власну обробку, передає результат головному потокові. |
І так далі і тому подібне. Корисний інструмент. :=)
Крім посилань вище див. також:
- Introducing the Concurrency Visualizer SDK
- Concurrency Visualizer SDK
- How To: Use the Concurrency Visualizer Markers SDK
- Parallel Diagnostic Tools (Concurrency Runtime)
MS Windows - Xperf
Трішки старішим інструментом, аналогічним до Concurrency Visualizer, є Xperf із Windows Performance Tools Kit.
Відстежування запускається та зупиняється вручну, отримується файл із розширенням etl, який потім можна "розглядати" у відповідному інструменті (для початку -- вибравши процес, що нас цікавить):
Детальніше див.:
Linux -- perf
Perf -- інструмент аналізу продуктивності Лінукс, фактично вбудований в ядро, але із user-space утилітою. :-) Не зважаючи на специфіку, підтримує багато апаратних архітектур, включаючи, але не обмежуючись, x86, ARM, PowerPC.
Вміє:
- Підраховувати різноманітні події -- від процесора, підсистем ядра, тощо, для даної програми чи цілої системи за якийсь проміжок часу. При чому -- кросплатформово. (Perf stat).
- Виводити інтерактивно найбільш використовувані функції, аналогічно як утиліта top робить із процесами. (perf top)
- Записувати виміри із вказаною частотою для програми (perf record) та аналізувати їх (perf report).
- Виводити інформацію про роботу диспетчера ОС.
- Багато чого іншого.
Як не дивно, підтримує Java (в сенсі, вміє видавати не тільки
інформацію про роботу JVM, але й про роботу програми, що ця віртуальна машина виконує)
та Node.js.
Для різноманітності, приклади нижче -- для Debian на Raspberry Pi 3 (ядро 4.9.35-v7+). ARMv8, 4 ядра.
Зауваження: Використання perf часто вимагає root-івських прав. Не завжди, але часто, подробиці -- див. посилання нижче.
Список подій, що вміє аналізувати на конкретній системі:
$ perf list branch-instructions OR branches [Hardware event] branch-misses [Hardware event] bus-cycles [Hardware event] cache-misses [Hardware event] cache-references [Hardware event] cpu-cycles OR cycles [Hardware event] instructions [Hardware event] alignment-faults [Software event] bpf-output [Software event] context-switches OR cs [Software event] cpu-clock [Software event] cpu-migrations OR migrations [Software event] .........skipped............... L1-dcache-load-misses [Hardware cache event] L1-dcache-loads [Hardware cache event] L1-dcache-store-misses [Hardware cache event] L1-dcache-stores [Hardware cache event] L1-icache-load-misses [Hardware cache event] L1-icache-loads [Hardware cache event] LLC-load-misses [Hardware cache event] LLC-loads [Hardware cache event] LLC-store-misses [Hardware cache event] LLC-stores [Hardware cache event] branch-load-misses [Hardware cache event] branch-loads [Hardware cache event] dTLB-load-misses [Hardware cache event] dTLB-store-misses [Hardware cache event] iTLB-load-misses [Hardware cache event] armv7_cortex_a7/br_immed_retired/ [Kernel PMU event] armv7_cortex_a7/br_mis_pred/ [Kernel PMU event] armv7_cortex_a7/br_pred/ [Kernel PMU event] armv7_cortex_a7/br_return_retired/ [Kernel PMU event] .........skipped............... rNNN [Raw hardware event descriptor] cpu/t1=v1[,t2=v2,t3 ...]/modifier [Raw hardware event descriptor] mem:[/len][:access] [Hardware breakpoint] block:block_bio_backmerge [Tracepoint event] block:block_bio_bounce [Tracepoint event] block:block_bio_complete [Tracepoint event] block:block_bio_frontmerge [Tracepoint event] .........skipped............... compaction:mm_compaction_wakeup_kcompactd [Tracepoint event] cpuhp:cpuhp_enter [Tracepoint event] cpuhp:cpuhp_exit [Tracepoint event] cpuhp:cpuhp_multi_enter [Tracepoint event] ext4:ext4_alloc_da_blocks [Tracepoint event] ext4:ext4_allocate_blocks [Tracepoint event] ext4:ext4_allocate_inode [Tracepoint event] ext4:ext4_begin_ordered_truncate [Tracepoint event] ext4:ext4_collapse_range [Tracepoint event] .........skipped............... ext4:ext4_zero_range [Tracepoint event] f2fs:f2fs_background_gc [Tracepoint event] f2fs:f2fs_commit_inmem_page [Tracepoint event] f2fs:f2fs_destroy_extent_tree [Tracepoint event] f2fs:f2fs_direct_IO_enter [Tracepoint event] f2fs:f2fs_direct_IO_exit [Tracepoint event] .........skipped............... kmem:kfree [Tracepoint event] kmem:kmalloc [Tracepoint event] kmem:kmalloc_node [Tracepoint event] .........skipped............... kmem:mm_page_free [Tracepoint event] kmem:mm_page_free_batched [Tracepoint event] kmem:mm_page_pcpu_drain [Tracepoint event] migrate:mm_migrate_pages [Tracepoint event] migrate:mm_numa_migrate_ratelimit [Tracepoint event] mmc:mmc_request_done [Tracepoint event] mmc:mmc_request_start [Tracepoint event] module:module_free [Tracepoint event] module:module_get [Tracepoint event] module:module_load [Tracepoint event] module:module_put [Tracepoint event] module:module_request [Tracepoint event] napi:napi_poll [Tracepoint event] net:napi_gro_frags_entry [Tracepoint event] net:napi_gro_receive_entry [Tracepoint event] net:net_dev_queue [Tracepoint event] .........skipped............... nfs4:nfs4_access [Tracepoint event] nfs4:nfs4_cached_open [Tracepoint event] nfs4:nfs4_cb_getattr [Tracepoint event] .........skipped............... rpm:rpm_suspend [Tracepoint event] sched:sched_kthread_stop [Tracepoint event] sched:sched_kthread_stop_ret [Tracepoint event] sched:sched_migrate_task [Tracepoint event] sched:sched_move_numa [Tracepoint event] sched:sched_pi_setprio [Tracepoint event] ...........skipped...............
Статистику роботи однієї програми можна побачити за допомогою perf stat:
root@pi3:~/Concurrency/cxx/4# perf stat ./seq_etalon
Total time: 12398928
Performance counter stats for './seq_etalon':
12689.440821 task-clock (msec) # 1.000 CPUs utilized
42 context-switches # 0.003 K/sec
0 cpu-migrations # 0.000 K/sec
465 page-faults # 0.037 K/sec
7,613,358,806 cycles # 0.600 GHz
stalled-cycles-frontend
stalled-cycles-backend
5,652,618,687 instructions # 0.74 insns per cycle
1,001,003,777 branches # 78.885 M/sec
57,720,606 branch-misses # 5.77% of all branches
12.694685821 seconds time elapsed
Або, більш детально, perf stat -d:
root@pi3:~/Concurrency/cxx/4# perf stat -d ./seq_etalon
Total time: 12625224
Performance counter stats for './seq_etalon':
12916.253687 task-clock (msec) # 1.000 CPUs utilized
45 context-switches # 0.003 K/sec
0 cpu-migrations # 0.000 K/sec
464 page-faults # 0.036 K/sec
7,730,773,288 cycles # 0.599 GHz (87.39%)
stalled-cycles-frontend
stalled-cycles-backend
5,651,337,126 instructions # 0.73 insns per cycle (87.47%)
1,000,522,910 branches # 77.462 M/sec (87.53%)
58,478,765 branch-misses # 5.84% of all branches (87.54%)
2,669,728,567 L1-dcache-loads # 206.695 M/sec (87.54%)
10,124,384 L1-dcache-load-misses # 0.38% of all L1-dcache hits (87.54%)
71,471,560 LLC-loads # 5.533 M/sec (87.54%)
468,577 LLC-load-misses # 0.66% of all LL-cache hits (74.87%)
12.922174666 seconds time elapsed
Зауважте такі поля, як:
- task-clock -- час задачі, враховуючи час всіх потоків.
- context-switches -- кількість перемикань контексту.
- cpu-migrations -- скільки раз задачу перекидали між процесорами/ядрами.
- page-faults -- відсутність сторінок пам'яті.
- cycles -- кількість тактів та
- instructions -- кількість виконаних команд
Навіть такі речі, як кількість розгалужень (branches) та
невдалих спроб вгадати обрану гілку розгалуження (branch-misses)
виводить. Але програма, що досліджується вище -- нецікава, однопоточна -- на багатоядерній
машині ні тобі перемикань контексту, ні тобі міграцій... Спробуємо
іншу:
root@pi3:~/Concurrency/cxx/4# perf stat -d ./ConditionalQueue
Total time: 6378083
Performance counter stats for './ConditionalQueue':
24817.142309 task-clock (msec) # 3.740 CPUs utilized
7,550 context-switches # 0.304 K/sec
84 cpu-migrations # 0.003 K/sec
3,143 page-faults # 0.127 K/sec
14,802,965,486 cycles # 0.596 GHz (87.52%)
stalled-cycles-frontend
stalled-cycles-backend
10,753,790,966 instructions # 0.73 insns per cycle (87.63%)
1,786,522,617 branches # 71.987 M/sec (87.32%)
102,020,801 branch-misses # 5.71% of all branches (87.34%)
4,980,437,018 L1-dcache-loads # 200.685 M/sec (87.46%)
18,043,482 L1-dcache-load-misses # 0.36% of all L1-dcache hits (87.52%)
135,968,632 LLC-loads # 5.479 M/sec (87.73%)
6,320,386 LLC-load-misses # 4.65% of all LL-cache hits (75.07%)
6.635007528 seconds time elapsed
Також можна отримати аналогічну інформацію для стороннього процесу (за його PID), обраних подій для всієї системи, тощо:
root@pi3:~/Concurrency/cxx/4# perf stat -e cycles,instructions,cache-references,cache-misses,bus-cycles -a sleep 10
Performance counter stats for 'system wide':
137,633,837 cycles
65,931,944 instructions # 0.48 insns per cycle
33,725,423 cache-references
56,081 cache-misses # 0.166 % of all cache refs
68,846,135 bus-cycles
10.005333430 seconds time elapsed
Ще одне призначення -- профілювання. Як рекомендується,
частота профілювання (опція -F) вказується не круглою (не 100 а 99, не
1000 а 997, тощо) -- щоб випадково не попасти в ритм із якимись
періодичними процесами.
root@pi3:~/Concurrency/cxx/4# perf record -F 9997 -g ./RawThreads Total time : 9622985 Analisys time : 3245658 [ perf record: Woken up 53 times to write data ] [ perf record: Captured and wrote 13.608 MB perf.data (186275 samples) ]
Проаналізувати цю інформацію можна за допомогою perf report ("perf report --stdio" в даному випадку):
Компілюючи, пам'ятайте додати опцію -fno-omit-frame-pointer! Також бажано залишити відладочну інформацію. Інакше розібратися, що відбувається буде неможливо.
Щоправда, такого виводу буде
десятки екранів. Розбиратися із ним -- дуже марудно. Тому автори
придумали допоміжний інструмент -- flame maps.
Інструмент
для їх побудови найпростіше взяти із github, а потім на місці і
використати (в тій же директорії, де виконувалася програма "під наглядом" perf та лежать журнали його роботи):
git clone --depth 1 https://github.com/brendangregg/FlameGraph
perf script | c++filt | ./FlameGraph/stackcollapse-perf.pl | ./FlameGraph/flamegraph.pl > RawThread1.svg
Виглядає це так (якщо зображення немає, svg файл можна скачати тут):
По вертикалі -- глибина стеку, знизу вверх. По
горизонталі: взаємне розташування не означає нічого, а ось ширина --
час, витрачений на дану функцію. Кольори теж нічого не означають.
Наведіть на блок мишкою, щоб побачити опис!
Насправді, perf вміє багато-багато більше. Детальніше див.:
- perf Examples
- Linux Performance -- огляд
- Choosing a Linux Tracer (2015)
- Flame Graphs visualize profiled code
- CPU Flame Graphs
- Linux kernel profiling with perf
- Hacking Linux USDT with Ftrace і Adding User Space Probing to an Application -- є можливість встановлювати свої tracepoint, аналогічно до маркерів Xperf, але, зізнаюся, я поки не розібрався.
- Active Benchmarking: Bonnie++
- PERF tutorial: Finding execution hot spots
- PerfTools
- Таке собі відео: "CppCon 2015: Chandler Carruth "Tuning C++: Benchmarks, and CPUs, and Compilers! Oh My!""
Linux -- Valgrind
Valgrind, в першу чергу, згадують як інструмент пошуку витікань пам'яті (memory leaks), але, насправді, він може багато більше. Інструмент це хитрий -- він не виконує код програми на CPU, транслює його у внутрішнє представлення, а далі вже може робити із ним все що хоче. Зокрема, додавати всі необхідні перевірки. (Звичайно, швидкодія страждає сильно, але багато що по іншому просто не зробиш). Як і perf, працює не лише на x86, зокрема -- підтримує ARM.
Для нас цікавими є:
- Helgrind -- інструмент пошуку гонитв та інших помилок у багатопоточному коді.
- DRD -- ще один інструмент пошуку помилок в багатопоточних програмах
- Cachegrind -- профілювач кешу.
Документація каже, що Helgrind недолюблює умовні змінні POSIX та самостійно реалізовані примітиви синхронізації. У нього та DRD є й інші "заморочки", але це й не дивно, враховуючи складність задачі... Ну і -- швидкодія може впасти на порядок-два!
У моїй практиці DRD дуже скаржиться на data race десь в глибинах реалізації future-promise та трохи на thread із С++11... От не знаю -- вони там є, чи він щось недозрозумів? В документації описано, як його подружити із C++11, але поки не пробував. Можливо, якби зробив описане там, повідомлення б зникли.
На
Raspverry Pi3 ці інструменти, здається, зависають (або сповільнюються
мінімум на 3.5 порядки and counting), тому приклади для x86-64 :
[indrekis@west 1]$ valgrind --tool=memcheck ./Async # default tool ==32639== Memcheck, a memory error detector ==32639== Copyright (C) 2002-2012, and GNU GPL'd, by Julian Seward et al. ==32639== Using Valgrind-3.8.1 and LibVEX; rerun with -h for copyright info ==32639== Command: ./Async ==32639== Total time : 678721 Analisys time : 588771 ==32639== ==32639== HEAP SUMMARY: ==32639== in use at exit: 0 bytes in 0 blocks ==32639== total heap usage: 6,451 allocs, 6,451 frees, 373,584 bytes allocated ==32639== ==32639== All heap blocks were freed -- no leaks are possible ==32639== ==32639== For counts of detected and suppressed errors, rerun with: -v ==32639== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 6 from 6) [indrekis@west 1]$ valgrind --tool=helgrind ./Async ==32747== Helgrind, a thread error detector ==32747== Copyright (C) 2007-2012, and GNU GPL'd, by OpenWorks LLP et al. ==32747== Using Valgrind-3.8.1 and LibVEX; rerun with -h for copyright info ==32747== Command: ./Async ==32747== Total time : 750336 Analisys time : 670382 ==32747== ==32747== For counts of detected and suppressed errors, rerun with: -v ==32747== Use --history-level=approx or =none to gain increased speed, at ==32747== the cost of reduced accuracy of conflicting-access information ==32747== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 0 from 0) [indrekis@west 1]$ valgrind --tool=drd ./Async ==32753== drd, a thread error detector ==32753== Copyright (C) 2006-2012, and GNU GPL'd, by Bart Van Assche. ==32753== Using Valgrind-3.8.1 and LibVEX; rerun with -h for copyright info ==32753== Command: ./Async ==32753== Total time : 1782330 Analisys time : 1694922 ==32753== ==32753== For counts of detected and suppressed errors, rerun with: -v ==32753== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 10 from 10) [indrekis@west 1]$ valgrind --tool=cachegrind ./Async ==678== Cachegrind, a cache and branch-prediction profiler ==678== Copyright (C) 2002-2012, and GNU GPL'd, by Nicholas Nethercote et al. ==678== Using Valgrind-3.8.1 and LibVEX; rerun with -h for copyright info ==678== Command: ./Async ==678== Total time : 732715 Analisys time : 643790 ==678== ==678== I refs: 18,008,741 ==678== I1 misses: 7,986 ==678== LLi misses: 3,072 ==678== I1 miss rate: 0.04% ==678== LLi miss rate: 0.01% ==678== ==678== D refs: 9,802,540 (5,825,160 rd + 3,977,380 wr) ==678== D1 misses: 43,962 ( 36,302 rd + 7,660 wr) ==678== LLd misses: 11,932 ( 6,123 rd + 5,809 wr) ==678== D1 miss rate: 0.4% ( 0.6% + 0.1% ) ==678== LLd miss rate: 0.1% ( 0.1% + 0.1% ) ==678== ==678== LL refs: 51,948 ( 44,288 rd + 7,660 wr) ==678== LL misses: 15,004 ( 9,195 rd + 5,809 wr) ==678== LL miss rate: 0.0% ( 0.0% + 0.1% )
Вміють вони, звичайно, багато більше:
[indrekis@west 1]$ valgrind --tool=drd --check-stack-var=yes --exclusive-threshold=500 --report-signal-unlocked=yes ./Async ==4489== drd, a thread error detector ==4489== Copyright (C) 2006-2012, and GNU GPL'd, by Bart Van Assche. ==4489== Using Valgrind-3.8.1 and LibVEX; rerun with -h for copyright info ==4489== Command: ./Async ==4489== Total time : 3187397 Analisys time : 3074152 ==4489== ==4489== For counts of detected and suppressed errors, rerun with: -v ==4489== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 16 from 16)
Зверніть
увагу на --exclusive-threshold=500 -- буде повідомлено про утримання
мютексів більше ніж 500 мс. Звичайно, продиратися через його
повідомлення про С++ код -- те ще задоволення...
[indrekis@west 1]$ valgrind --tool=drd --check-stack-var=yes --exclusive-threshold=200 --report-signal-unlocked=yes ./RawThreads ==7957== drd, a thread error detector ==7957== Copyright (C) 2006-2012, and GNU GPL'd, by Bart Van Assche. ==7957== Using Valgrind-3.8.1 and LibVEX; rerun with -h for copyright info ==7957== Command: ./RawThreads ==7957== ==7957== Thread 6: ==7957== Acquired at: ==7957== at 0x4A135FE: pthread_mutex_lock (drd_pthread_intercepts.c:653) ==7957== by 0x4362B6: __gthread_mutex_lock(pthread_mutex_t*) (gthr-default.h:748) ==7957== by 0x4371ED: std::mutex::lock() (mutex:135) ==7957== by 0x439557: std::lock_guard::lock_guard(std::mutex&) (mutex:377) ==7957== by 0x437F68: void wordCounter > > >(__gnu_cxx::__normal_iterator > >, __gnu_cxx::__normal_iterator > >, std::unordered_map, std::equal_to, std::allocator > >&, std::mutex&) (RawThreads.cpp:48) ==7957== by 0x442AB3: void std::_Bind_simple > >, __gnu_cxx::__normal_iterator > >, std::reference_wrapper, std::equal_to, std::allocator > > >, std::reference_wrapper))(__gnu_cxx::__normal_iterator > >, __gnu_cxx::__normal_iterator > >, std::unordered_map, std::equal_to, std::allocator > >&, std::mutex&)>::_M_invoke(std::_Index_tuple) (functional:1531) ==7957== by 0x4428D2: std::_Bind_simple > >, __gnu_cxx::__normal_iterator > >, std::reference_wrapper, std::equal_to, std::allocator > > >, std::reference_wrapper))(__gnu_cxx::__normal_iterator > >, __gnu_cxx::__normal_iterator > >, std::unordered_map, std::equal_to, std::allocator > >&, std::mutex&)>::operator()() (functional:1520) ==7957== by 0x442871: std::thread::_Impl > >, __gnu_cxx::__normal_iterator > >, std::reference_wrapper, std::equal_to, std::allocator > > >, std::reference_wrapper))(__gnu_cxx::__normal_iterator > >, __gnu_cxx::__normal_iterator > >, std::unordered_map, std::equal_to, std::allocator > >&, std::mutex&)> >::_M_run() (thread:115) ==7957== by 0x444C8F: execute_native_thread_routine (in /home/indrekis/Concurrency/cxx/1/RawThreads) ==7957== by 0x4A128B4: vgDrd_thread_wrapper (drd_pthread_intercepts.c:355) ==7957== by 0x3F87607AA0: start_thread (in /lib64/libpthread-2.12.so) ==7957== by 0x3F86AE8AAC: clone (in /lib64/libc-2.12.so) ==7957== Lock on mutex 0x7fefff880 was held during 208 ms (threshold: 200 ms). ==7957== at 0x4A14E2C: pthread_mutex_unlock (drd_pthread_intercepts.c:703) ==7957== by 0x4362E5: __gthread_mutex_unlock(pthread_mutex_t*) (gthr-default.h:778) ==7957== by 0x43721B: std::mutex::unlock() (mutex:153) ==7957== by 0x439576: std::lock_guard::~lock_guard() (mutex:383) ==7957== by 0x438006: void wordCounter > > >(__gnu_cxx::__normal_iterator > >, __gnu_cxx::__normal_iterator > >, std::unordered_map, std::equal_to, std::allocator > >&, std::mutex&) (RawThreads.cpp:48) ==7957== by 0x442AB3: void std::_Bind_simple > >, __gnu_cxx::__normal_iterator > >, std::reference_wrapper, std::equal_to, std::allocator > > >, std::reference_wrapper))(__gnu_cxx::__normal_iterator > >, __gnu_cxx::__normal_iterator > >, std::unordered_map, std::equal_to, std::allocator > >&, std::mutex&)>::_M_invoke(std::_Index_tuple) (functional:1531) ==7957== by 0x4428D2: std::_Bind_simple > >, __gnu_cxx::__normal_iterator > >, std::reference_wrapper, std::equal_to, std::allocator > > >, std::reference_wrapper))(__gnu_cxx::__normal_iterator > >, __gnu_cxx::__normal_iterator > >, std::unordered_map, std::equal_to, std::allocator > >&, std::mutex&)>::operator()() (functional:1520) ==7957== by 0x442871: std::thread::_Impl > >, __gnu_cxx::__normal_iterator > >, std::reference_wrapper, std::equal_to, std::allocator > > >, std::reference_wrapper))(__gnu_cxx::__normal_iterator > >, __gnu_cxx::__normal_iterator > >, std::unordered_map, std::equal_to, std::allocator > >&, std::mutex&)> >::_M_run() (thread:115) ==7957== by 0x444C8F: execute_native_thread_routine (in /home/indrekis/Concurrency/cxx/1/RawThreads) ==7957== by 0x4A128B4: vgDrd_thread_wrapper (drd_pthread_intercepts.c:355) ==7957== by 0x3F87607AA0: start_thread (in /lib64/libpthread-2.12.so) ==7957== by 0x3F86AE8AAC: clone (in /lib64/libc-2.12.so) ==7957== mutex 0x7fefff880 was first observed at: ==7957== at 0x4A1354C: pthread_mutex_lock (drd_pthread_intercepts.c:650) ==7957== by 0x4362B6: __gthread_mutex_lock(pthread_mutex_t*) (gthr-default.h:748) ==7957== by 0x4371ED: std::mutex::lock() (mutex:135) ==7957== by 0x439557: std::lock_guard::lock_guard(std::mutex&) (mutex:377) ==7957== by 0x437F68: void wordCounter > > >(__gnu_cxx::__normal_iterator > >, __gnu_cxx::__normal_iterator > >, std::unordered_map, std::equal_to, std::allocator > >&, std::mutex&) (RawThreads.cpp:48) ==7957== by 0x442AB3: void std::_Bind_simple > >, __gnu_cxx::__normal_iterator > >, std::reference_wrapper, std::equal_to, std::allocator > > >, std::reference_wrapper))(__gnu_cxx::__normal_iterator > >, __gnu_cxx::__normal_iterator > >, std::unordered_map, std::equal_to, std::allocator > >&, std::mutex&)>::_M_invoke(std::_Index_tuple) (functional:1531) ==7957== by 0x4428D2: std::_Bind_simple > >, __gnu_cxx::__normal_iterator > >, std::reference_wrapper, std::equal_to, std::allocator > > >, std::reference_wrapper))(__gnu_cxx::__normal_iterator > >, __gnu_cxx::__normal_iterator > >, std::unordered_map, std::equal_to, std::allocator > >&, std::mutex&)>::operator()() (functional:1520) ==7957== by 0x442871: std::thread::_Impl > >, __gnu_cxx::__normal_iterator > >, std::reference_wrapper, std::equal_to, std::allocator > > >, std::reference_wrapper))(__gnu_cxx::__normal_iterator > >, __gnu_cxx::__normal_iterator > >, std::unordered_map, std::equal_to, std::allocator > >&, std::mutex&)> >::_M_run() (thread:115) ==7957== by 0x444C8F: execute_native_thread_routine (in /home/indrekis/Concurrency/cxx/1/RawThreads) ==7957== by 0x4A128B4: vgDrd_thread_wrapper (drd_pthread_intercepts.c:355) ==7957== by 0x3F87607AA0: start_thread (in /lib64/libpthread-2.12.so) ==7957== by 0x3F86AE8AAC: clone (in /lib64/libc-2.12.so) ==7957== Total time : 3729164 Analisys time : 3582082 ==7957== ==7957== For counts of detected and suppressed errors, rerun with: -v ==7957== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 16 from 16) [indrekis@west 1]$
Ще можна побачити обмін блокувань та нотифікацій:
[indrekis@west 1]$ valgrind --tool=drd --trace-cond=yes --trace-barrier=yes --trace-mutex=yes --trace-semaphore=yes --trace-rwlock=yes ./ConditionalQueue ==10897== drd, a thread error detector ==10897== Copyright (C) 2006-2012, and GNU GPL'd, by Bart Van Assche. ==10897== Using Valgrind-3.8.1 and LibVEX; rerun with -h for copyright info ==10897== Command: ./ConditionalQueue ==10897== ==10897== [1] pre_rwlock_wrlock 0x3f86d8f860 ==10897== [1] post_rwlock_wrlock 0x3f86d8f860 ==10897== [1] rwlock_unlock 0x3f86d8f860 ==10897== [1] mutex_init mutex 0x7fefff310 ==10897== [2] mutex_trylock mutex 0x7fefff310 rc 0 owner 0 ==10897== [2] post_mutex_lock mutex 0x7fefff310 rc 0 owner 0 ==10897== [2] mutex_unlock mutex 0x7fefff310 rc 1 ==10897== [1] mutex_trylock mutex 0x7fefff310 rc 0 owner 2 ==10897== [1] post_mutex_lock mutex 0x7fefff310 rc 0 owner 2 ==10897== [1] mutex_unlock mutex 0x7fefff310 rc 1 ==10897== [1] mutex_destroy mutex 0x7fefff310 rc 0 owner 1 ==10897== [1] mutex_init mutex 0x7fefff390 ==10897== [1] mutex_trylock mutex 0x7fefff390 rc 0 owner 0 ==10897== [1] post_mutex_lock mutex 0x7fefff390 rc 0 owner 0 ==10897== [1] mutex_unlock mutex 0x7fefff390 rc 1 <=========== SKIPPED nagging about std::thread implementation problems -- see note above ==============> бурчання ==10897== ==10897== [3] mutex_trylock mutex 0x7fefff390 rc 0 owner 1 ==10897== [3] post_mutex_lock mutex 0x7fefff390 rc 0 owner 1 ==10897== [3] mutex_unlock mutex 0x7fefff390 rc 1 ==10897== [3] mutex_trylock mutex 0x7fefffa50 rc 0 owner 0 ==10897== [3] post_mutex_lock mutex 0x7fefffa50 rc 0 owner 0 ==10897== [3] mutex_unlock mutex 0x7fefffa50 rc 1 ==10897== [3] cond_pre_wait cond 0x7fefffa20 ==10897== [2] mutex_trylock mutex 0x7fefffa50 rc 0 owner 3 ==10897== [2] post_mutex_lock mutex 0x7fefffa50 rc 0 owner 3 ==10897== [2] cond_signal cond 0x7fefffa20 ==10897== [1] mutex_trylock mutex 0x7fefff390 rc 0 owner 3 ==10897== [1] post_mutex_lock mutex 0x7fefff390 rc 0 owner 3 ==10897== [1] mutex_unlock mutex 0x7fefff390 rc 1 ==10897== [1] mutex_destroy mutex 0x7fefff390 rc 0 owner 1 ==10897== [1] mutex_init mutex 0x7fefff390 ==10897== [4] mutex_trylock mutex 0x7fefff390 rc 0 owner 0 ==10897== [4] post_mutex_lock mutex 0x7fefff390 rc 0 owner 0 ==10897== [4] mutex_unlock mutex 0x7fefff390 rc 1 ==10897== [4] mutex_trylock mutex 0x7fefffa50 rc 1 owner 2 ==10897== [2] mutex_unlock mutex 0x7fefffa50 rc 1 ==10897== [2] mutex_trylock mutex 0x7fefffa50 rc 0 owner 2 ==10897== [2] post_mutex_lock mutex 0x7fefffa50 rc 0 owner 2 ==10897== [2] cond_broadcast cond 0x7fefffa20 ==10897== [2] mutex_unlock mutex 0x7fefffa50 rc 1 ==10897== [3] cond_post_wait cond 0x7fefffa20 ==10897== [3] cond_post_wait mutex 0x7fefffa50 rc 0 owner 2 ==10897== [3] mutex_unlock mutex 0x7fefffa50 rc 1 ==10897== [1] mutex_trylock mutex 0x7fefff390 rc 0 owner 4 ==10897== [1] post_mutex_lock mutex 0x7fefff390 rc 0 owner 4 ==10897== [1] mutex_unlock mutex 0x7fefff390 rc 1 ==10897== [1] mutex_destroy mutex 0x7fefff390 rc 0 owner 1 ==10897== [1] mutex_init mutex 0x7fefff400 ==10897== [5] mutex_trylock mutex 0x7fefff400 rc 0 owner 0 ==10897== [5] post_mutex_lock mutex 0x7fefff400 rc 0 owner 0 ==10897== [5] mutex_unlock mutex 0x7fefff400 rc 1 ==10897== [5] mutex_trylock mutex 0x7fefffa50 rc 0 owner 3 ==10897== [5] post_mutex_lock mutex 0x7fefffa50 rc 0 owner 3 ==10897== [5] mutex_unlock mutex 0x7fefffa50 rc 1 ==10897== [4] post_mutex_lock mutex 0x7fefffa50 rc 0 owner 5 ==10897== [4] mutex_unlock mutex 0x7fefffa50 rc 1 ==10897== [4] mutex_trylock mutex 0x7fefff9a0 rc 0 owner 0 ==10897== [4] post_mutex_lock mutex 0x7fefff9a0 rc 0 owner 0 ==10897== [4] cond_broadcast cond 0x7fefff970 ==10897== [4] mutex_unlock mutex 0x7fefff9a0 rc 1 ==10897== [3] mutex_trylock mutex 0x7fefffa50 rc 0 owner 4 ==10897== [3] post_mutex_lock mutex 0x7fefffa50 rc 0 owner 4 ==10897== [3] mutex_unlock mutex 0x7fefffa50 rc 1 ==10897== [3] mutex_trylock mutex 0x7fefff9a0 rc 0 owner 4 ==10897== [3] post_mutex_lock mutex 0x7fefff9a0 rc 0 owner 4 ==10897== [3] cond_broadcast cond 0x7fefff970 ==10897== [3] mutex_unlock mutex 0x7fefff9a0 rc 1 ==10897== [1] mutex_trylock mutex 0x7fefff400 rc 0 owner 5 ==10897== [1] post_mutex_lock mutex 0x7fefff400 rc 0 owner 5 ==10897== [1] mutex_unlock mutex 0x7fefff400 rc 1 ==10897== [1] mutex_destroy mutex 0x7fefff400 rc 0 owner 1 ==10897== [1] mutex_trylock mutex 0x7fefff9a0 rc 0 owner 3 ==10897== [1] post_mutex_lock mutex 0x7fefff9a0 rc 0 owner 3 ==10897== [1] mutex_unlock mutex 0x7fefff9a0 rc 1 ==10897== [1] cond_pre_wait cond 0x7fefff970 ==10897== [5] mutex_trylock mutex 0x7fefff9a0 rc 0 owner 1 ==10897== [5] post_mutex_lock mutex 0x7fefff9a0 rc 0 owner 1 ==10897== [5] cond_signal cond 0x7fefff970 ==10897== [5] mutex_unlock mutex 0x7fefff9a0 rc 1 ==10897== [5] mutex_trylock mutex 0x7fefffa50 rc 0 owner 3 ==10897== [5] post_mutex_lock mutex 0x7fefffa50 rc 0 owner 3 ==10897== [5] mutex_unlock mutex 0x7fefffa50 rc 1 ==10897== [5] mutex_trylock mutex 0x7fefff9a0 rc 0 owner 5 ==10897== [5] post_mutex_lock mutex 0x7fefff9a0 rc 0 owner 5 ==10897== [5] cond_broadcast cond 0x7fefff970 ==10897== [5] mutex_unlock mutex 0x7fefff9a0 rc 1 ==10897== [1] cond_post_wait cond 0x7fefff970 ==10897== [1] cond_post_wait mutex 0x7fefff9a0 rc 0 owner 5 ==10897== [1] mutex_unlock mutex 0x7fefff9a0 rc 1 ==10897== [1] mutex_trylock mutex 0x7fefff9a0 rc 0 owner 1 ==10897== [1] post_mutex_lock mutex 0x7fefff9a0 rc 0 owner 1 ==10897== [1] mutex_unlock mutex 0x7fefff9a0 rc 1 ==10897== [1] mutex_trylock mutex 0x7fefff9a0 rc 0 owner 1 ==10897== [1] post_mutex_lock mutex 0x7fefff9a0 rc 0 owner 1 ==10897== [1] mutex_unlock mutex 0x7fefff9a0 rc 1 Total time: 2835806 ==10897== [1] cond_destroy cond 0x7fefff970 ==10897== [1] cond_destroy cond 0x7fefffa20 ==10897== [1] mutex_trylock recursive mutex 0x3f86820908 rc 0 owner 0 ==10897== [1] post_mutex_lock recursive mutex 0x3f86820908 rc 0 owner 0 ==10897== [1] mutex_unlock recursive mutex 0x3f86820908 rc 1 ==10897== ==10897== For counts of detected and suppressed errors, rerun with: -v ==10897== ERROR SUMMARY: 2 errors from 1 contexts (suppressed: 61 from 59)
Детальніше див, наприклад:
- DRD: a thread error detector
- Helgrind: a thread error detector
- Cachegrind: a cache and branch-prediction profile
- Зокрема, всі ті інструменти підтримують можливість анотувати код певними макросами, щоб полегшити їм роботу і зменшити кількість false positive.
Linux -- mutrace
Невеликий і не дуже популярний інструмент: mutrace, який, однак, може бути цікавим.
На сайті є трохи помилок (не оновлено вчасно?), то опишу процедуру інсталяції (із розгортанням у власну домашню директорію -- щоб не потребувати права root), яка успішно спрацювала у мене:
git clone http://git.0pointer.net/mutrace.git/
cd mutrace
./bootstrap.sh --prefix=/home/<username>/mutrace/
make && make install
Нотатка: пише, що потребує autoconf версії 2.68, у мене був 2.63, без можливості оновити найближчим часом, але після виправлення в configure.ac (AC_PREREQ([2.63])) підійшов і 63-й без проблем.
export LD_LIBRARY_PATH=$LD_LIBRARY_PATH:/home/<username>/mutrace/lib
Використання:
[indrekis@west 1]$ /home/indrekis/mutrace/bin/matrace ./ConditionalQueue
matrace: 0.2 successfully initialized for process ConditionalQueu (PID: 12578).
Total time: 5497
matrace: Total of 3999 allocations and 4033 frees in non-realtime threads in process ConditionalQueu (PID: 12578).
matrace: Total of 0 allocations and 0 frees in realtime threads.
[indrekis@west 1]$ /home/indrekis/mutrace/bin/mutrace ./ConditionalQueue
mutrace: 0.2 successfully initialized for process ConditionalQueu (PID: 12725).
Total time: 4753
mutrace: Showing statistics for process ConditionalQueu (PID: 12725).
mutrace: 2 mutexes used.
Mutex #1 (0x0x7fffd5230430) first referenced by:
/home/indrekis/mutrace/lib/libmutrace.so(pthread_mutex_lock+0x119) [0x7f7f0def1dcc]
./ConditionalQueue() [0x4473c7]
./ConditionalQueue(_ZNSt5mutex4lockEv+0x18) [0x44836c]
./ConditionalQueue(_ZNSt11unique_lockISt5mutexE4lockEv+0x47) [0x44bab5]
./ConditionalQueue(_ZNSt11unique_lockISt5mutexEC1ERS0_+0x3a) [0x449f66]
./ConditionalQueue(_ZN15SimpleQueStructISt6vectorISsSaISsEESt5dequeIS2_SaIS2_EEE7dequeueERS2_+0x2d) [0x448cad]
./ConditionalQueue(_Z18countWordsConsumerR15SimpleQueStructISt6vectorISsSaISsEESt5dequeIS2_SaIS2_EEERS_ISt13unordered_mapISsjSt4hashISsESt8equal_toISsESaISt4pairIKSsjEEES3_ISH_SaISH_EEE+0x3c) [0x447606]
./ConditionalQueue(_ZNSt12_Bind_simpleIFPFvR15SimpleQueStructISt6vectorISsSaISsEESt5dequeIS3_SaIS3_EEERS0_ISt13unordered_mapISsjSt4hashISsESt8equal_toISsESaISt4pairIKSsjEEES4_ISI_SaISI_EEEESt17reference_wrapperIS7_ESP_ISL_EEE9_M_invokeIJLm0ELm1EEEEvSt12_Index_tupleIJXspT_EEE+0x69) [0x457a75]
./ConditionalQueue(_ZNSt12_Bind_simpleIFPFvR15SimpleQueStructISt6vectorISsSaISsEESt5dequeIS3_SaIS3_EEERS0_ISt13unordered_mapISsjSt4hashISsESt8equal_toISsESaISt4pairIKSsjEEES4_ISI_SaISI_EEEESt17reference_wrapperIS7_ESP_ISL_EEEclEv+0x1d) [0x4578dd]
./ConditionalQueue(_ZNSt6thread5_ImplISt12_Bind_simpleIFPFvR15SimpleQueStructISt6vectorISsSaISsEESt5dequeIS5_SaIS5_EEERS2_ISt13unordered_mapISsjSt4hashISsESt8equal_toISsESaISt4pairIKSsjEEES6_ISK_SaISK_EEEESt17reference_wrapperIS9_ESR_ISN_EEEE6_M_runEv+0x1c) [0x45781c]
./ConditionalQueue() [0x459e00]
Mutex #0 (0x0x7fffd5230380) first referenced by:
/home/indrekis/mutrace/lib/libmutrace.so(pthread_mutex_lock+0x119) [0x7f7f0def1dcc]
./ConditionalQueue() [0x4473c7]
./ConditionalQueue(_ZNSt5mutex4lockEv+0x18) [0x44836c]
./ConditionalQueue(_ZNSt11unique_lockISt5mutexE4lockEv+0x47) [0x44bab5]
./ConditionalQueue(_ZNSt11unique_lockISt5mutexEC1ERS0_+0x3a) [0x449f66]
./ConditionalQueue(_ZN15SimpleQueStructISt13unordered_mapISsjSt4hashISsESt8equal_toISsESaISt4pairIKSsjEEESt5dequeIS9_SaIS9_EEE7dequeueERS9_+0x2d) [0x44900b]
./ConditionalQueue(_Z17mergeMapsConsumerR15SimpleQueStructISt13unordered_mapISsjSt4hashISsESt8equal_toISsESaISt4pairIKSsjEEESt5dequeIS9_SaIS9_EEERS9_+0x3c) [0x44776c]
./ConditionalQueue(main+0x4aa) [0x447cd0]
/lib64/libc.so.6(__libc_start_main+0xfd) [0x3f86a1ed1d]
mutrace: Showing 2 mutexes in order of (write) contention count:
Mutex # Locked Changed Cont. cont.Time[ms] tot.Time[ms] avg.Time[ms] Flags
1 12 7 2 1.193 0.057 0.005 M-.--.
0 10 5 0 0.000 0.207 0.021 M-.--.
... ... ... ... ... ... ... ||||||
/|||||
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: 2 condition variables used.
Condvar #1 (0x0x7fffd5230400) first referenced by:
/home/indrekis/mutrace/lib/libmutrace.so(pthread_cond_wait+0x74) [0x7f7f0def2ba3]
/usr/lib64/libstdc++.so.6(_ZNSt18condition_variable4waitERSt11unique_lockISt5mutexE+0xc) [0x30fd0b62fc]
./ConditionalQueue(_Z18countWordsConsumerR15SimpleQueStructISt6vectorISsSaISsEESt5dequeIS2_SaIS2_EEERS_ISt13unordered_mapISsjSt4hashISsESt8equal_toISsESaISt4pairIKSsjEEES3_ISH_SaISH_EEE+0x3c) [0x447606]
./ConditionalQueue(_ZNSt12_Bind_simpleIFPFvR15SimpleQueStructISt6vectorISsSaISsEESt5dequeIS3_SaIS3_EEERS0_ISt13unordered_mapISsjSt4hashISsESt8equal_toISsESaISt4pairIKSsjEEES4_ISI_SaISI_EEEESt17reference_wrapperIS7_ESP_ISL_EEE9_M_invokeIJLm0ELm1EEEEvSt12_Index_tupleIJXspT_EEE+0x69) [0x457a75]
./ConditionalQueue(_ZNSt12_Bind_simpleIFPFvR15SimpleQueStructISt6vectorISsSaISsEESt5dequeIS3_SaIS3_EEERS0_ISt13unordered_mapISsjSt4hashISsESt8equal_toISsESaISt4pairIKSsjEEES4_ISI_SaISI_EEEESt17reference_wrapperIS7_ESP_ISL_EEEclEv+0x1d) [0x4578dd]
./ConditionalQueue(_ZNSt6thread5_ImplISt12_Bind_simpleIFPFvR15SimpleQueStructISt6vectorISsSaISsEESt5dequeIS5_SaIS5_EEERS2_ISt13unordered_mapISsjSt4hashISsESt8equal_toISsESaISt4pairIKSsjEEES6_ISK_SaISK_EEEESt17reference_wrapperIS9_ESR_ISN_EEEE6_M_runEv+0x1c) [0x45781c]
./ConditionalQueue() [0x459e00]
Condvar #0 (0x0x7fffd5230350) first referenced by:
/home/indrekis/mutrace/lib/libmutrace.so(pthread_cond_wait+0x74) [0x7f7f0def2ba3]
/usr/lib64/libstdc++.so.6(_ZNSt18condition_variable4waitERSt11unique_lockISt5mutexE+0xc) [0x30fd0b62fc]
./ConditionalQueue(_Z17mergeMapsConsumerR15SimpleQueStructISt13unordered_mapISsjSt4hashISsESt8equal_toISsESaISt4pairIKSsjEEESt5dequeIS9_SaIS9_EEERS9_+0x3c) [0x44776c]
./ConditionalQueue(main+0x4aa) [0x447cd0]
/lib64/libc.so.6(__libc_start_main+0xfd) [0x3f86a1ed1d]
mutrace: Showing 2 condition variables in order of wait contention count:
Cond # Waits Signals Cont. tot.Time[ms] cont.Time[ms] avg.Time[ms] Flags
1 3 2 2 2.423 0.000 0.000 x.
0 2 4 0 2.194 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 8.346 ms.
mutrace: Results for SMP with 8 processors.
Можна також спробувати зробити так:mutrace ./ConditionalQueue 2>&1 | c++filt
Воно
може вийти читабельнішим -- c++filt виконує demangling С++-імен.
("Заклинання "2>&1" перенаправляє stderr в stdout. Воно потрібне, тому
що mutrace виводить в stderr, а перенаправляється для c++filt --
stdout).
Зверніть увагу на часи очікування, кількість використань, тощо об'єктів синхронізації -- мютексів та умовних змінних.
Додатково
Ще деякі суміжні інструменти, про які детальніше не писатиму.
 |
| Зображення взято тут: "Linux Performance". |
 |
| Клікабельно! Зображення взято тут: "Linux Performance". |
- VTune -- комерційний (є безкоштовні студентські та академічні ліцензії) кросплатформовий (Linux, Windows, Mac OS) профайлер і т.д. Кажуть, дуже потужний.
- gprof/gcov (http://www.thegeekstuff.com/2012/08/gprof-tutorial)
- "Linux Trace Toolkit: next generation"
- Windows підтримує API для відстежування подій, яким інструменти типу Concurrency Visualizer i Xperf й користуються: "Event Tracing". Хоча воно корисне для нашого дослідження, через спеціалізованість і складність в освоєнні, поки не розглядаємо.
- Список "List of performance analysis tools" на Вікіпедії.
- CodeXL колись від АМД, тепер -- Open Source. Нормально працює лише із їхніми процесорами (як і інтелівський VTune -- з інтелівськими).
- OProfile - компактний, зате простий
- Розповідь ще про кілька "тематичних" утиліток: "How to measure mutex contention?"
Ще однією цінною бібліотекою є Google Benchmark. Вона дозволяє зовсім просто (при тому -- впорядковано) організувати дослідження продуктивності фрагментів коду. Однак, для вимірювань вона покладається на трюки, описані в попередньому пості, і має ті ж проблеми боротьби із надмірними чи невчасними оптимізаціями компілятора. Тому поки її не використовуватимемо.
Завершуючи
Програми, до яких відсилається код вище, живуть тут. Наступного разу розглянемо пару API для доступу до лічильників процесора. А поки --
Дякую за увагу!
Немає коментарів:
Дописати коментар