[OAK-3506] Uniformization of compaction log messages

• Type: Improvement
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Fix Version/s: 1.3.9, 1.4
• Component/s: core
• Labels: compaction gc
• Epic Link: SegmentMK revision GC
• Assignee: Michael Dürig
• Reporter: Valentin Olteanu
• Created: 12/Oct/15 15:11
• Updated: 16/Feb/21 09:52
• Resolved: 26/Oct/15 15:49

Description

The logs generated during different phases of tar garbage collection (compaction) are currently quite heterogenous and difficult to grep/parse.

I propose with the attached patch to uniformize these logs, changing the following:

1. all logs start with the prefix TarMK GargabeCollection {}#:
2. different phases of garbage collection are easier to identify by the first word after prefix, e.g. estimation, compaction, cleanup
3. all values are also printed in a standard unit, with the following format: <human_readable_value> (<standard_unit_value>). This makes extraction of information much easier.
4. messages corresponding to the same cycle (run) can be grouped by including the runId in the prefix.

Note1: I don't have enough visibility, but the changes might impact any system relying on the old format. Yet, I've seen they have changed before so this might not be a real concern.

Note2: the runId is implemented as a static variable, which is reset every time the class is reloaded (e.g. at restart), so it is unique only during one run.

Below you can find an excerpt of old logs and new logs to compare:

NEW:

12.10.2015 16:11:56.705 *INFO* [TarMK compaction thread [/Users/volteanu/workspace/test/qp/quickstart-author-4502/crx-quickstart/repository/segmentstore], active since Mon Oct 12 16:11:56 CEST 2015, previous max duration 0ms] org.apache.jackrabbit.oak.plugins.segment.file.FileStore TarMK GarbageCollection #1: started
12.10.2015 16:11:56.707 *INFO* [TarMK compaction thread [/Users/volteanu/workspace/test/qp/quickstart-author-4502/crx-quickstart/repository/segmentstore], active since Mon Oct 12 16:11:56 CEST 2015, previous max duration 0ms] org.apache.jackrabbit.oak.plugins.segment.file.FileStore TarMK GarbageCollection #1: estimation started
12.10.2015 16:11:59.275 *INFO* [TarMK compaction thread [/Users/volteanu/workspace/test/qp/quickstart-author-4502/crx-quickstart/repository/segmentstore], active since Mon Oct 12 16:11:56 CEST 2015, previous max duration 0ms] org.apache.jackrabbit.oak.plugins.segment.file.FileStore TarMK GarbageCollection #1: estimation completed in 2.569 s (2567 ms). Gain is 16% or 1.1 GB/1.3 GB (1062364160/1269737472 bytes), so running compaction
12.10.2015 16:11:59.275 *INFO* [TarMK compaction thread [/Users/volteanu/workspace/test/qp/quickstart-author-4502/crx-quickstart/repository/segmentstore], active since Mon Oct 12 16:11:56 CEST 2015, previous max duration 0ms] org.apache.jackrabbit.oak.plugins.segment.file.FileStore TarMK GarbageCollection #1: compaction started, strategy=CompactionStrategy{paused=false, cloneBinaries=false, cleanupType=CLEAN_OLD, olderThan=36000000, memoryThreshold=5, persistedCompactionMap=true, retryCount=5, forceAfterFail=true, compactionStart=1444659116706, offlineCompaction=false}
12.10.2015 16:12:05.839 *INFO* [TarMK compaction thread [/Users/volteanu/workspace/test/qp/quickstart-author-4502/crx-quickstart/repository/segmentstore], active since Mon Oct 12 16:11:56 CEST 2015, previous max duration 0ms] org.apache.jackrabbit.oak.plugins.segment.Compactor Finished compaction: 420022 nodes, 772259 properties, 20544 binaries.
12.10.2015 16:12:07.459 *INFO* [TarMK compaction thread [/Users/volteanu/workspace/test/qp/quickstart-author-4502/crx-quickstart/repository/segmentstore], active since Mon Oct 12 16:11:56 CEST 2015, previous max duration 0ms] org.apache.jackrabbit.oak.plugins.segment.file.FileStore TarMK GarbageCollection #1: compaction completed in 8.184 s (8183 ms), after 0 cycles
12.10.2015 16:12:11.912 *INFO* [TarMK flush thread [/Users/volteanu/workspace/test/qp/quickstart-author-4502/crx-quickstart/repository/segmentstore], active since Mon Oct 12 16:12:11 CEST 2015, previous max duration 10ms] org.apache.jackrabbit.oak.plugins.segment.file.FileStore TarMK GarbageCollection #1: cleanup started. Current repository size is 1.4 GB (1368899584 bytes)
12.10.2015 16:12:12.368 *INFO* [TarMK flush thread [/Users/volteanu/workspace/test/qp/quickstart-author-4502/crx-quickstart/repository/segmentstore], active since Mon Oct 12 16:12:11 CEST 2015, previous max duration 10ms] org.apache.jackrabbit.oak.plugins.segment.file.FileStore TarMK GarbageCollection #1: cleanup marking file for deletion: data00008a.tar
12.10.2015 16:12:12.434 *INFO* [TarMK flush thread [/Users/volteanu/workspace/test/qp/quickstart-author-4502/crx-quickstart/repository/segmentstore], active since Mon Oct 12 16:12:11 CEST 2015, previous max duration 10ms] org.apache.jackrabbit.oak.plugins.segment.file.FileStore TarMK GarbageCollection #1: cleanup completed in 522.8 ms (522 ms). Post cleanup size is 1.2 GB (1217132544 bytes)and space reclaimed 151.8 MB (151767040 bytes). Compaction map weight/depth is 0 B/1 (0 bytes/1).

