jackrabbit-oak-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Michael Dürig (JIRA) <j...@apache.org>
Subject [jira] [Updated] (OAK-3506) Uniformization of compaction log messages
Date Fri, 11 Dec 2015 11:23:11 GMT

     [ https://issues.apache.org/jira/browse/OAK-3506?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

Michael Dürig updated OAK-3506:
-------------------------------
    Labels: candidate_oak_1_0 candidate_oak_1_2 compaction gc  (was: compaction gc)

> 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: candidate_oak_1_0, candidate_oak_1_2, 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)

Mime
View raw message