[OAK-9488] Extra logging in org.apache.jackrabbit.oak.run.DataStoreCommand

• Type: Improvement
• Status: Closed
• Priority: Minor
• Resolution: Fixed
• Fix Version/s: 1.42.0
• Component/s: segment-azure
• Assignee: Matt Ryan
• Reporter: Paul Chibulcuteanu
• Created: 06/Jul/21 13:38
• Updated: 12/Jan/22 13:44
• Resolved: 04/Oct/21 16:43

Description

Running datastore command to retrieve the index binaries blob IDs from Azure with following options:

16.06.2021 20:49:50.452 *INFO* [main] o.a.j.oak.run.DataStoreCommand - Command line arguments used for datastore command [--dump-ref --out-dir /opt/out_dir --azureds /DataStore.config --verboseRootPath /oak:index/ --verbosePathInclusionRegex /*/:data,/*/:suggest-data --verbose] 
16.06.2021 20:49:50.454 *INFO* [main] o.a.j.oak.run.DataStoreCommand - System properties and vm options passed [-Dsegment.timeout.interval=60, -Dsegment.timeout.execution=325] 

can sometimes take minutes. This operation is usually fast(a few seconds).

The log of the command only displays little info about what is happening:

16.06.2021 20:49:50.839 *INFO* [pool-3-thread-1] o.a.j.o.plugins.blob.FileCache - Cache built with [0] files from file system in [0] seconds 
16.06.2021 20:54:45.901 *INFO* [main] o.a.j.oak.run.DataStoreCommand - Starting dump of blob references by traversing 

There is no information on where the 5 minutes is spent. It could be a network hiccup, maybe Azure connectivity issues, or too many sessions opened, but there is no way to find out. We should add extra logging in org.apache.jackrabbit.oak.run.DataStoreCommand in order to be able to investigate such slowness cases.