I am getting the "Slow ReadProcessor read" log in my cluster when I increase the socket timeout for client.
16/04/14 17:57:59 WARN DataStreamer: Slow ReadProcessor read fields for block BP-873267638-192.168.100.12-1460002479721:blk_1073752739_11917 took 47858ms (threshold=30000ms); ack: seqno: 3 reply: SUCCESS reply: SUCCESS reply: SUCCESS downstreamAckTimeNanos: 803180 flag: 0 flag: 0 flag: 0, targets: [DatanodeInfoWithStorage[192.168.100.9:25009,DS-d552bfd7-1c38-430d-8703-c3b539caf351,DISK], DatanodeInfoWithStorage[192.168.100.11:25009,DS-02897c9b-bceb-4790-b08a-f711d8e3fd81,DISK], DatanodeInfoWithStorage[192.168.100.10:25009,DS-fae7b497-a269-4614-afe5-7006660eafcf,DISK]]
But when I checked the packet send time, it is same as packet acknowledge time
16/04/14 17:57:59 DEBUG DataStreamer: DataStreamer block BP-873267638-192.168.100.12-1460002479721:blk_1073752739_11917 sending packet packet seqno: 3 offsetInBlock: 8704 lastPacketInBlock: false lastByteOffsetInBlock: 12316
This is coming because ResponseProcessor set the current time as begin time and wait for the packet ack, after getting the ack it will calculate the duration and compare with the dfs.client.slow.io.warning.threshold.ms.
long begin = Time.monotonicNow();
long duration = Time.monotonicNow() - begin;
Suppose client sent two packets and now he doesn't have data to write, after some time he got more data and sent third packet.
Client waited for some time after sending second packet. Time between second packet and third packet should not be considered by ResponseProcessor in packet acknowledge duration.