[
https://issues.apache.org/jira/browse/HDDS-408?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Nanda kumar updated HDDS-408:
-----------------------------
Attachment: HDDS-408.000.patch
> 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
> Assignee: Xiaoyu Yao
> Priority: Blocker
> Fix For: 0.2.1
>
> Attachments: HDDS-408.000.patch
>
>
> 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: [email protected]
For additional commands, e-mail: [email protected]
