[
https://issues.apache.org/jira/browse/TEZ-3967?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17088651#comment-17088651
]
László Bodor commented on TEZ-3967:
-----------------------------------
[~jeagles]: in [^TEZ-3967.03.patch], there is a pluggable "instrumented"
read-write lock, what I've used in the unit tests, for instance:
{code}
mvn test -Dtest=TestDAGImpl#testGroupDAGCompletionWithCommitSuccess -pl tez-dag
{code}
I can see that the numbers were better in case of the new approach, let me
share some numbers
I believe the most important is "AVG_LOCK_BLOCKED" kind of numbers, which shows
the average time spent before and after calling .lock() (I guess this is the
best way to check for how much time a thread is blocked blocked because of
locks)
with an average 1ms improvement per lock, it can add up into a major
improvement for a bigger/longer dag (considering that
testGroupDAGCompletionWithCommitSuccess is a quite short-living unit test)
WITHOUT THE PATCH:
average blocked time for write lock: 2.8, 3.42, 2.82
{code}
READ_AVG_LOCK_BLOCKED_TIMES_MS: 2.1760985915492954,
READ_COUNT_LOCK_ACQUIRED_BY_LOCK_METHOD: 71,
READ_MAX_LOCK_BLOCKED_TIME_MS: 15.031,
READ_SUM_LOCK_BLOCKED_TIMES_MS: 154.503,
WRITE_AVG_LOCK_BLOCKED_TIMES_MS: 2.809090909090909,
WRITE_COUNT_LOCK_ACQUIRED_BY_LOCK_METHOD: 11,
WRITE_MAX_LOCK_BLOCKED_TIME_MS: 16.09,
WRITE_SUM_LOCK_BLOCKED_TIME_MS: 30.9]
READ_AVG_LOCK_BLOCKED_TIMES_MS: 2.330492957746479,
READ_COUNT_LOCK_ACQUIRED_BY_LOCK_METHOD: 71,
READ_MAX_LOCK_BLOCKED_TIME_MS: 18.983,
READ_SUM_LOCK_BLOCKED_TIMES_MS: 165.465,
WRITE_AVG_LOCK_BLOCKED_TIMES_MS: 3.4274545454545455,
WRITE_COUNT_LOCK_ACQUIRED_BY_LOCK_METHOD: 11,
WRITE_MAX_LOCK_BLOCKED_TIME_MS: 17.092,
WRITE_SUM_LOCK_BLOCKED_TIME_MS: 37.702]
READ_AVG_LOCK_BLOCKED_TIMES_MS: 2.427774647887324,
READ_COUNT_LOCK_ACQUIRED_BY_LOCK_METHOD: 71,
READ_MAX_LOCK_BLOCKED_TIME_MS: 15.377,
READ_SUM_LOCK_BLOCKED_TIMES_MS: 172.372,
WRITE_AVG_LOCK_BLOCKED_TIMES_MS: 2.8256363636363635,
WRITE_COUNT_LOCK_ACQUIRED_BY_LOCK_METHOD: 11,
WRITE_MAX_LOCK_BLOCKED_TIME_MS: 16.377,
WRITE_SUM_LOCK_BLOCKED_TIME_MS: 31.082]
{code}
WITH THE PATCH:
average blocked time for write lock: 2.01, 1.51, 1.65
{code}
READ_AVG_LOCK_BLOCKED_TIMES_MS: 1.8155,
READ_COUNT_LOCK_ACQUIRED_BY_LOCK_METHOD: 60,
READ_MAX_LOCK_BLOCKED_TIME_MS: 6.974,
READ_SUM_LOCK_BLOCKED_TIMES_MS: 108.93,
WRITE_AVG_LOCK_BLOCKED_TIMES_MS: 2.0169,
WRITE_COUNT_LOCK_ACQUIRED_BY_LOCK_METHOD: 10,
WRITE_MAX_LOCK_BLOCKED_TIME_MS: 4.047,
WRITE_SUM_LOCK_BLOCKED_TIME_MS: 20.169]
READ_AVG_LOCK_BLOCKED_TIMES_MS: 1.46175,
READ_COUNT_LOCK_ACQUIRED_BY_LOCK_METHOD: 60,
READ_MAX_LOCK_BLOCKED_TIME_MS: 5.533,
READ_SUM_LOCK_BLOCKED_TIMES_MS: 87.705,
WRITE_AVG_LOCK_BLOCKED_TIMES_MS: 1.5105,
WRITE_COUNT_LOCK_ACQUIRED_BY_LOCK_METHOD: 10,
WRITE_MAX_LOCK_BLOCKED_TIME_MS: 3.642,
WRITE_SUM_LOCK_BLOCKED_TIME_MS: 15.105]
READ_AVG_LOCK_BLOCKED_TIMES_MS: 1.50095,
READ_COUNT_LOCK_ACQUIRED_BY_LOCK_METHOD: 60,
READ_MAX_LOCK_BLOCKED_TIME_MS: 4.009,
READ_SUM_LOCK_BLOCKED_TIMES_MS: 90.057,
WRITE_AVG_LOCK_BLOCKED_TIMES_MS: 1.6573,
WRITE_COUNT_LOCK_ACQUIRED_BY_LOCK_METHOD: 10,
WRITE_MAX_LOCK_BLOCKED_TIME_MS: 5.042,
WRITE_SUM_LOCK_BLOCKED_TIME_MS: 16.573]
{code}
> DAGImpl: dag lock is unfair and can starve the writers
> ------------------------------------------------------
>
> Key: TEZ-3967
> URL: https://issues.apache.org/jira/browse/TEZ-3967
> Project: Apache Tez
> Issue Type: Bug
> Reporter: Gopal Vijayaraghavan
> Assignee: László Bodor
> Priority: Major
> Attachments: TEZ-3967.01.patch, TEZ-3967.02.patch, TEZ-3967.03.patch
>
>
> Found when debugging HIVE-20103, that a reader arriving when another reader
> is active can postpone a writer from obtaining a write-lock.
> This is fundamentally bad for the DAGImpl as useful progress can only happen
> when the writeLock is held.
> {code}
> public void handle(DAGEvent event) {
> ...
> try {
> writeLock.lock();
> {code}
> {code}
> java.lang.Thread.State: WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for <0x00007efb02246f40> (a
> java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
> at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
> at
> java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:943)
> at org.apache.tez.dag.app.dag.impl.DAGImpl.handle(DAGImpl.java:1162)
> at org.apache.tez.dag.app.dag.impl.DAGImpl.handle(DAGImpl.java:149)
> at
> org.apache.tez.dag.app.DAGAppMaster$DagEventDispatcher.handle(DAGAppMaster.java:2251)
> at
> org.apache.tez.dag.app.DAGAppMaster$DagEventDispatcher.handle(DAGAppMaster.java:2242)
> at
> org.apache.tez.common.AsyncDispatcher.dispatch(AsyncDispatcher.java:180)
> at
> org.apache.tez.common.AsyncDispatcher$1.run(AsyncDispatcher.java:115)
> at java.lang.Thread.run(Thread.java:745)
> {code}
> while read-lock is passed around between
> {code}
> at
> org.apache.tez.dag.app.dag.impl.DAGImpl.getDAGStatus(DAGImpl.java:901)
> at
> org.apache.tez.dag.app.dag.impl.DAGImpl.getDAGStatus(DAGImpl.java:940)
> at
> org.apache.tez.dag.api.client.DAGClientHandler.getDAGStatus(DAGClientHandler.java:73)
> {code}
> calls.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
