You are viewing a plain text version of this content. The canonical link for it is here.
Posted to oak-issues@jackrabbit.apache.org by "Michael Dürig (JIRA)" <ji...@apache.org> on 2015/10/26 16:49:27 UTC
[jira] [Resolved] (OAK-3506) Uniformization of compaction log
messages
[ https://issues.apache.org/jira/browse/OAK-3506?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Michael Dürig resolved OAK-3506.
--------------------------------
Resolution: Fixed
Resolving thus. Thanks Alex!
> 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)