[HDFS-12298] Ozone: Block deletion service floods the log when deleting large number of block files

• Type: Sub-task
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: HDFS-7240
• Fix Version/s: HDFS-7240
• Component/s: ozone
• Target Version/s: HDFS-7240
• Hadoop Flags: Reviewed
• Assignee: Yiqun Lin
• Reporter: Yiqun Lin
• Created: 14/Aug/17 12:37
• Updated: 26/Apr/18 21:53
• Resolved: 15/Aug/17 09:14

Description

Block deletion service will floods the log when deleting large number of blocks.
We can write a simple performance test (create a bunch of blocks file meta data but don't create real files) to reproduce this.
The following are the logs in my local.

2017-08-14 16:20:59,992 [BlockDeletingService#3] INFO  utils.BackgroundService (BackgroundService.java:run(103)) - Number of background tasks to execute : 10
2017-08-14 16:20:59,993 [BlockDeletingService#8] INFO  background.BlockDeletingService (BlockDeletingService.java:call(173))      - Container : c555fc61-d4fa-4db8-afed-3837510d301d, To-Delete blocks : 2
2017-08-14 16:20:59,993 [BlockDeletingService#1] INFO  background.BlockDeletingService (BlockDeletingService.java:call(173))      - Container : db7d6a21-e0da-4409-9b72-2ade7f1fad53, To-Delete blocks : 2
2017-08-14 16:20:59,993 [BlockDeletingService#8] INFO  background.BlockDeletingService (BlockDeletingService.java:lambda$0(177))      - Deleting block #deleting#c555fc61-d4fa-4db8-afed-3837510d301db89
2017-08-14 16:20:59,993 [BlockDeletingService#1] INFO  background.BlockDeletingService (BlockDeletingService.java:lambda$0(177))      - Deleting block #deleting#db7d6a21-e0da-4409-9b72-2ade7f1fad53b89
2017-08-14 16:20:59,997 [BlockDeletingService#2] INFO  background.BlockDeletingService (BlockDeletingService.java:call(173))      - Container : 005b32b3-c383-451b-a780-5a1a284a35a3, To-Delete blocks : 2
2017-08-14 16:20:59,997 [BlockDeletingService#2] INFO  background.BlockDeletingService (BlockDeletingService.java:lambda$0(177))      - Deleting block #deleting#005b32b3-c383-451b-a780-5a1a284a35a3b89
2017-08-14 16:20:59,998 [BlockDeletingService#6] INFO  background.BlockDeletingService (BlockDeletingService.java:call(173))      - Container : 9a7a9005-26a6-445e-a887-bee693240cb2, To-Delete blocks : 2
2017-08-14 16:21:00,005 [BlockDeletingService#6] INFO  background.BlockDeletingService (BlockDeletingService.java:lambda$0(177))      - Deleting block #deleting#9a7a9005-26a6-445e-a887-bee693240cb2b89
2017-08-14 16:21:00,005 [BlockDeletingService#1] INFO  background.BlockDeletingService (BlockDeletingService.java:lambda$0(177))      - Deleting block #deleting#db7d6a21-e0da-4409-9b72-2ade7f1fad53b9
2017-08-14 16:21:00,004 [BlockDeletingService#2] INFO  background.BlockDeletingService (BlockDeletingService.java:lambda$0(177))      - Deleting block #deleting#005b32b3-c383-451b-a780-5a1a284a35a3b9
2017-08-14 16:21:00,003 [BlockDeletingService#9] INFO  background.BlockDeletingService (BlockDeletingService.java:call(173))      - Container : 20f37c36-9ea3-46d7-9eaf-c7d3db478870, To-Delete blocks : 2
2017-08-14 16:21:00,007 [BlockDeletingService#9] INFO  background.BlockDeletingService (BlockDeletingService.java:lambda$0(177))      - Deleting block #deleting#20f37c36-9ea3-46d7-9eaf-c7d3db478870b89
2017-08-14 16:21:00,002 [BlockDeletingService#5] INFO  background.BlockDeletingService (BlockDeletingService.java:call(173))      - Container : 2b3f389c-d7fd-4990-83b5-02d8d40569e9, To-Delete blocks : 2
2017-08-14 16:21:00,001 [BlockDeletingService#0] INFO  background.BlockDeletingService (BlockDeletingService.java:call(173))      - Container : 6eabd191-54b6-4acd-bdc7-1bb05e81bd68, To-Delete blocks : 2
2017-08-14 16:21:00,000 [BlockDeletingService#4] INFO  background.BlockDeletingService (BlockDeletingService.java:call(173))      - Container : 2e16e39d-c000-41ae-afb3-1a1b3a43e9bc, To-Delete blocks : 2
2017-08-14 16:21:00,009 [BlockDeletingService#4] INFO  background.BlockDeletingService (BlockDeletingService.java:lambda$0(177))      - Deleting block #deleting#2e16e39d-c000-41ae-afb3-1a1b3a43e9bcb89
2017-08-14 16:21:00,009 [BlockDeletingService#0] INFO  background.BlockDeletingService (BlockDeletingService.java:lambda$0(177))      - Deleting block #deleting#6eabd191-54b6-4acd-bdc7-1bb05e81bd68b89
2017-08-14 16:20:59,999 [BlockDeletingService#7] INFO  background.BlockDeletingService (BlockDeletingService.java:call(173))      - Container : bed13000-8eea-42d2-a538-bd917cbef0fa, To-Delete blocks : 2
2017-08-14 16:21:00,011 [BlockDeletingService#7] INFO  background.BlockDeletingService (BlockDeletingService.java:lambda$0(177))      - Deleting block #deleting#bed13000-8eea-42d2-a538-bd917cbef0fab89
2017-08-14 16:21:00,000 [BlockDeletingService#8] INFO  background.BlockDeletingService (BlockDeletingService.java:lambda$0(177))      - Deleting block #deleting#c555fc61-d4fa-4db8-afed-3837510d301db9
2017-08-14 16:21:00,008 [BlockDeletingService#5] INFO  background.BlockDeletingService (BlockDeletingService.java:lambda$0(177))      - Deleting block #deleting#2b3f389c-d7fd-4990-83b5-02d8d40569e9b89
2017-08-14 16:21:00,023 [BlockDeletingService#0] INFO  background.BlockDeletingService (BlockDeletingService.java:lambda$0(177))      - Deleting block #deleting#6eabd191-54b6-4acd-bdc7-1bb05e81bd68b9
2017-08-14 16:21:00,027 [BlockDeletingService#7] INFO  background.BlockDeletingService (BlockDeletingService.java:lambda$0(177))      - Deleting block #deleting#bed13000-8eea-42d2-a538-bd917cbef0fab9
2017-08-14 16:21:00,037 [BlockDeletingService#4] INFO  background.BlockDeletingService (BlockDeletingService.java:lambda$0(177))      - Deleting block #deleting#2e16e39d-c000-41ae-afb3-1a1b3a43e9bcb9
2017-08-14 16:21:00,041 [BlockDeletingService#5] INFO  background.BlockDeletingService (BlockDeletingService.java:lambda$0(177))      - Deleting block #deleting#2b3f389c-d7fd-4990-83b5-02d8d40569e9b9
2017-08-14 16:21:00,055 [BlockDeletingService#6] INFO  background.BlockDeletingService (BlockDeletingService.java:lambda$0(177))      - Deleting block #deleting#9a7a9005-26a6-445e-a887-bee693240cb2b9
2017-08-14 16:21:00,056 [BlockDeletingService#9] INFO  background.BlockDeletingService (BlockDeletingService.java:lambda$0(177))      - Deleting block #deleting#20f37c36-9ea3-46d7-9eaf-c7d3db478870b9
2017-08-14 16:21:00,139 [BlockDeletingService#7] INFO  background.BlockDeletingService (BlockDeletingService.java:call(173))      - Container : 0448a714-1f06-4e1c-943e-e2726fce3f05, To-Delete blocks : 2
2017-08-14 16:21:00,139 [BlockDeletingService#7] INFO  background.BlockDeletingService (BlockDeletingService.java:lambda$0(177))      - Deleting block #deleting#0448a714-1f06-4e1c-943e-e2726fce3f05b89
2017-08-14 16:21:00,143 [BlockDeletingService#7] INFO  background.BlockDeletingService (BlockDeletingService.java:lambda$0(177))      - Deleting block #deleting#0448a714-1f06-4e1c-943e-e2726fce3f05b9
2017-08-14 16:21:00,505 [main] INFO  common.TestBlockDeletingService (TestBlockDeletingService.java:waitComplete(252))      - Pending deleting blocks : 10.
2017-08-14 16:21:01,256 [BlockDeletingService#3] INFO  utils.BackgroundService (BackgroundService.java:run(95)) - Running background service : BlockDeletingService
2017-08-14 16:21:01,256 [BlockDeletingService#3] INFO  utils.BackgroundService (BackgroundService.java:run(103)) - Number of background tasks to execute : 10

We should use DEBUG or TRACE level to replace INFO level here.