[
https://issues.apache.org/jira/browse/OAK-3506?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14955131#comment-14955131
]
Michael Dürig commented on OAK-3506:
------------------------------------
Committed slightly edited patch at
http://svn.apache.org/viewvc?rev=1708447&view=rev.
[~alex.parvulescu], I don't think the compaction map is the right place for
this counter. This one is for logging (as opposed to generations) and thus has
different semantics. Maybe the compaction strategy would be a better home?
Anyway, I'm leaving this issue open so we can sort this out in follow up
commits.
> 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.3.9
>
> 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)
