Author: cdouglas
Date: Tue Apr 21 08:24:55 2009
New Revision: 767067
URL: http://svn.apache.org/viewvc?rev=767067&view=rev
Log:
HADOOP-5625. Add operation duration to clienttrace. Contributed by Lei Xu
Modified:
hadoop/core/trunk/CHANGES.txt
hadoop/core/trunk/src/hdfs/org/apache/hadoop/hdfs/server/datanode/BlockReceiver.java
hadoop/core/trunk/src/hdfs/org/apache/hadoop/hdfs/server/datanode/BlockSender.java
hadoop/core/trunk/src/hdfs/org/apache/hadoop/hdfs/server/datanode/DataNode.java
hadoop/core/trunk/src/hdfs/org/apache/hadoop/hdfs/server/datanode/DataXceiver.java
hadoop/core/trunk/src/mapred/org/apache/hadoop/mapred/TaskTracker.java
Modified: hadoop/core/trunk/CHANGES.txt
URL:
http://svn.apache.org/viewvc/hadoop/core/trunk/CHANGES.txt?rev=767067&r1=767066&r2=767067&view=diff
==============================================================================
--- hadoop/core/trunk/CHANGES.txt (original)
+++ hadoop/core/trunk/CHANGES.txt Tue Apr 21 08:24:55 2009
@@ -246,6 +246,8 @@
HADOOP-5697. Change org.apache.hadoop.examples.Grep to use new
mapreduce api. (Amareshwari Sriramadasu via sharad)
+ HADOOP-5625. Add operation duration to clienttrace. (Lei Xu via cdouglas)
+
OPTIMIZATIONS
HADOOP-5595. NameNode does not need to run a replicator to choose a
Modified:
hadoop/core/trunk/src/hdfs/org/apache/hadoop/hdfs/server/datanode/BlockReceiver.java
URL:
http://svn.apache.org/viewvc/hadoop/core/trunk/src/hdfs/org/apache/hadoop/hdfs/server/datanode/BlockReceiver.java?rev=767067&r1=767066&r2=767067&view=diff
==============================================================================
---
hadoop/core/trunk/src/hdfs/org/apache/hadoop/hdfs/server/datanode/BlockReceiver.java
(original)
+++
hadoop/core/trunk/src/hdfs/org/apache/hadoop/hdfs/server/datanode/BlockReceiver.java
Tue Apr 21 08:24:55 2009
@@ -747,6 +747,7 @@
private synchronized void lastDataNodeRun() {
long lastHeartbeat = System.currentTimeMillis();
boolean lastPacket = false;
+ final long startTime = ClientTraceLog.isInfoEnabled() ?
System.nanoTime() : 0;
while (running && datanode.shouldRun && !lastPacket) {
long now = System.currentTimeMillis();
@@ -794,6 +795,7 @@
if (pkt.lastPacketInBlock) {
if (!receiver.finalized) {
receiver.close();
+ final long endTime = ClientTraceLog.isInfoEnabled() ?
System.nanoTime() : 0;
block.setNumBytes(receiver.offsetInBlock);
datanode.data.finalizeBlock(block);
datanode.myMetrics.blocksWritten.inc();
@@ -805,7 +807,7 @@
ClientTraceLog.info(String.format(DN_CLIENTTRACE_FORMAT,
receiver.inAddr, receiver.myAddr, block.getNumBytes(),
"HDFS_WRITE", receiver.clientName, offset,
- datanode.dnRegistration.getStorageID(), block));
+ datanode.dnRegistration.getStorageID(), block,
endTime-startTime));
} else {
LOG.info("Received block " + block +
" of size " + block.getNumBytes() +
@@ -843,6 +845,7 @@
}
boolean lastPacketInBlock = false;
+ final long startTime = ClientTraceLog.isInfoEnabled() ?
System.nanoTime() : 0;
while (running && datanode.shouldRun && !lastPacketInBlock) {
try {
@@ -918,6 +921,7 @@
// file and finalize the block before responding success
if (lastPacketInBlock && !receiver.finalized) {
receiver.close();
+ final long endTime = ClientTraceLog.isInfoEnabled() ?
System.nanoTime() : 0;
block.setNumBytes(receiver.offsetInBlock);
datanode.data.finalizeBlock(block);
datanode.myMetrics.blocksWritten.inc();
@@ -929,7 +933,7 @@
ClientTraceLog.info(String.format(DN_CLIENTTRACE_FORMAT,
receiver.inAddr, receiver.myAddr, block.getNumBytes(),
"HDFS_WRITE", receiver.clientName, offset,
- datanode.dnRegistration.getStorageID(), block));
+ datanode.dnRegistration.getStorageID(), block,
endTime-startTime));
} else {
LOG.info("Received block " + block +
" of size " + block.getNumBytes() +
Modified:
hadoop/core/trunk/src/hdfs/org/apache/hadoop/hdfs/server/datanode/BlockSender.java
URL:
http://svn.apache.org/viewvc/hadoop/core/trunk/src/hdfs/org/apache/hadoop/hdfs/server/datanode/BlockSender.java?rev=767067&r1=767066&r2=767067&view=diff
==============================================================================
---
hadoop/core/trunk/src/hdfs/org/apache/hadoop/hdfs/server/datanode/BlockSender.java
(original)
+++
hadoop/core/trunk/src/hdfs/org/apache/hadoop/hdfs/server/datanode/BlockSender.java
Tue Apr 21 08:24:55 2009
@@ -357,6 +357,7 @@
long totalRead = 0;
OutputStream streamForSendChunks = out;
+ final long startTime = ClientTraceLog.isInfoEnabled() ? System.nanoTime()
: 0;
try {
try {
checksum.writeHeader(out);
@@ -412,7 +413,8 @@
}
} finally {
if (clientTraceFmt != null) {
- ClientTraceLog.info(String.format(clientTraceFmt, totalRead,
initialOffset));
+ final long endTime = System.nanoTime();
+ ClientTraceLog.info(String.format(clientTraceFmt, totalRead,
initialOffset, endTime - startTime));
}
close();
}
Modified:
hadoop/core/trunk/src/hdfs/org/apache/hadoop/hdfs/server/datanode/DataNode.java
URL:
http://svn.apache.org/viewvc/hadoop/core/trunk/src/hdfs/org/apache/hadoop/hdfs/server/datanode/DataNode.java?rev=767067&r1=767066&r2=767067&view=diff
==============================================================================
---
hadoop/core/trunk/src/hdfs/org/apache/hadoop/hdfs/server/datanode/DataNode.java
(original)
+++
hadoop/core/trunk/src/hdfs/org/apache/hadoop/hdfs/server/datanode/DataNode.java
Tue Apr 21 08:24:55 2009
@@ -142,7 +142,9 @@
", cliID: %s" + // DFSClient id
", offset: %s" + // offset
", srvID: %s" + // DatanodeRegistration
- ", blockid: %s"; // block id
+ ", blockid: %s" + // block id
+ ", duration: %s"; // duration time
+
static final Log ClientTraceLog =
LogFactory.getLog(DataNode.class.getName() + ".clienttrace");
Modified:
hadoop/core/trunk/src/hdfs/org/apache/hadoop/hdfs/server/datanode/DataXceiver.java
URL:
http://svn.apache.org/viewvc/hadoop/core/trunk/src/hdfs/org/apache/hadoop/hdfs/server/datanode/DataXceiver.java?rev=767067&r1=767066&r2=767067&view=diff
==============================================================================
---
hadoop/core/trunk/src/hdfs/org/apache/hadoop/hdfs/server/datanode/DataXceiver.java
(original)
+++
hadoop/core/trunk/src/hdfs/org/apache/hadoop/hdfs/server/datanode/DataXceiver.java
Tue Apr 21 08:24:55 2009
@@ -164,7 +164,7 @@
clientName.length() > 0 && ClientTraceLog.isInfoEnabled()
? String.format(DN_CLIENTTRACE_FORMAT, localAddress, remoteAddress,
"%d", "HDFS_READ", clientName, "%d",
- datanode.dnRegistration.getStorageID(), block)
+ datanode.dnRegistration.getStorageID(), block, "%d")
: datanode.dnRegistration + " Served block " + block + " to " +
s.getInetAddress();
try {
Modified: hadoop/core/trunk/src/mapred/org/apache/hadoop/mapred/TaskTracker.java
URL:
http://svn.apache.org/viewvc/hadoop/core/trunk/src/mapred/org/apache/hadoop/mapred/TaskTracker.java?rev=767067&r1=767066&r2=767067&view=diff
==============================================================================
--- hadoop/core/trunk/src/mapred/org/apache/hadoop/mapred/TaskTracker.java
(original)
+++ hadoop/core/trunk/src/mapred/org/apache/hadoop/mapred/TaskTracker.java Tue
Apr 21 08:24:55 2009
@@ -116,7 +116,8 @@
", dest: %s" + // dst IP
", bytes: %s" + // byte count
", op: %s" + // operation
- ", cliID: %s"; // task id
+ ", cliID: %s" + // task id
+ ", duration: %s"; // duration
public static final Log ClientTraceLog =
LogFactory.getLog(TaskTracker.class.getName() + ".clienttrace");
@@ -2960,8 +2961,11 @@
TaskTracker tracker =
(TaskTracker) context.getAttribute("task.tracker");
+ long startTime = 0;
try {
shuffleMetrics.serverHandlerBusy();
+ if(ClientTraceLog.isInfoEnabled())
+ startTime = System.nanoTime();
outStream = response.getOutputStream();
JobConf conf = (JobConf) context.getAttribute("conf");
LocalDirAllocator lDirAlloc =
@@ -3045,12 +3049,13 @@
if (null != mapOutputIn) {
mapOutputIn.close();
}
+ final long endTime = ClientTraceLog.isInfoEnabled() ?
System.nanoTime() : 0;
shuffleMetrics.serverHandlerFree();
if (ClientTraceLog.isInfoEnabled()) {
ClientTraceLog.info(String.format(MR_CLIENTTRACE_FORMAT,
request.getLocalAddr() + ":" + request.getLocalPort(),
request.getRemoteAddr() + ":" + request.getRemotePort(),
- totalRead, "MAPRED_SHUFFLE", mapId));
+ totalRead, "MAPRED_SHUFFLE", mapId, endTime-startTime));
}
}
outStream.close();
