Data Race Detector

by Devexperts

Child pages
  • Анализ логов
Skip to end of metadata
Go to start of metadata

Введение

DRD ведет 3 лог-файла:

  • drd.log, содержащий информационные сообщения
  • drd_error.log, в который пишутся ошибки самого DRD
  • drd_races.log, содержащий отчеты обо всех обнаруженные гонках в приложении.

Если DRD ведет себя некорректно (а то и совсем падает), то крайне желательно приложить эти файлы к баг-репорту.

drd_races.log

Пример обнаруженной гонки по полю какого-то класса:

WRITE_READ data race occurred between current thread AWT-EventQueue-0(id = 18) and thread Thread-11(id = 27)

Race target: FIELD com/devexperts/jtt/tracker/gui/worklogs/model/HistoryWorklogsAdapter.fromMillis
Current thread 18: com/devexperts/jtt/tracker/gui/worklogs/model/HistoryWorklogsAdapter.changePeriod (line : 46)
Racing thread 27: com/devexperts/jtt/tracker/gui/worklogs/model/HistoryWorklogsAdapter.access$200 (line : 20)

---------------------Stack trace for racing thread (id = 27) is not available.------------------

---------------------Current thread's stack trace (id = 18) : -------------------------
    at com.devexperts.jtt.tracker.gui.worklogs.model.HistoryWorklogsAdapter.changePeriod(HistoryWorklogsAdapter.java:46)
    at com.devexperts.jtt.tracker.gui.worklogs.model.WorklogAdapterWrapper.changePeriod(WorklogAdapterWrapper.java:253)
    at com.devexperts.jtt.tracker.gui.worklogs.WorklogsHistoryPanelController.refresh(WorklogsHistoryPanelController.java:119)
    at com.devexperts.jtt.tracker.gui.worklogs.WorklogsHistoryPanelController.refresh(WorklogsHistoryPanelController.java:123)
    at com.devexperts.jtt.tracker.gui.worklogs.WorklogsHistoryPanelController.actionPerformed(WorklogsHistoryPanelController.java:80)
    at javax.swing.AbstractButton.fireActionPerformed(AbstractButton.java:1995)
    at javax.swing.AbstractButton$Handler.actionPerformed(AbstractButton.java:2318)
    at javax.swing.DefaultButtonModel.fireActionPerformed(DefaultButtonModel.java:387)

---------------------Current thread's vc were: -------------------------
Live: [1:2][18:68693][26:7] size = 6; Dead: [12:5]; tid = 18
-------------------------Data vc were: --------------------------------
{W:[0:0] R:[27:13]; exclusive = true}

Это значит следующее: текущий поток (id=18, name=AWT-EventQueue-0) обратился к полю fromMillis класса HistoryWorklogsAdapter на чтение из метода HistoryWorklogsAdapter.changePeriod(), строка 46. Это обращение образует гонку с предшествовавшим обращением к этому же полю на запись в другом потоке (name = "Thread-11", id=27) из метода HistoryWorklogsAdapter.access$200() в строке номер 20. Stacktrace потока id=27 недоступен, stacktrace текущего потока (id=18) указан.

Также указано состояние часов текущего потока и поля на момент обнаружения гонки (например, по ним видно, что текущий поток не располагал информацией о предыдущем обращении второго потока к этому полю - у него компонента часов, соответствующая потоку с id=27, отсутствует, то есть равна 0, что меньше, чем эта же компонента в часах поля - 13).

Пример обнаруженной гонки по какому-то объекту

READ_WRITE data race occurred between current thread AWT-EventQueue-0(id = 18) and thread Thread-11(id = 27)

Race target: method calls on java/util/Collection
Current thread 18 called java/util/Collection.iterator() at : com/devexperts/jtt/util/adapters/CachingDataAdapter.addAll (line : 66)
Racing thread 27 called java/util/Collection.addAll() at : com/devexperts/jtt/tracker/core/service/impl/CacheAwareDataProvider.getWorklogs (line : 118)

---------------------Stack trace for racing thread (id = 27) is not available.------------------

---------------------Current thread's stack trace (id = 18) : -------------------------
    at com.devexperts.jtt.util.adapters.CachingDataAdapter.addAll(CachingDataAdapter.java:66)
    at com.devexperts.jtt.tracker.gui.worklogs.model.HistoryWorklogsAdapter.access$500(HistoryWorklogsAdapter.java:20)
    at com.devexperts.jtt.tracker.gui.worklogs.model.HistoryWorklogsAdapter$2.succeeded(HistoryWorklogsAdapter.java:69)
    at com.devexperts.jtt.tracker.gui.worklogs.model.HistoryWorklogsAdapter$2.succeeded(HistoryWorklogsAdapter.java:66)
    at com.devexperts.jtt.tracker.core.service.impl.DataServiceImpl$1$1.run(DataServiceImpl.java:80)
    at java.awt.event.InvocationEvent.dispatch(InvocationEvent.java:209)

---------------------Current thread's vc were: -------------------------
Live: [1:2][18:68676] size = 4; Dead: [12:5]; tid = 18
-------------------------Field vc were: --------------------------------
{W:[27:14] R:[0:0]; exclusive = true}

Это значит следующее: текущий поток (id=18) вызвал метод iterator() на объекте типа Collection в методе CachingDataAdapter.addAll(), что DRD трактовал как обращение к этому объекту на чтение. Этот вызов образует гонку с предшествовавшим вызовом метода "add()" того же объекта, что DRD трактовал как обращение к нему на запись, в другом потоке (id=27) из метода CacheAwareDataProvider.getWorklogs(), строка номер 118. Stacktrace потока id=27 недоступен, stacktrace текущего потока (id=18) указан.
Также указано состояние часов текущего потока и поля на момент обнаружения гонки.

