Uploaded image for project: 'Apache Ozone'
  1. Apache Ozone
  2. HDDS-408

Read (getKey) operation is very slow

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Resolved
    • Blocker
    • Resolution: Fixed
    • None
    • 0.2.1
    • Ozone Datanode, Ozone Manager
    • 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
          Nandakumar

        Activity

          People

            nanda Nandakumar
            nilotpalnandi Nilotpal Nandi
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: