jackrabbit-oak-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Chetan Mehrotra (JIRA)" <j...@apache.org>
Subject [jira] [Comment Edited] (OAK-3436) Prevent missing checkpoint due to unstable topology from causing complete reindexing
Date Fri, 25 Sep 2015 11:37:04 GMT

    [ https://issues.apache.org/jira/browse/OAK-3436?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14907888#comment-14907888
] 

Chetan Mehrotra edited comment on OAK-3436 at 9/25/15 11:37 AM:
----------------------------------------------------------------

[testcase patch|^OAK-3436-0.patch] for reproducing the scenario.

Had to modify {{AsyncIndexUpdate}} to allow configuring the lease timeout easily. Whats happening
is like this

{{AsyncIndexUpdate}} maintains an array of temp checkpoints which are released before indexing
is done. Upon each indexing cycle new checkpoint that gets created is pushed to this array.

Now assume you have 2 cluster nodes and each running AsyncIndexUpdate (N1 and N2). 

# Base state - Indexing done and current checkpoint stored in {{:async}} is CP1
# Async indexer starts on N2 and creates a new checkpoint CP2. At time T1 - It updates the
tmp checkpoint array with CP2 and proceed for 
indexing. Indexing is yet not complete
# At this stage async indexer starts on N1 and sees base checkpoint as CP1 with CP2 in tmp
checkpoint array. Also due to some reason default 15 min lease time has also expired. So at
time T2 this run proceeds further and removed the tmp checkpoint CP2 
# Now async indexer on N2 completes and releases CP1 (base checkpoint) and updates the {{:async}}
node with lease status
# Now async indexer on N1 also proceeds but commit fails due to concurrent update on {{:async}}
# Now at some point async indexer on N2 starts again and looks for CP2 but its has already
been removed!

If we move cleanup of tmp checkpoint to finally clause in run method this then current working
checkpoint would not get lost

[~alex.parvulescu] [~amitj_76] Thoughts?

{noformat}
15:28:56.420 INFO  [main] DocumentNodeStore.java:545        Initialized DocumentNodeStore
with clusterNodeId: 1 (no cluster node info)
15:28:56.444 INFO  [main] DocumentNodeStore.java:545        Initialized DocumentNodeStore
with clusterNodeId: 2 (no cluster node info)
15:28:56.595 DEBUG [main] AsyncIndexUpdate.java:268         [async] Running background index
task
15:28:56.611 INFO  [main] AsyncIndexUpdate.java:307         [async] Initial index update
15:28:56.679 INFO  [aysnc-index-update-async] IndexUpdate.java:117 Reindexing will be performed
for following indexes: [/oak:index/rootIndex]
15:28:56.692 INFO  [aysnc-index-update-async] IndexUpdate.java:226 Indexing report
    - /oak:index/rootIndex*(1)

15:28:56.712 INFO  [aysnc-index-update-async] AsyncIndexUpdate.java:449 [async] Reindexing
completed for indexes: [/oak:index/rootIndex*(1)] in 94.72 ms
15:28:56.744 INFO  [main] AsyncIndexUpdateClusterTest.java:108 ===== Phase 1 - Created base
setup
15:28:56.759 DEBUG [Thread-1] AsyncIndexUpdate.java:268     [async] Running background index
task
15:28:56.793 INFO  [main] AsyncIndexUpdateClusterTest.java:128 ===== Phase 2 - async2 now
waiting for signal
15:28:56.797 DEBUG [Thread-2] AsyncIndexUpdate.java:268     [async] Running background index
task
15:28:56.805 DEBUG [aysnc-index-update-async] AsyncIndexUpdate.java:224 [async] Releasing
temporary checkpoint r15003f0fde9-0-2: true
15:28:56.811 INFO  [main] AsyncIndexUpdateClusterTest.java:141 ===== Phase 3 - async1 now
waiting for signal
15:28:56.812 DEBUG [aysnc-index-update-async] IndexUpdate.java:228 Indexing report
    - /oak:index/rootIndex(1)

15:28:56.822 DEBUG [aysnc-index-update-async] AsyncIndexUpdate.java:463 [async] AsyncIndex
update run completed in 43.90 ms. Indexed 1 nodes
15:28:56.824 DEBUG [aysnc-index-update-async] IndexUpdate.java:228 Indexing report
    - /oak:index/rootIndex(2)

