[YARN-4159] False-positive of ACK slow log in DFSClient

• Type: Bug
• Status: Resolved
• Priority: Minor
• Resolution: Invalid
• Affects Version/s: 2.6.0
• Component/s: client
• Assignee: Unassigned
• Reporter: He Tianyi
• Created: 15/Sep/15 10:21
• Updated: 15/Sep/15 13:05
• Resolved: 15/Sep/15 13:04

Description

This issue is related with code below:

if (duration > dfsclientSlowLogThresholdMs
    && ack.getSeqno() != Packet.HEART_BEAT_SEQNO) {
  DFSClient.LOG
      .warn("Slow ReadProcessor read fields took " + duration
          + "ms (threshold=" + dfsclientSlowLogThresholdMs + "ms); ack: "
          + ack + ", targets: " + Arrays.asList(targets));
} else if (DFSClient.LOG.isDebugEnabled()) {
  DFSClient.LOG.debug("DFSClient " + ack);
}

DFSClient prints slow log when awaited after unexpected amount of time (usually 30000 ms). This is a good indicator for network or I/O performance issue.

However, there is scenario that this slow log is false-positive, i.e. a reducer, (StageA) iterates over records with identical key, this takes arbitrary amount of time, but generates no output. (StageB) Then, it output arbitrary number of records when meet a different key.

If one StageA lasts more than 30000 ms (as the example above), there will be one or more slow log generated, which is not related to any HDFS performance issue.
In general cases, user should not expect this, as they could be misguided.