OLD:

12.10.2015 15:54:55.115 *INFO* [TarMK compaction thread [/Users/volteanu/workspace/test/qp/quickstart-author-4502/crx-quickstart/repository/segmentstore], active since Mon Oct 12 15:54:55 CEST 2015, previous max duration 0ms] org.apache.jackrabbit.oak.plugins.segment.file.FileStore TarMK compaction started
12.10.2015 15:54:56.082 *INFO* [TarMK compaction thread [/Users/volteanu/workspace/test/qp/quickstart-author-4502/crx-quickstart/repository/segmentstore], active since Mon Oct 12 15:54:55 CEST 2015, previous max duration 0ms] org.apache.jackrabbit.oak.plugins.segment.file.FileStore Estimated compaction in 967.6 ms, gain is 7% (1083809280/1170960384) or (1.1 GB/1.2 GB), so running compaction
12.10.2015 15:54:56.083 *INFO* [TarMK compaction thread [/Users/volteanu/workspace/test/qp/quickstart-author-4502/crx-quickstart/repository/segmentstore], active since Mon Oct 12 15:54:55 CEST 2015, previous max duration 0ms] org.apache.jackrabbit.oak.plugins.segment.file.FileStore TarMK compaction running, strategy=CompactionStrategy{paused=false, cloneBinaries=false, cleanupType=CLEAN_OLD, olderThan=36000000, memoryThreshold=5, persistedCompactionMap=true, retryCount=5, forceAfterFail=true, compactionStart=1444658095115, offlineCompaction=false}
12.10.2015 15:55:01.986 *INFO* [TarMK compaction thread [/Users/volteanu/workspace/test/qp/quickstart-author-4502/crx-quickstart/repository/segmentstore], active since Mon Oct 12 15:54:55 CEST 2015, previous max duration 0ms] org.apache.jackrabbit.oak.plugins.segment.Compactor Finished compaction: 419878 nodes, 771824 properties, 20542 binaries.
12.10.2015 15:55:03.273 *INFO* [TarMK compaction thread [/Users/volteanu/workspace/test/qp/quickstart-author-4502/crx-quickstart/repository/segmentstore], active since Mon Oct 12 15:54:55 CEST 2015, previous max duration 0ms] org.apache.jackrabbit.oak.plugins.segment.file.FileStore TarMK compaction completed after 0 cycles in 7190ms
12.10.2015 15:55:08.032 *INFO* [TarMK flush thread [/Users/volteanu/workspace/test/qp/quickstart-author-4502/crx-quickstart/repository/segmentstore], active since Mon Oct 12 15:55:08 CEST 2015, previous max duration 10ms] org.apache.jackrabbit.oak.plugins.segment.file.FileStore TarMK revision cleanup started. Current repository size 1.3 GB
12.10.2015 15:55:08.719 *INFO* [TarMK flush thread [/Users/volteanu/workspace/test/qp/quickstart-author-4502/crx-quickstart/repository/segmentstore], active since Mon Oct 12 15:55:08 CEST 2015, previous max duration 10ms] org.apache.jackrabbit.oak.plugins.segment.file.FileStore TarMK revision cleanup completed in 688.0 ms. Post cleanup size is 1.3 GB and space reclaimed 0. Compaction map weight/depth is 0 B/1.