drd.log

В начале работы DRD в drd.log пишутся конфиги, которые прочитал DRD, и выдается сообщение об успешном запуске DRD. Если этих строк нет, значит что-то не так.

DRDAgent started it's work.
Sync instrumentation scope config : <description of scope, in which sync events would be intercepted>
Race detection instrumentation scope config : <description of scope, in which data races would be searched>

Accesses config: 
Accesses of following fields wouldn't be instrumented : <description of accesses to which fields wouldn't be analyzed against data races>
Foreign calls of following methods wouldn't be instrumented : <description of which foreign calls wouldn't be analyzed against data races>

Contracts config:
Contracts matcher would try to apply following contracts sequentially. If no one matches, target method would be treated as write.
<List of contracts>

Trace config: <trace config>

++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
Config initialized : true.
Transformer and detector launched.
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
...
Happens-before config read successfully. Synchronization points are: ...

Во время работы DRD в drd.log пишутся информационные сообщения, которые могут быть полезны разработчикам DRD для выявления проблем и их причин. В частности, раз в минуту собирается статистика о потреблении памяти и количестве вазовов различных методов DRD. Собранные данные будут невероятно важны при анализе перформанса/ошибок DRD разработчиками (авторами данного мануала).

Пример статистики:

+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
Last time stats were gathered 59999 ms ago.
19 active threads.
Memory usage: init = 134185856(131040K) used = 53789304(52528K) committed = 80805888(78912K) max = 1908932608(1864192K).
Contract clocks: 0 ( + 0 - 0 = 0. Disposal took 0 ms).
    Hits : 0.
    Approx total reserved size: 0; real size : 0. Dead threads clocks size: 0.
    Contracts ignored : 0, processed : 0.
Volatile clocks: 13 ( + 0 - 0 = 0. Disposal took 0 ms).
    Hits : 0.
    Approx total reserved size: 260; real size : 104. Dead threads clocks size: 34.
    Volatiles ignored : 0, processed : 0.
Syn clocks: 58 ( + 0 - 0 = 0). New clock for nothing : 0.
    Hits : 200.
    Approx total reserved size : 960; real size : 426. Dead threads clocks size : 180.
    Syncs ignored : 0, processed : 200.
Foreign clocks: 2388 ( + 600 - 0 = 600). New clock for nothing : 0.
    Hits : 1800
    Approx total reserved size: 10532; real size : 9988. Dead threads clocks size: 180
Vector clock counters: 
    New array allocations for live clocks: 0 vs 0 reusages.
    Dead clocks during merge: 0 cached, 0 same, 0 new.
    Generations update: 0 light, 0 hard (0 of them from zero).
    Vector clock merge: 0 optimized vs 0 full acquires; 0 optimized vs 0 full releases. 0 two-way merges. 
Diff was calculated 0 times.
    Shared reads in data clock occurred 0 times.
    Data races reported: 0, skipped: 0.
    VC total live resizes: 0, total dead resizes: 0.
    Yield counter : 0.
HBDynamic helper cache hits : 0; misses : 0.
Happens-before vertices returned true : 0; false : 0.
Foreign calls: 10000; field hits: 0
-----------------Data clock histogram (top 20): -----------------
24170   com/devexperts/jtt/tracker/core/time/impl/TimeSpyImpl$2 (java/util/Map$Entry)
6259   com/devexperts/jtt/util/event/impl/StrongRefEventManager (java/util/Iterator)
3637   com/devexperts/jtt/tracker/core/time/impl/TimeSpyImpl$2 (java/util/Set)
3637   com/devexperts/jtt/tracker/core/time/impl/TimeSpyImpl$2 (java/util/HashMap)
3539   com/devexperts/jtt/tracker/core/time/impl/TimeSpyImpl$2 (java/util/Iterator)
2216   com/devexperts/jtt/tracker/core/storage/impl/local/SerializableStorageImpl (java/util/Set)
2059   com/devexperts/jtt/common/impl/IssueHeaderImpl
768   com/devexperts/jtt/common/impl/IssueDetailsImpl
711   com/devexperts/jtt/tracker/core/storage/impl/local/IssueRecord (java/util/Collection)
517   com/devexperts/jtt/tracker/core/issues/IssuesManager$StorageListener$1 (java/util/Iterator)
351   com/devexperts/jtt/tracker/gui/activity/spy/impl/UserMonitorStateProvider (java/awt/PointerInfo)
335   com/devexperts/jtt/tracker/core/issues/IssuesManager$StorageListener (java/util/Iterator)
280   com/devexperts/jtt/tracker/core/issues/IssuesManager$StorageListener (java/util/Set)
274   com/devexperts/jtt/common/impl/WorklogImpl
221   com/devexperts/jtt/tracker/core/jira/sync/JiraSyncService (java/util/Iterator)
218   com/devexperts/jtt/tracker/gui/log/LogTabPanelController$2 (javax/swing/event/TableModelEvent)
172   com/devexperts/jtt/util/service/AbstractService (java/util/Iterator)
165   com/devexperts/jtt/tracker/core/issues/IssuesManager$StorageListener$1
161   com/devexperts/jtt/tracker/gui/worklogs/WorklogEditorPanelController
144   com/devexperts/jtt/util/adapters/AbstractDataAdapter$3
--------------------Total: 53276------------------------
Total 5 data races reported up to this moment.
Stats gathered in 0 ms.
+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
  • No labels