15:28:56.860 WARN  [aysnc-index-update-async] AsyncIndexUpdate.java:359 [async] The index
update failed
org.apache.jackrabbit.oak.plugins.document.FailedWithConflictException: OakMerge0004: The
node 1:/:async was changed in revision
r15003f0fe30-0-2, which was applied after the base revision
r15003f0fe26-0-1, before
r15003f0fe52-0-1
	at org.apache.jackrabbit.oak.plugins.document.ConflictException.asCommitFailedException(ConflictException.java:59)
~[classes/:na]
	at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreBranch$InMemory.merge(DocumentNodeStoreBranch.java:494)
~[classes/:na]
	at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreBranch.merge0(DocumentNodeStoreBranch.java:173)
~[classes/:na]
	at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreBranch.merge(DocumentNodeStoreBranch.java:129)
~[classes/:na]
	at org.apache.jackrabbit.oak.plugins.document.DocumentRootBuilder.merge(DocumentRootBuilder.java:158)
~[classes/:na]
	at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStore.merge(DocumentNodeStore.java:1556)
~[classes/:na]
	at org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate.mergeWithConcurrencyCheck(AsyncIndexUpdate.java:493)
~[classes/:na]
	at org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate.access$400(AsyncIndexUpdate.java:76)
~[classes/:na]
	at org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate$AsyncUpdateCallback.close(AsyncIndexUpdate.java:242)
~[classes/:na]
	at org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate.updateIndex(AsyncIndexUpdate.java:454)
~[classes/:na]
	at org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate.run(AsyncIndexUpdate.java:336)
~[classes/:na]
	at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]
Caused by: org.apache.jackrabbit.oak.plugins.document.ConflictException: The node 1:/:async
was changed in revision
r15003f0fe30-0-2, which was applied after the base revision
r15003f0fe26-0-1, before
r15003f0fe52-0-1
	at org.apache.jackrabbit.oak.plugins.document.Commit.checkConflicts(Commit.java:579) ~[classes/:na]
	at org.apache.jackrabbit.oak.plugins.document.Commit.createOrUpdateNode(Commit.java:485)
~[classes/:na]
	at org.apache.jackrabbit.oak.plugins.document.Commit.applyToDocumentStore(Commit.java:369)
~[classes/:na]
	at org.apache.jackrabbit.oak.plugins.document.Commit.applyToDocumentStore(Commit.java:263)
~[classes/:na]
	at org.apache.jackrabbit.oak.plugins.document.Commit.applyInternal(Commit.java:232) ~[classes/:na]
	at org.apache.jackrabbit.oak.plugins.document.Commit.apply(Commit.java:217) ~[classes/:na]
	at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreBranch.persist(DocumentNodeStoreBranch.java:282)
~[classes/:na]
	at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreBranch.persist(DocumentNodeStoreBranch.java:252)
~[classes/:na]
	at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreBranch.access$300(DocumentNodeStoreBranch.java:54)
~[classes/:na]
	at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreBranch$InMemory.merge(DocumentNodeStoreBranch.java:490)
~[classes/:na]
	... 10 common frames omitted
15:28:56.865 INFO  [main] AsyncIndexUpdateClusterTest.java:154 ===== Phase 4 - Both async
allowed to complete
15:28:56.874 DEBUG [main] AsyncIndexUpdate.java:268         [async] Running background index
task
15:28:56.875 WARN  [main] AsyncIndexUpdate.java:292         [async] Failed to retrieve previously
indexed checkpoint r15003f0fde9-0-2; re-running the initial index update
15:28:56.876 DEBUG [aysnc-index-update-async] AsyncIndexUpdate.java:224 [async] Releasing
temporary checkpoint r15003f0fd51-0-1: true
15:28:56.876 DEBUG [aysnc-index-update-async] AsyncIndexUpdate.java:224 [async] Releasing
temporary checkpoint r15003f0fde9-0-2: true
15:28:56.880 INFO  [aysnc-index-update-async] IndexUpdate.java:152 Found a new index node
[rootIndex]. Reindexing is requested
15:28:56.886 INFO  [aysnc-index-update-async] IndexUpdate.java:117 Reindexing will be performed
for following indexes: [/oak:index/rootIndex]
15:28:56.897 INFO  [aysnc-index-update-async] IndexUpdate.java:226 Indexing report
    - /oak:index/rootIndex*(3)

