HDFS Slow Put

[#1]

3 node HDP cluster with 10Gb network 3 X 2 TB (7200rpm) ea node

master (node 1), worker2 (node 2), worker3 (node 3)

why is it slow when putting a file in hdfs?

[client1@master1 txt]$ ls -l
total 1203488
-rw-rw-r--. 1 client1 client1   4314198 Feb 20 11:51 random1.txt
-rw-rw-r--. 1 client1 client1 482564279 Nov  2  2016 random1.log
-rw-rw-r--. 1 client1 client1 745472547 May 15 15:03 random1.log.txt
-rwxrwxrwx. 1 client1 client1       183 May 15 14:05 transfer2hdfs.sh


[client1@master1 txt]$ ./transfer2hdfs.sh random1.txt
Fri May 19 09:05:56 +08 2017
Fri May 19 09:06:10 +08 2017
14

[client1@master1 txt]$ ./transfer2hdfs.sh random1.log.txt
Fri May 19 09:08:11 +08 2017
Fri May 19 09:09:31 +08 2017
80
[client1@master1 txt]$ ./transfer2hdfs.sh random1.log
Fri May 19 09:09:41 +08 2017
Fri May 19 09:10:35 +08 2017
54

[#2 · Accepted solution]

Hi Mel!,

Are you using hdfs dfs commands in your script? If you are, try to add

--loglevel TRACE

to the hdfs commands, so that we can see at which point most of the time is being spent.

Best regards,

--

Tomas

[#3]

@tsokorai

Hi Tomas,

Upon check trace, it takes 13-15secs Sending DataTransferOp.

17/06/05 15:06:26 TRACE datatransfer.DataTransferProtocol: Sending DataTransferOp OpWriteBlockProto: header {
17/06/05 15:06:41 TRACE datatransfer.DataTransferProtocol: Sending DataTransferOp OpWriteBlockProto: header
17/06/05 15:07:02 TRACE datatransfer.DataTransferProtocol: Sending DataTransferOp OpWriteBlockProto: header {
17/06/05 15:07:16 TRACE datatransfer.DataTransferProtocol: Sending DataTransferOp OpWriteBlockProto: header {

[#4]

@mel mendoza

Hi Mel,

It looks like the data transfer itself is taking the time. Could be network.

Are these nodes virtual machines or are they physical nodes?

Also, can you take a look in your datanode logs (/var/log/hadoop/hdfs/hadoop-hdfs-datanode* on each node), and look for some slowness message like "Slow BlockReceiver" ?

Best Regards,

--

Tomas

[#5]

@tsokorai

Upon checking, I'm having a slow blockreceiver.

Server 3
2017-06-05 13:17:34,210 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6316ms (threshold=300ms)
2017-06-05 13:17:41,421 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6378ms (threshold=300ms)
2017-06-05 13:17:46,730 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6316ms (threshold=300ms)
2017-06-05 13:17:47,431 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6316ms (threshold=300ms)
2017-06-05 13:17:47,966 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6315ms (threshold=300ms)
2017-06-05 13:17:55,893 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6379ms (threshold=300ms)
2017-06-05 13:18:29,615 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6472ms (threshold=300ms)
2017-06-05 13:18:35,108 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6379ms (threshold=300ms)
2017-06-05 13:18:35,994 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6059ms (threshold=300ms)
2017-06-05 13:19:16,052 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6320ms (threshold=300ms)
2017-06-05 13:19:22,431 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6059ms (threshold=300ms)
2017-06-05 13:20:02,761 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6299ms (threshold=300ms)
2017-06-05 13:20:09,140 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6059ms (threshold=300ms)
2017-06-05 13:20:13,156 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6317ms (threshold=300ms)
2017-06-05 14:18:31,029 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6440ms (threshold=300ms)
2017-06-05 14:19:29,885 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6348ms (threshold=300ms)
2017-06-05 14:19:44,370 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6348ms (threshold=300ms)
2017-06-05 14:21:17,524 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6315ms (threshold=300ms)
2017-06-05 14:21:47,190 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6315ms (threshold=300ms)
2017-06-05 14:22:01,013 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6315ms (threshold=300ms)
2017-06-05 14:38:36,960 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6346ms (threshold=300ms)
2017-06-05 14:38:52,316 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6347ms (threshold=300ms)
2017-06-05 14:39:22,903 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6316ms (threshold=300ms)
2017-06-05 14:42:13,357 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6316ms (threshold=300ms)
2017-06-05 14:42:27,970 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6316ms (threshold=300ms)
2017-06-05 14:43:12,248 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6316ms (threshold=300ms)
2017-06-05 14:43:27,225 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6379ms (threshold=300ms)
2017-06-05 15:06:50,003 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6315ms (threshold=300ms)
2017-06-05 15:07:05,381 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6316ms (threshold=300ms)
2017-06-06 04:50:36,118 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6286ms (threshold=300ms)



Server 2
2017-06-05 13:20:26,755 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6326ms (threshold=300ms)
2017-06-05 13:20:33,072 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 5996ms (threshold=300ms)
2017-06-05 13:20:33,366 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6379ms (threshold=300ms)
2017-06-05 14:19:06,478 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6317ms (threshold=300ms)
2017-06-05 14:19:21,001 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6317ms (threshold=300ms)
2017-06-05 14:19:35,321 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6316ms (threshold=300ms)
2017-06-05 14:21:53,394 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6317ms (threshold=300ms)
2017-06-05 14:22:36,143 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6316ms (threshold=300ms)
2017-06-05 14:22:50,619 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6317ms (threshold=300ms)
2017-06-05 14:38:33,079 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6315ms (threshold=300ms)
2017-06-05 14:39:27,543 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6317ms (threshold=300ms)
2017-06-05 14:40:01,897 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6316ms (threshold=300ms)
2017-06-05 14:43:02,861 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6317ms (threshold=300ms)
2017-06-05 14:43:17,503 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6317ms (threshold=300ms)
2017-06-05 15:06:20,526 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6315ms (threshold=300ms)
2017-06-05 15:06:35,291 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6316ms (threshold=300ms)
2017-06-05 15:06:56,859 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6317ms (threshold=300ms)
2017-06-05 15:07:38,618 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6347ms (threshold=300ms)
2017-06-05 15:19:27,961 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6317ms (threshold=300ms)
2017-06-05 15:30:20,450 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6316ms (threshold=300ms)
2017-06-06 04:50:49,974 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6303ms (threshold=300ms)

Server 1 
2017-06-05 14:43:44,558 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6317ms (threshold=300ms)
2017-06-05 14:43:50,876 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6037ms (threshold=300ms)
2017-06-05 14:43:59,473 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6379ms (threshold=300ms)
2017-06-05 14:44:05,853 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6060ms (threshold=300ms)
2017-06-05 15:06:32,905 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6378ms (threshold=300ms)
2017-06-05 15:06:39,222 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6036ms (threshold=300ms)
2017-06-05 15:06:47,670 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6378ms (threshold=300ms)
2017-06-05 15:06:53,987 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 5997ms (threshold=300ms)
2017-06-05 15:07:09,238 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6378ms (threshold=300ms)
2017-06-05 15:07:15,555 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 5997ms (threshold=300ms)
2017-06-05 15:07:22,323 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6317ms (threshold=300ms)
2017-06-05 15:07:28,640 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 5996ms (threshold=300ms)
2017-06-05 15:07:37,701 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6315ms (threshold=300ms)
2017-06-05 15:07:44,018 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 5997ms (threshold=300ms)
2017-06-05 15:07:50,966 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6379ms (threshold=300ms)
2017-06-05 15:07:57,314 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6029ms (threshold=300ms)
2017-06-05 15:19:40,342 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6408ms (threshold=300ms)
2017-06-05 15:19:46,659 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 5997ms (threshold=300ms)
2017-06-05 15:30:32,832 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 6410ms (threshold=300ms)
2017-06-05 15:30:39,150 WARN  datanode.DataNode (BlockReceiver.java:receivePacket(571)) - Slow BlockReceiver write packet to mirror took 5997ms (threshold=300ms)

[#6]

Hi @mel mendoza

Yes, that was exactly what I was thinking that could be happening.

You have networking issues on your data nodes.

Take a look a the typical configuration issues that could cause this, like checking the network interfaces for dropped packets, that they (both the node's eth interfaces and the communication equipment between them) are set in the correct speed and duplex mode, and that they have proper MTU settings.

Best regards,

--

Tomas

[#7]

@tsokorai

Upon check server network side, MTU is 9000. Is there any configuration in hadoop side?