-
Notifications
You must be signed in to change notification settings - Fork 442
TEZ-4349. DAGClient gets stuck with invalid cached DAGStatus #161
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Changes from 1 commit
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,104 @@ | ||
| /** | ||
| * Licensed to the Apache Software Foundation (ASF) under one | ||
| * or more contributor license agreements. See the NOTICE file | ||
| * distributed with this work for additional information | ||
| * regarding copyright ownership. The ASF licenses this file | ||
| * to you under the Apache License, Version 2.0 (the | ||
| * "License"); you may not use this file except in compliance | ||
| * with the License. You may obtain a copy of the License at | ||
| * | ||
| * http://www.apache.org/licenses/LICENSE-2.0 | ||
| * | ||
| * Unless required by applicable law or agreed to in writing, software | ||
| * distributed under the License is distributed on an "AS IS" BASIS, | ||
| * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. | ||
| * See the License for the specific language governing permissions and | ||
| * limitations under the License. | ||
| */ | ||
| package org.apache.tez.common; | ||
|
|
||
| import java.util.concurrent.TimeUnit; | ||
| import java.util.concurrent.atomic.AtomicReference; | ||
|
|
||
| import org.apache.hadoop.yarn.util.Clock; | ||
| import org.apache.hadoop.yarn.util.MonotonicClock; | ||
|
|
||
| /** | ||
| * A thread safe implementation used as a container for cacheable entries with Expiration times. | ||
| * It supports custom {@link Clock} to control the elapsed time calculation. | ||
| * @param <T> the data object type. | ||
| */ | ||
| public class CachedEntity<T> { | ||
| private final AtomicReference<T> entryDataRef; | ||
| private final Clock cacheClock; | ||
| private final long expiryDurationMS; | ||
| private volatile long entryTimeStamp; | ||
|
|
||
| public CachedEntity(TimeUnit expiryTimeUnit, long expiryLength, Clock clock) { | ||
| entryDataRef = new AtomicReference<>(null); | ||
| cacheClock = clock; | ||
| expiryDurationMS = TimeUnit.MILLISECONDS.convert(expiryLength, expiryTimeUnit); | ||
| entryTimeStamp = 0; | ||
| } | ||
|
|
||
| public CachedEntity(TimeUnit expiryTimeUnit, long expiryLength) { | ||
| this(expiryTimeUnit, expiryLength, new MonotonicClock()); | ||
| } | ||
|
|
||
| /** | ||
| * | ||
| * @return true if expiration timestamp is 0, or the elapsed time since last update is | ||
| * greater than {@link #expiryDurationMS} | ||
| */ | ||
| public boolean isExpired() { | ||
| return (entryTimeStamp == 0) | ||
| || ((cacheClock.getTime() - entryTimeStamp) > expiryDurationMS); | ||
| } | ||
|
|
||
| /** | ||
| * If the entry has expired, it reset the cache reference through {@link #clearExpiredEntry()}. | ||
| * @return cached data if the timestamp is valid. Null, if the timestamp has expired. | ||
| */ | ||
| public T getValue() { | ||
| if (isExpired()) { // quick check for expiration | ||
| if (clearExpiredEntry()) { // remove reference to the expired entry | ||
| return null; | ||
| } | ||
| } | ||
| return entryDataRef.get(); | ||
| } | ||
|
|
||
| /** | ||
| * Safely sets the cached data. | ||
| * @param newEntry | ||
| */ | ||
| public void setValue(T newEntry) { | ||
| T currentEntry = entryDataRef.get(); | ||
| while (!entryDataRef.compareAndSet(currentEntry, newEntry)) { | ||
| currentEntry = entryDataRef.get(); | ||
| } | ||
| entryTimeStamp = cacheClock.getTime(); | ||
| } | ||
|
|
||
| /** | ||
| * Enforces the expiration of the cached entry. | ||
| */ | ||
| public void enforceExpiration() { | ||
| entryTimeStamp = 0; | ||
| } | ||
|
|
||
| /** | ||
| * Safely deletes the reference to the data if it was not null. | ||
| * @return true if the reference is set to Null. False indicates that another thread | ||
| * updated the cache. | ||
| */ | ||
| private boolean clearExpiredEntry() { | ||
| T currentEntry = entryDataRef.get(); | ||
| if (currentEntry == null) { | ||
| return true; | ||
| } | ||
| // the current value is not null: try to reset it. | ||
| // if the CAS is successful, then we won't override a recent update to the cache. | ||
| return (entryDataRef.compareAndSet(currentEntry, null)); | ||
| } | ||
| } |
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -27,9 +27,11 @@ | |
| import java.util.HashMap; | ||
| import java.util.Map; | ||
| import java.util.Set; | ||
| import java.util.concurrent.TimeUnit; | ||
|
|
||
| import com.google.common.annotations.VisibleForTesting; | ||
| import org.apache.hadoop.security.UserGroupInformation; | ||
| import org.apache.tez.common.CachedEntity; | ||
| import org.apache.tez.common.Preconditions; | ||
|
|
||
| import org.apache.hadoop.yarn.exceptions.ApplicationNotFoundException; | ||
|
|
@@ -58,13 +60,15 @@ public class DAGClientImpl extends DAGClient { | |
| private final String dagId; | ||
| private final TezConfiguration conf; | ||
| private final FrameworkClient frameworkClient; | ||
|
|
||
| /** | ||
| * Container to cache the last {@link DAGStatus}. | ||
| */ | ||
| private final CachedEntity<DAGStatus> cachedDAGStatusRef; | ||
| @VisibleForTesting | ||
| protected DAGClientInternal realClient; | ||
| private boolean dagCompleted = false; | ||
| private volatile boolean dagCompleted = false; | ||
| @VisibleForTesting | ||
| protected boolean isATSEnabled = false; | ||
| private DAGStatus cachedDagStatus = null; | ||
| Map<String, VertexStatus> cachedVertexStatus = new HashMap<String, VertexStatus>(); | ||
|
|
||
| private static final long SLEEP_FOR_COMPLETION = 500; | ||
|
|
@@ -110,6 +114,28 @@ public DAGClientImpl(ApplicationId appId, String dagId, TezConfiguration conf, | |
| this.diagnoticsWaitTimeout = conf.getLong( | ||
| TezConfiguration.TEZ_CLIENT_DIAGNOSTICS_WAIT_TIMEOUT_MS, | ||
| TezConfiguration.TEZ_CLIENT_DIAGNOSTICS_WAIT_TIMEOUT_MS_DEFAULT); | ||
| cachedDAGStatusRef = initCacheDAGRefFromConf(conf); | ||
| } | ||
|
|
||
| /** | ||
| * Constructs a new {@link CachedEntity} for {@link DAGStatus} | ||
| * @param conf TEZ configuration parameters. | ||
| * @return a caching entry to hold the {@link DAGStatus}. | ||
| */ | ||
| protected CachedEntity initCacheDAGRefFromConf(TezConfiguration conf) { | ||
| long clientDAGStatusCacheTimeOut = conf.getLong( | ||
| TezConfiguration.TEZ_CLIENT_DAG_STATUS_CACHE_TIMEOUT_MINUTES, | ||
| TezConfiguration.TEZ_CLIENT_DAG_STATUS_CACHE_TIMEOUT_MINUTES_DEFAULT); | ||
| if (clientDAGStatusCacheTimeOut <= 0) { | ||
| LOG.error("DAG Status cache timeout interval should be positive. Enforcing default value."); | ||
| clientDAGStatusCacheTimeOut = | ||
| TezConfiguration.TEZ_CLIENT_DAG_STATUS_CACHE_TIMEOUT_MINUTES_DEFAULT; | ||
| } | ||
| return new CachedEntity<>(TimeUnit.MINUTES, clientDAGStatusCacheTimeOut); | ||
| } | ||
|
|
||
| protected CachedEntity getCachedDAGStatusRef() { | ||
| return cachedDAGStatusRef; | ||
| } | ||
|
|
||
| @Override | ||
|
|
@@ -133,13 +159,11 @@ public DAGStatus getDAGStatus(@Nullable Set<StatusGetOpts> statusOptions, | |
| } | ||
|
|
||
| long startTime = System.currentTimeMillis(); | ||
| boolean refreshStatus; | ||
| DAGStatus dagStatus; | ||
| if(cachedDagStatus != null) { | ||
| dagStatus = cachedDagStatus; | ||
| refreshStatus = true; | ||
| } else { | ||
| // For the first lookup only. After this cachedDagStatus should be populated. | ||
|
|
||
| DAGStatus dagStatus = cachedDAGStatusRef.getValue(); | ||
| boolean refreshStatus = true; | ||
| if (dagStatus == null) { | ||
| // the first lookup only or when the cachedDAG has expired | ||
| dagStatus = getDAGStatus(statusOptions); | ||
| refreshStatus = false; | ||
| } | ||
|
|
@@ -221,13 +245,14 @@ protected DAGStatus getDAGStatusInternal(@Nullable Set<StatusGetOpts> statusOpti | |
| final DAGStatus dagStatus = getDAGStatusViaAM(statusOptions, timeout); | ||
|
|
||
| if (!dagCompleted) { | ||
| if (dagStatus != null) { | ||
| cachedDagStatus = dagStatus; | ||
| if (dagStatus != null) { // update the cached DAGStatus | ||
| cachedDAGStatusRef.setValue(dagStatus); | ||
| return dagStatus; | ||
| } | ||
| if (cachedDagStatus != null) { | ||
| DAGStatus cachedDAG = cachedDAGStatusRef.getValue(); | ||
| if (cachedDAG != null) { | ||
| // could not get from AM (not reachable/ was killed). return cached status. | ||
| return cachedDagStatus; | ||
| return cachedDAG; | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. am I right to assume this is the codepath where the original issue happened? could you please clarify how can we indefinitely stuck here? also getApplicationReportInternal keeps returning null in checkAndSetDagCompletionStatus was it the case for you?
Contributor
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Thanks for the feedback. Yes, considering the implementation of TezJob.run()-Line222 in Pig: Pig polls on the DAGStatus inside an infinite loop: while (true) {
try {
dagStatus = dagClient.getDAGStatus(null);
} catch (Exception e) {
log.info("Cannot retrieve DAG status", e);
break;
}
if (dagStatus.isCompleted()) {
// do something
// break;
}
sleep(1000);
} Let's assume the following scenario on Tez Side:
The problem in this corner case is that the Pig client will keep looping indefinitely as long as it does not receive a null or dagClient.getDAGStatus(null) does not throw an exception. |
||
| } | ||
| } | ||
|
|
||
|
|
@@ -253,8 +278,11 @@ protected DAGStatus getDAGStatusInternal(@Nullable Set<StatusGetOpts> statusOpti | |
|
|
||
| // dag completed and Timeline service is either not enabled or does not have completion status | ||
| // return cached status if completion info is present. | ||
| if (dagCompleted && cachedDagStatus != null && cachedDagStatus.isCompleted()) { | ||
| return cachedDagStatus; | ||
| if (dagCompleted) { | ||
| DAGStatus cachedDag = cachedDAGStatusRef.getValue(); | ||
| if (cachedDag != null && cachedDag.isCompleted()) { | ||
| return cachedDag; | ||
| } | ||
| } | ||
|
|
||
| // everything else fails rely on RM. | ||
|
|
||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I think we can lower this to 1 minute, especially because in case of query status stuck (that the patch is about to address) this default value will be the minimum time in which the client has the chance to realize the stuck cached progress
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I'm wondering if we actually would prefer seconds. I can see use cases that would benefit from a lower time than 1 minute.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I am fine with seconds. However, I am not so sure about the impact of setting the expiration to a small value.
For example, it is possible to have some delay in the AM executing the RPC call (or even a timeout at one time). If the expiration of the cache is smaller than the total of ("AM RPC with failure" + "wait for the client to retry" + "AM RPC"), then the cache won't serve its purpose.
If I understand correctly,
cachedDAGStatuspurpose is to protect the client from falling too soon to the RM. Correct me if I misunderstand the purpose of thecachedDAGStatus.There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
The latest commit changes the TimeUnit to seconds and the default to 60.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
thanks @amahussein, I'm assuming the default value 60s would work properly