[
https://issues.apache.org/jira/browse/OAK-3506?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Michael Dürig updated OAK-3506:
-------------------------------
Fix Version/s: (was: 1.3.9)
1.4
> Uniformization of compaction log messages
> -----------------------------------------
>
> Key: OAK-3506
> URL: https://issues.apache.org/jira/browse/OAK-3506
> Project: Jackrabbit Oak
> Issue Type: Improvement
> Components: core
> Reporter: Valentin Olteanu
> Assignee: Michael Dürig
> Labels: compaction, gc
> Fix For: 1.4
>
> Attachments: compaction_logs.git.patch
>
>
> 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:
> # all logs start with the prefix {{TarMK GargabeCollection \{\}#:}}
> # different phases of garbage collection are easier to identify by the first
> word after prefix, e.g. estimation, compaction, cleanup
> # 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.
> # 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:
> {code}
> 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).
> {code}
> OLD:
> {code}
> 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.
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
