Nilotpal Nandi created HDDS-408:
-----------------------------------
Summary: Read (getKey) operation is very slow
Key: HDDS-408
URL: https://issues.apache.org/jira/browse/HDDS-408
Project: Hadoop Distributed Data Store
Issue Type: Bug
Components: Ozone Datanode, Ozone Manager
Reporter: Nilotpal Nandi
Fix For: 0.2.1
PutKey operation for a 2GB file took around ~42 secs .
real 0m41.955s
user 0m19.367s
sys 0m7.480s
For the same Key, getKey operation took around 8min 49 secs.
real 0m41.955s
user 0m19.367s
sys 0m7.480s
Repeated operation multiple times, results were similar.
For read operation , the client waits for a long time. In ozone.log, there is a
long trail of these messages on all datanodes :
{noformat}
2018-09-06 14:10:52,288 [BlockDeletingService#2] DEBUG
(TopNOrderedContainerDeletionChoosingPolicy.java:79) - Stop looking for next
container, there is no pending deletion block contained in remaining containers.
2018-09-06 14:11:02,413 [Datanode State Machine Thread - 0] DEBUG
(DatanodeStateMachine.java:145) - Executing cycle Number : 3350
2018-09-06 14:11:32,414 [Datanode State Machine Thread - 0] DEBUG
(DatanodeStateMachine.java:145) - Executing cycle Number : 3351
2018-09-06 14:11:41,797 [Datanode ReportManager Thread - 0] DEBUG
(ContainerSet.java:191) - Starting container report iteration.
2018-09-06 14:11:52,288 [BlockDeletingService#2] DEBUG
(TopNOrderedContainerDeletionChoosingPolicy.java:79) - Stop looking for next
container, there is no pending deletion block contained in remaining containers.
2018-09-06 14:12:02,414 [Datanode State Machine Thread - 0] DEBUG
(DatanodeStateMachine.java:145) - Executing cycle Number : 3352
2018-09-06 14:12:32,416 [Datanode State Machine Thread - 0] DEBUG
(DatanodeStateMachine.java:145) - Executing cycle Number : 3353
2018-09-06 14:12:48,723 [Datanode ReportManager Thread - 0] DEBUG
(ContainerSet.java:191) - Starting container report iteration.
2018-09-06 14:12:52,289 [BlockDeletingService#2] DEBUG
(TopNOrderedContainerDeletionChoosingPolicy.java:79) - Stop looking for next
container, there is no pending deletion block contained in remaining containers.
2018-09-06 14:13:02,416 [Datanode State Machine Thread - 0] DEBUG
(DatanodeStateMachine.java:145) - Executing cycle Number : 3354
2018-09-06 14:13:32,416 [Datanode State Machine Thread - 0] DEBUG
(DatanodeStateMachine.java:145) - Executing cycle Number : 3355
2018-09-06 14:13:52,289 [BlockDeletingService#2] DEBUG
(TopNOrderedContainerDeletionChoosingPolicy.java:79) - Stop looking for next
container, there is no pending deletion block contained in remaining containers.
2018-09-06 14:14:02,416 [Datanode State Machine Thread - 0] DEBUG
(DatanodeStateMachine.java:145) - Executing cycle Number : 3356
2018-09-06 14:14:31,725 [Datanode ReportManager Thread - 2] DEBUG
(ContainerSet.java:191) - Starting container report iteration.
2018-09-06 14:14:32,416 [Datanode State Machine Thread - 0] DEBUG
(DatanodeStateMachine.java:145) - Executing cycle Number : 3357
2018-09-06 14:14:52,290 [BlockDeletingService#2] DEBUG
(TopNOrderedContainerDeletionChoosingPolicy.java:79) - Stop looking for next
container, there is no pending deletion block contained in remaining containers.
2018-09-06 14:15:02,417 [Datanode State Machine Thread - 0] DEBUG
(DatanodeStateMachine.java:145) - Executing cycle Number : 3358
2018-09-06 14:15:32,418 [Datanode State Machine Thread - 0] DEBUG
(DatanodeStateMachine.java:145) - Executing cycle Number : 3359
2018-09-06 14:15:52,290 [BlockDeletingService#2] DEBUG
(TopNOrderedContainerDeletionChoosingPolicy.java:79) - Stop looking for next
container, there is no pending deletion block contained in remaining containers.
2018-09-06 14:16:02,419 [Datanode State Machine Thread - 0] DEBUG
(DatanodeStateMachine.java:145) - Executing cycle Number : 3360
2018-09-06 14:16:26,897 [Datanode ReportManager Thread - 0] DEBUG
(ContainerSet.java:191) - Starting container report iteration.
2018-09-06 14:16:32,420 [Datanode State Machine Thread - 0] DEBUG
(DatanodeStateMachine.java:145) - Executing cycle Number : 3361
2018-09-06 14:16:52,290 [BlockDeletingService#2] DEBUG
(TopNOrderedContainerDeletionChoosingPolicy.java:79) - Stop looking for next
container, there is no pending deletion block contained in remaining containers.
2018-09-06 14:17:02,420 [Datanode State Machine Thread - 0] DEBUG
(DatanodeStateMachine.java:145) - Executing cycle Number : 3362
2018-09-06 14:17:32,420 [Datanode State Machine Thread - 0] DEBUG
(DatanodeStateMachine.java:145) - Executing cycle Number : 3363
2018-09-06 14:17:48,024 [Datanode ReportManager Thread - 0] DEBUG
(ContainerSet.java:191) - Starting container report iteration.
2018-09-06 14:17:52,291 [BlockDeletingService#2] DEBUG
(TopNOrderedContainerDeletionChoosingPolicy.java:79) - Stop looking for next
container, there is no pending deletion block contained in remaining containers.
2018-09-06 14:18:02,421 [Datanode State Machine Thread - 0] DEBUG
(DatanodeStateMachine.java:145) - Executing cycle Number : 3364{noformat}
Only relevant logs , I could find is in the ozone.log of the node from where I
ran the getKey command ( it is also the scm node)
{noformat}
2018-09-06 14:03:51,247 [main] DEBUG (ChunkGroupInputStream.java:282) - get key
accessing 20 1536240013896
2018-09-06 14:03:52,914 [main] DEBUG (ChunkGroupInputStream.java:282) - get key
accessing 19 1536240017969
2018-09-06 14:03:53,304 [main] DEBUG (ChunkGroupInputStream.java:282) - get key
accessing 18 1536240025529
2018-09-06 14:03:53,658 [main] DEBUG (ChunkGroupInputStream.java:282) - get key
accessing 17 1536240029421
2018-09-06 14:03:54,010 [main] DEBUG (ChunkGroupInputStream.java:282) - get key
accessing 16 1536240034898
2018-09-06 14:03:54,346 [main] DEBUG (ChunkGroupInputStream.java:282) - get key
accessing 15 1536240039501
2018-09-06 14:03:54,692 [main] DEBUG (ChunkGroupInputStream.java:282) - get key
accessing 14 1536240044807
2018-09-06 14:03:55,035 [main] DEBUG (ChunkGroupInputStream.java:282) - get key
accessing 13 1536240049048
2018-09-06 14:03:55,373 [main] DEBUG (ChunkGroupInputStream.java:282) - get key
accessing 12 1536240053383
2018-09-06 14:03:55,709 [main] DEBUG (ChunkGroupInputStream.java:282) - get key
accessing 11 1536240057095
2018-09-06 14:03:56,053 [main] DEBUG (ChunkGroupInputStream.java:282) - get key
accessing 10 1536240067626
2018-09-06 14:03:56,412 [main] DEBUG (ChunkGroupInputStream.java:282) - get key
accessing 9 1536240072429
2018-09-06 14:03:56,819 [main] DEBUG (ChunkGroupInputStream.java:282) - get key
accessing 8 1536240081782
2018-09-06 14:03:57,154 [main] DEBUG (ChunkGroupInputStream.java:282) - get key
accessing 7 1536240087097
2018-09-06 14:03:57,488 [main] DEBUG (ChunkGroupInputStream.java:282) - get key
accessing 6 1536240097377
2018-09-06 14:03:57,827 [main] DEBUG (ChunkGroupInputStream.java:282) - get key
accessing 5 1536240107789
2018-09-06 14:03:58,184 [main] DEBUG (ChunkGroupInputStream.java:282) - get key
accessing 4 1536240114786
{noformat}
Also , there is no log entry seen in scm/om log files for the operation. Please
add some more logging for better debug.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
---------------------------------------------------------------------
To unsubscribe, e-mail: hdfs-issues-unsubscr...@hadoop.apache.org
For additional commands, e-mail: hdfs-issues-h...@hadoop.apache.org