15:28:56.915 INFO  [aysnc-index-update-async] AsyncIndexUpdate.java:449 [async] Reindexing
completed for indexes: [/oak:index/rootIndex*(3)] in 39.43 ms
15:28:56.920 INFO  [main] AsyncIndexUpdateClusterTest.java:161 ===== Phase 5 - Triggered next
cycle on async2
{noformat}

Logs from the testcase. Near end it can be seen that checkpoints have gone missing and reindexing
is being performed




was (Author: chetanm):
[testcase patch|^OAK-3436-0.patch] for reproducing the scenario.

Had to modify {{AsyncIndexUpdate}} to allow configuring the lease timeout easily. Whats happening
is like this

{{AsyncIndexUpdate}} maintains an array of temp checkpoints which are released before indexing
is done. Upon each indexing cycle new checkpoint that gets created is pushed to this array.

Now assume you have 2 cluster nodes and each running AsyncIndexUpdate (N1 and N2). 

# Base state - Indexing done and current checkpoint stored in {{:async}} is CP1
# Async indexer starts on N2 and creates a new checkpoint CP2. At time T1 - It updates the
tmp checkpoint array with CP2 and proceed for 
indexing. Indexing is yet not complete
# At this stage async indexer starts on N1 and sees base checkpoint as CP1 with CP2 in tmp
checkpoint array. Also due to some reason default 15 min lease time has also expired. So at
time T2 this run proceeds further and removed the tmp checkpoint CP2 
# Now async indexer on N2 completes and releases CP1 (base checkpoint) and updates the {{:async}}
node with lease status
# Now async indexer on N1 also proceeds but commit fails due to concurrent update on {{:async}}
# Now at some point async indexer on N2 starts again and looks for CP2 but its has already
been removed!

If we move cleanup of tmp checkpoint to finally clause in run method this then current working
checkpoint would not get lost

[~alex.parvulescu] [~amitj_76] Thoughts?



> Prevent missing checkpoint due to unstable topology from causing complete reindexing
> ------------------------------------------------------------------------------------
>
>                 Key: OAK-3436
>                 URL: https://issues.apache.org/jira/browse/OAK-3436
>             Project: Jackrabbit Oak
>          Issue Type: Improvement
>          Components: query
>            Reporter: Chetan Mehrotra
>            Assignee: Chetan Mehrotra
>             Fix For: 1.3.7, 1.2.7, 1.0.22
>
>         Attachments: AsyncIndexUpdateClusterTest.java, OAK-3436-0.patch
>
>
> Async indexing logic relies on embedding application to ensure that async indexing job
is run as a singleton in a cluster. For Sling based apps it depends on Sling Discovery support.
At times it is being seen that if topology is not stable then different cluster nodes can
consider them as leader and execute the async indexing job concurrently.
> This can cause problem as both cluster node might not see same repository state (due
to write skew and eventual consistency) and might remove the checkpoint which other cluster
node is still relying upon. For e.g. consider a 2 node cluster N1 and N2 where both are performing
async indexing.
> # Base state - CP1 is the checkpoint for "async" job
> # N2 starts indexing and removes changes CP1 to CP2. For Mongo the checkpoints are saved
in {{settings}} collection
> # N1 also decides to execute indexing but has yet not seen the latest repository state
so still thinks that CP1 is the base checkpoint and tries to read it. However CP1 is already
removed from {{settings}} and this makes N1 think that checkpoint is missing and it decides
to reindex everything!
> To avoid this topology must be stable but at Oak level we should still handle such a
case and avoid doing a full reindexing. So we would need to have a {{MissingCheckpointStrategy}}
similar to {{MissingIndexEditorStrategy}} as done in OAK-2203 
> Possible approaches
> # A1 - Fail the indexing run if checkpoint is missing - Checkpoint being missing can
have valid reason and invalid reason. Need to see what are valid scenarios where a checkpoint
can go missing
> # A2 - When a checkpoint is created also store the creation time. When a checkpoint is
found to be missing and its a *recent* checkpoint then fail the run. For e.g. we would fail
the run till checkpoint found to be missing is less than an hour old (for just started take
startup time into account)



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Mime
View raw message