hadoop-hdfs-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Xiaoyu Yao (JIRA)" <j...@apache.org>
Subject [jira] [Assigned] (HDDS-408) Read (getKey) operation is very slow
Date Fri, 07 Sep 2018 00:01:00 GMT

     [ https://issues.apache.org/jira/browse/HDDS-408?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

Xiaoyu Yao reassigned HDDS-408:
-------------------------------

    Assignee: Xiaoyu Yao

> 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
>
>
> 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-unsubscribe@hadoop.apache.org
For additional commands, e-mail: hdfs-issues-help@hadoop.apache.org


Mime
View raw message