Uploaded image for project: 'Hadoop Distributed Data Store'
  1. Hadoop Distributed Data Store
  2. HDDS-408

Read (getKey) operation is very slow

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Blocker
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 0.2.1
    • Labels:
      None

      Description

      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 :

       

      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

       

       

      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)

       

       

      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
       
      

       

       

      Also , there is no log entry seen in scm/om log files for the operation. Please add some more logging for better debug.

       

        Attachments

        1. HDDS-408.000.patch
          2 kB
          Nanda kumar

          Activity

            People

            • Assignee:
              nanda Nanda kumar
              Reporter:
              nilotpalnandi Nilotpal Nandi
            • Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: