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 "Chetan Mehrotra (JIRA)" <ji...@apache.org> on 2017/07/18 06:23:00 UTC
[jira] [Comment Edited] (OAK-6409) Oak-run indexing: improved (user
friendly) output
[ https://issues.apache.org/jira/browse/OAK-6409?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16091171#comment-16091171 ]
Chetan Mehrotra edited comment on OAK-6409 at 7/18/17 6:22 AM:
---------------------------------------------------------------
Done following changes with 1802241,1802242
# oak-run index would now copy a logback-index.xml to work dir (default ./temp) and use that for configuring
# Logback is configured to scan the config periodically and if any change is done at runtime the changes would be picked up
# By default all info logs would be routed to temp/indexing.log
# In addition logs from following categories would be logged at info level to stdout with just time and message
{noformat}
org.apache.jackrabbit.oak.index
org.apache.jackrabbit.oak.plugins.index.importer
org.apache.jackrabbit.oak.plugins.index.IndexUpdate
org.apache.jackrabbit.oak.plugins.index.progress
{noformat}
Some run
{noformat}
Apache Jackrabbit Oak
11:28:41 - Logging configured from /mnt/hdd/data/oak/oak-run-indexing/temp/logback-indexing.xml
11:28:41 - Any change in logging config would be picked up
11:28:41 - Logs would be written to temp/indexing.log
/content/oak:index/enablementResourceName => valid
/oak:index/authorizables => valid
/oak:index/commerceLucene => valid
/oak:index/cqMobileAppLucene => valid
/oak:index/cqPageLucene => valid
/oak:index/cqProjectLucene => valid
/oak:index/cqTagLucene => valid
/oak:index/damAssetLucene => valid
/oak:index/lucene => valid
/oak:index/ntBaseLucene => valid
/oak:index/slingeventJob => valid
/oak:index/socialLucene => valid
/oak:index/versionStoreIndex => valid
/oak:index/workflowDataLucene => valid
Index consistency check report stored at /mnt/hdd/data/oak/oak-run-indexing/indexing-result/index-consistency-check-report.txt
{noformat}
Sample run for indexing
{noformat}
Apache Jackrabbit Oak 1.8-SNAPSHOT
11:39:50 - Logging configured from /mnt/hdd/data/oak/oak-run-indexing/import/temp/logback-indexing.xml
11:39:50 - Any change in logging config would be picked up
11:39:50 - Logs would be written to temp/indexing.log
11:39:51 - Created checkpoint [r15d54512839-0-2] for indexing
11:39:51 - Proceeding to reindex with read only access to NodeStore
11:39:51 - Proceeding to index [/oak:index/lucene] upto checkpoint r15d54512839-0-2 {creator=IndexCommand, created=2017-07-18T11:39:51.160+05:30}
11:39:51 - Switched the async lane for indexes at [/oak:index/lucene] to offline-reindex-async and marked them for reindex
11:39:51 - Reindexing will be performed for following indexes: [/oak:index/lucene]
11:39:51 - Paths to be traversed includedPath : [/], excludedPaths : [/etc/workflow/instances, /jcr:system, /etc/replication, /var]
11:39:51 - Estimated node count to be traversed for reindexing under / is [131072]
11:40:02 - Reindexing Traversed #10000 /content/mobileapps/we-retail/shell/jcr:content/pge-app/app-content/phonegap/res/screens/android/screen-hdpi-portrait.png/jcr:content [999.90 nodes/s, 3599640.00 nodes/hr] (Elapsed 10.76 s, Expected 2.017 min, Completed 7.63%)
11:40:02 - /oak:index/lucene => Indexed 10000 nodes in 10.75 s ...
11:40:09 - Reindexing Traversed #20000 /content/we-retail/us/en/experience/skiing-deep-powder-in-siberia/jcr:content/root/responsivegrid/content_fragment [1111.06 nodes/s, 3999800.00 nodes/hr] (Elapsed 18.06 s, Expected 99.00 s, Completed 15.26%)
11:40:09 - /oak:index/lucene => Indexed 20000 nodes in 7.303 s ...
11:40:18 - Reindexing Traversed #30000 /etc/clientlibs/social/thirdparty/ckeditor/plugins/docprops/dialogs/docprops.js [1153.81 nodes/s, 4153707.69 nodes/hr] (Elapsed 26.80 s, Expected 87.00 s, Completed 22.89%)
11:40:18 - /oak:index/lucene => Indexed 30000 nodes in 8.742 s ...
11:40:26 - Reindexing Traversed #40000 /etc/packages/day/cq560/social/calendar/cq-social-calendar-pkg-1.4.33.zip/jcr:content/vlt:definition/filter/f2 [1176.44 nodes/s, 4235188.24 nodes/hr] (Elapsed 34.57 s, Expected 77.00 s, Completed 30.52%)
11:40:26 - /oak:index/lucene => Indexed 40000 nodes in 7.771 s ...
11:40:32 - Reindexing Traversed #50000 /libs/cq/contentsync/widgets/source/widgets/ConsolePanel.js/jcr:content [1249.98 nodes/s, 4499910.00 nodes/hr] (Elapsed 40.73 s, Expected 64.00 s, Completed 38.15%)
11:40:32 - /oak:index/lucene => Indexed 50000 nodes in 6.158 s ...
11:40:41 - Reindexing Traversed #60000 /libs/cq/personalization/clientlib/kernel/source/teaser/teaser-client.js/jcr:content [1199.98 nodes/s, 4319928.00 nodes/hr] (Elapsed 50.30 s, Expected 59.00 s, Completed 45.78%)
11:40:41 - /oak:index/lucene => Indexed 60000 nodes in 9.569 s ...
11:40:48 - Reindexing Traversed #70000 /libs/cq/workflow/components/model/step/tab_common/items/timeout/items/timeoutHandler [1249.98 nodes/s, 4499935.71 nodes/hr] (Elapsed 56.54 s, Expected 48.00 s, Completed 53.41%)
11:40:48 - /oak:index/lucene => Indexed 70000 nodes in 6.240 s ...
11:40:55 - Reindexing Traversed #80000 /libs/dam/gui/content/assets/moveassetwizard/jcr:content/head [1249.98 nodes/s, 4499943.75 nodes/hr] (Elapsed 1.073 min, Expected 40.00 s, Completed 61.04%)
11:40:55 - /oak:index/lucene => Indexed 80000 nodes in 7.819 s ...
11:41:03 - Reindexing Traversed #90000 /libs/fd/af/components/actions/submit/cq:styleConfig/items/button/items/buttonText/states [1267.59 nodes/s, 4563329.58 nodes/hr] (Elapsed 1.194 min, Expected 32.00 s, Completed 68.66%)
11:41:03 - /oak:index/lucene => Indexed 90000 nodes in 7.283 s ...
11:41:09 - Reindexing Traversed #100000 /libs/foundation/components/page/tab_advanced/items/advanced/items/alias [1282.04 nodes/s, 4615338.46 nodes/hr] (Elapsed 1.308 min, Expected 24.00 s, Completed 76.29%)
11:41:09 - /oak:index/lucene => Indexed 100000 nodes in 6.819 s ...
11:41:17 - Reindexing Traversed #110000 /libs/mcm/content/tools/editleaddialog/items/tabpanel/items/address/items/country/options/Cape_Verde [1279.06 nodes/s, 4604609.30 nodes/hr] (Elapsed 1.441 min, Expected 16.00 s, Completed 83.92%)
11:41:17 - /oak:index/lucene => Indexed 110000 nodes in 7.981 s ...
11:41:25 - Reindexing Traversed #120000 /libs/settings/wcm/template-types/afpage/initial/jcr:content/guideContainer/layout [1290.31 nodes/s, 4645122.58 nodes/hr] (Elapsed 1.561 min, Expected 8.000 s, Completed 91.55%)
11:41:25 - /oak:index/lucene => Indexed 120000 nodes in 7.203 s ...
11:41:31 - Reindexing Traversed #130000 /libs/social/tally/components/hbs/liking/clientlibs/css.txt/jcr:content [1313.12 nodes/s, 4727236.36 nodes/hr] (Elapsed 1.666 min, Expected 0.000 ns, Completed 99.18%)
11:41:31 - /oak:index/lucene => Indexed 130000 nodes in 6.303 s ...
11:41:40 - Indexing report
- /oak:index/lucene*(139710)
11:41:40 - Reindexing completed
11:41:40 - Indexing completed for indexes [/oak:index/lucene] in 1.812 min (108727 ms) and index files are copied to /mnt/hdd/data/oak/oak-run-indexing/import/indexing-result/indexes
11:41:40 - To complete indexing import the created index files via IndexerMBean#importIndex operation with [/mnt/hdd/data/oak/oak-run-indexing/import/indexing-result/indexes] as input
11:41:40 - Proceeding to import index data from [/mnt/hdd/data/oak/oak-run-indexing/import/indexing-result/indexes] by connecting to NodeStore in read-write mode
11:41:40 - Proceeding to import [/oak:index/lucene] indexes from /mnt/hdd/data/oak/oak-run-indexing/import/indexing-result/indexes
11:41:40 - Done with switching of index lanes before import
11:41:40 - Importing index data for /oak:index/lucene
11:41:41 - Done with importing of index data
11:41:41 - Acquired the lock for async indexer lane [fulltext-async]
11:41:41 - Proceeding to update imported indexes [/oak:index/lucene] to checkpoint [r15d54478022-0-1] for lane [fulltext-async]
11:41:41 - Imported index is updated to repository state at checkpoint [r15d54478022-0-1] for indexing lane [fulltext-async]
11:41:41 - Remove the lock for async indexer lane [fulltext-async]
11:41:41 - Import done for indexes [/oak:index/lucene]
11:41:41 - Released the referred checkpoint [r15d54512839-0-2]
11:41:41 - Indexes imported successfully in 1.764 s (1763 ms)
11:41:41 - Indexing completed and imported successfully in 1.861 min (111644 ms)
{noformat}
[~tmueller] [~chibulcu] Thoughts? Let me know if you want to change some aspect around logging further
was (Author: chetanm):
Done following changes with 1802241,1802242
# oak-run index would now copy a logback-index.xml to work dir (default ./temp) and use that for configuring
# Logback is configured to scan the config periodically and if any change is done at runtime the changes would be picked up
# By default all info logs would be routed to temp/indexing.log
# In addition logs from following categories would be logged at info level to stdout with just time and message
{noformat}
org.apache.jackrabbit.oak.index
org.apache.jackrabbit.oak.plugins.index.importer
org.apache.jackrabbit.oak.plugins.index.IndexUpdate
org.apache.jackrabbit.oak.plugins.index.progress
{noformat}
Same run
{noformat}
Apache Jackrabbit Oak
11:28:41 - Logging configured from /mnt/hdd/data/oak/oak-run-indexing/temp/logback-indexing.xml
11:28:41 - Any change in logging config would be picked up
11:28:41 - Logs would be written to temp/indexing.log
/content/oak:index/enablementResourceName => valid
/oak:index/authorizables => valid
/oak:index/commerceLucene => valid
/oak:index/cqMobileAppLucene => valid
/oak:index/cqPageLucene => valid
/oak:index/cqProjectLucene => valid
/oak:index/cqTagLucene => valid
/oak:index/damAssetLucene => valid
/oak:index/lucene => valid
/oak:index/ntBaseLucene => valid
/oak:index/slingeventJob => valid
/oak:index/socialLucene => valid
/oak:index/versionStoreIndex => valid
/oak:index/workflowDataLucene => valid
Index consistency check report stored at /mnt/hdd/data/oak/oak-run-indexing/indexing-result/index-consistency-check-report.txt
{noformat}
Sample run for indexing
{noformat}
Apache Jackrabbit Oak 1.8-SNAPSHOT
11:39:50 - Logging configured from /mnt/hdd/data/oak/oak-run-indexing/import/temp/logback-indexing.xml
11:39:50 - Any change in logging config would be picked up
11:39:50 - Logs would be written to temp/indexing.log
11:39:51 - Created checkpoint [r15d54512839-0-2] for indexing
11:39:51 - Proceeding to reindex with read only access to NodeStore
11:39:51 - Proceeding to index [/oak:index/lucene] upto checkpoint r15d54512839-0-2 {creator=IndexCommand, created=2017-07-18T11:39:51.160+05:30}
11:39:51 - Switched the async lane for indexes at [/oak:index/lucene] to offline-reindex-async and marked them for reindex
11:39:51 - Reindexing will be performed for following indexes: [/oak:index/lucene]
11:39:51 - Paths to be traversed includedPath : [/], excludedPaths : [/etc/workflow/instances, /jcr:system, /etc/replication, /var]
11:39:51 - Estimated node count to be traversed for reindexing under / is [131072]
11:40:02 - Reindexing Traversed #10000 /content/mobileapps/we-retail/shell/jcr:content/pge-app/app-content/phonegap/res/screens/android/screen-hdpi-portrait.png/jcr:content [999.90 nodes/s, 3599640.00 nodes/hr] (Elapsed 10.76 s, Expected 2.017 min, Completed 7.63%)
11:40:02 - /oak:index/lucene => Indexed 10000 nodes in 10.75 s ...
11:40:09 - Reindexing Traversed #20000 /content/we-retail/us/en/experience/skiing-deep-powder-in-siberia/jcr:content/root/responsivegrid/content_fragment [1111.06 nodes/s, 3999800.00 nodes/hr] (Elapsed 18.06 s, Expected 99.00 s, Completed 15.26%)
11:40:09 - /oak:index/lucene => Indexed 20000 nodes in 7.303 s ...
11:40:18 - Reindexing Traversed #30000 /etc/clientlibs/social/thirdparty/ckeditor/plugins/docprops/dialogs/docprops.js [1153.81 nodes/s, 4153707.69 nodes/hr] (Elapsed 26.80 s, Expected 87.00 s, Completed 22.89%)
11:40:18 - /oak:index/lucene => Indexed 30000 nodes in 8.742 s ...
11:40:26 - Reindexing Traversed #40000 /etc/packages/day/cq560/social/calendar/cq-social-calendar-pkg-1.4.33.zip/jcr:content/vlt:definition/filter/f2 [1176.44 nodes/s, 4235188.24 nodes/hr] (Elapsed 34.57 s, Expected 77.00 s, Completed 30.52%)
11:40:26 - /oak:index/lucene => Indexed 40000 nodes in 7.771 s ...
11:40:32 - Reindexing Traversed #50000 /libs/cq/contentsync/widgets/source/widgets/ConsolePanel.js/jcr:content [1249.98 nodes/s, 4499910.00 nodes/hr] (Elapsed 40.73 s, Expected 64.00 s, Completed 38.15%)
11:40:32 - /oak:index/lucene => Indexed 50000 nodes in 6.158 s ...
11:40:41 - Reindexing Traversed #60000 /libs/cq/personalization/clientlib/kernel/source/teaser/teaser-client.js/jcr:content [1199.98 nodes/s, 4319928.00 nodes/hr] (Elapsed 50.30 s, Expected 59.00 s, Completed 45.78%)
11:40:41 - /oak:index/lucene => Indexed 60000 nodes in 9.569 s ...
11:40:48 - Reindexing Traversed #70000 /libs/cq/workflow/components/model/step/tab_common/items/timeout/items/timeoutHandler [1249.98 nodes/s, 4499935.71 nodes/hr] (Elapsed 56.54 s, Expected 48.00 s, Completed 53.41%)
11:40:48 - /oak:index/lucene => Indexed 70000 nodes in 6.240 s ...
11:40:55 - Reindexing Traversed #80000 /libs/dam/gui/content/assets/moveassetwizard/jcr:content/head [1249.98 nodes/s, 4499943.75 nodes/hr] (Elapsed 1.073 min, Expected 40.00 s, Completed 61.04%)
11:40:55 - /oak:index/lucene => Indexed 80000 nodes in 7.819 s ...
11:41:03 - Reindexing Traversed #90000 /libs/fd/af/components/actions/submit/cq:styleConfig/items/button/items/buttonText/states [1267.59 nodes/s, 4563329.58 nodes/hr] (Elapsed 1.194 min, Expected 32.00 s, Completed 68.66%)
11:41:03 - /oak:index/lucene => Indexed 90000 nodes in 7.283 s ...
11:41:09 - Reindexing Traversed #100000 /libs/foundation/components/page/tab_advanced/items/advanced/items/alias [1282.04 nodes/s, 4615338.46 nodes/hr] (Elapsed 1.308 min, Expected 24.00 s, Completed 76.29%)
11:41:09 - /oak:index/lucene => Indexed 100000 nodes in 6.819 s ...
11:41:17 - Reindexing Traversed #110000 /libs/mcm/content/tools/editleaddialog/items/tabpanel/items/address/items/country/options/Cape_Verde [1279.06 nodes/s, 4604609.30 nodes/hr] (Elapsed 1.441 min, Expected 16.00 s, Completed 83.92%)
11:41:17 - /oak:index/lucene => Indexed 110000 nodes in 7.981 s ...
11:41:25 - Reindexing Traversed #120000 /libs/settings/wcm/template-types/afpage/initial/jcr:content/guideContainer/layout [1290.31 nodes/s, 4645122.58 nodes/hr] (Elapsed 1.561 min, Expected 8.000 s, Completed 91.55%)
11:41:25 - /oak:index/lucene => Indexed 120000 nodes in 7.203 s ...
11:41:31 - Reindexing Traversed #130000 /libs/social/tally/components/hbs/liking/clientlibs/css.txt/jcr:content [1313.12 nodes/s, 4727236.36 nodes/hr] (Elapsed 1.666 min, Expected 0.000 ns, Completed 99.18%)
11:41:31 - /oak:index/lucene => Indexed 130000 nodes in 6.303 s ...
11:41:40 - Indexing report
- /oak:index/lucene*(139710)
11:41:40 - Reindexing completed
11:41:40 - Indexing completed for indexes [/oak:index/lucene] in 1.812 min (108727 ms) and index files are copied to /mnt/hdd/data/oak/oak-run-indexing/import/indexing-result/indexes
11:41:40 - To complete indexing import the created index files via IndexerMBean#importIndex operation with [/mnt/hdd/data/oak/oak-run-indexing/import/indexing-result/indexes] as input
11:41:40 - Proceeding to import index data from [/mnt/hdd/data/oak/oak-run-indexing/import/indexing-result/indexes] by connecting to NodeStore in read-write mode
11:41:40 - Proceeding to import [/oak:index/lucene] indexes from /mnt/hdd/data/oak/oak-run-indexing/import/indexing-result/indexes
11:41:40 - Done with switching of index lanes before import
11:41:40 - Importing index data for /oak:index/lucene
11:41:41 - Done with importing of index data
11:41:41 - Acquired the lock for async indexer lane [fulltext-async]
11:41:41 - Proceeding to update imported indexes [/oak:index/lucene] to checkpoint [r15d54478022-0-1] for lane [fulltext-async]
11:41:41 - Imported index is updated to repository state at checkpoint [r15d54478022-0-1] for indexing lane [fulltext-async]
11:41:41 - Remove the lock for async indexer lane [fulltext-async]
11:41:41 - Import done for indexes [/oak:index/lucene]
11:41:41 - Released the referred checkpoint [r15d54512839-0-2]
11:41:41 - Indexes imported successfully in 1.764 s (1763 ms)
11:41:41 - Indexing completed and imported successfully in 1.861 min (111644 ms)
{noformat}
[~tmueller] [~chibulcu] Thoughts? Let me know if you want to change some aspect around logging further
> Oak-run indexing: improved (user friendly) output
> -------------------------------------------------
>
> Key: OAK-6409
> URL: https://issues.apache.org/jira/browse/OAK-6409
> Project: Jackrabbit Oak
> Issue Type: Improvement
> Components: indexing
> Reporter: Thomas Mueller
> Assignee: Chetan Mehrotra
> Fix For: 1.8
>
>
> The oak-run indexing (OAK-6081) output should be human readable, and if possible minimal. Detailed output should be written to a log file, but stdout should be easy for a user to understand. For example some header info when starting, where to find the detailed output, then one line every 3 seconds about the progress (in %, number of nodes read, ETA), and when done some info on what to do next.
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)