[
https://issues.apache.org/jira/browse/OAK-7646?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16550294#comment-16550294
]
Amit Jain commented on OAK-7646:
--------------------------------
The issue is some sort of a race condition when using MeterStats which is
backed by LongAdder and should not happen. The sequence of operations which
fail sometimes are:
* Thread 1 & 2 concurrently {{mark()}} the MeterStats i.e. increment the value
* After a few seconds {{MeterStats.getCount()}} is called
It seems that sometimes an increment update is missed by the underlying data
structures. The logs [1] have a successful and a failure invocation.
I have committed a fix with http://svn.apache.org/viewvc?rev=1836320&view=rev.
Curiously using {{mark(1)}} seems to work reliably for me. Earlier I used to
get 3-8 failures in 100 invocations of the test.
[~catholicon]/[~reschke] Could you please give it a try now.
[1]
{noformat}
11:16:57.059 INFO [main] UploadStagingCacheTest.java:431 Starting
testConcurrentSameAddRequest
11:16:57.059 INFO [main] UploadStagingCache.java:525 Uploads in progress
on close [0]
11:16:57.059 INFO [main] UploadStagingCache.java:526 Uploads completed
but not cleared from cache [0]
11:16:57.059 INFO [main] UploadStagingCache.java:527 Staging cache stats
on close [StagingCacheStats{requestCount=0, hitCount=0, hitRate=0.00,
missCount=0, missRate=0.00, loadCount=0, loadSuccessCount=0, elementCount=0,
currentMemSize=0, totalWeight=0 B, maxWeight=8.2 kB}]
11:16:57.061 INFO [main] UploadStagingCache.java:237 Scheduling pending
uploads
11:16:57.061 INFO [main] UploadStagingCache.java:259 Scheduled [0]
pending uploads
11:16:57.062 INFO [pool-318-thread-2] UploadStagingCacheTest.java:794 Starting
put
11:16:57.062 INFO [pool-318-thread-1] UploadStagingCacheTest.java:794 Starting
put
11:16:57.064 INFO [pool-318-thread-2] UploadStagingCache.java:663 After
marking request
11:16:57.064 INFO [pool-318-thread-1] UploadStagingCache.java:663 After
marking request
11:16:57.268 INFO [pool-318-thread-2] UploadStagingCache.java:332 Moved file
to staging
11:16:57.268 INFO [pool-318-thread-2] UploadStagingCache.java:338 File
[target/junit6458090256194865475/junit5039948307724460945.tmp] moved to staging
cache
[target/junit6458090256194865475/junit8471597446455288839/upload/12/34/50/123450]
11:16:57.268 INFO [pool-318-thread-1] UploadStagingCache.java:341 Already
exists in staging
11:16:57.269 DEBUG [pool-318-thread-2] UploadStagingCache.java:410 File
[target/junit6458090256194865475/junit8471597446455288839/upload/12/34/50/123450]
scheduled for upload
[com.google.common.util.concurrent.SettableFuture@3bba8a8d]
11:16:57.269 INFO [pool-318-thread-1] UploadStagingCacheTest.java:796 Finished
put
11:16:57.269 INFO [pool-318-thread-2] UploadStagingCacheTest.java:796 Finished
put
11:16:57.269 INFO [pool-318-thread-1] UploadStagingCacheTest.java:798
Retrieved file
target/junit6458090256194865475/junit8471597446455288839/upload/12/34/50/123450,
true
11:16:57.269 INFO [pool-318-thread-2] UploadStagingCacheTest.java:798
Retrieved file
target/junit6458090256194865475/junit8471597446455288839/upload/12/34/50/123450,
true
11:16:57.270 INFO [oak-async-thread-1] AbstractDataStoreCacheTest.java:91 In
TestStagingUploader after write
[target/junit6458090256194865475/junit7417157165846513127/datastore/12/34/123450]
11:16:57.270 DEBUG [oak-async-thread-1] UploadStagingCache.java:367 File added
to backend
[target/junit6458090256194865475/junit8471597446455288839/upload/12/34/50/123450]
11:16:57.270 INFO [oak-async-thread-1] UploadStagingCache.java:382
Successfully added [123450],
[target/junit6458090256194865475/junit8471597446455288839/upload/12/34/50/123450]
11:16:57.271 INFO [oak-async-thread-1] AbstractDataStoreCacheTest.java:205
After execution....after counting down latch
11:16:57.271 INFO [pool-320-thread-1] UploadStagingCache.java:448 Starting
purge of uploaded files
11:16:57.271 DEBUG [pool-320-thread-1] UploadStagingCache.java:482 Trying to
delete file
[target/junit6458090256194865475/junit8471597446455288839/upload/12/34/50/123450]
11:16:57.271 INFO [pool-320-thread-1] DataStoreCacheUtils.java:43 Deleted file
[target/junit6458090256194865475/junit8471597446455288839/upload/12/34/50/123450]
11:16:57.272 DEBUG [pool-320-thread-1] DataStoreCacheUtils.java:54 Deleted
directory
[target/junit6458090256194865475/junit8471597446455288839/upload/12/34/50],
[true]
11:16:57.272 DEBUG [pool-320-thread-1] DataStoreCacheUtils.java:54 Deleted
directory
[target/junit6458090256194865475/junit8471597446455288839/upload/12/34], [true]
11:16:57.272 DEBUG [pool-320-thread-1] DataStoreCacheUtils.java:54 Deleted
directory [target/junit6458090256194865475/junit8471597446455288839/upload/12],
[true]
11:16:57.272 DEBUG [pool-320-thread-1] UploadStagingCache.java:486 deleted file
[target/junit6458090256194865475/junit8471597446455288839/upload/12/34/50/123450]
11:16:57.272 DEBUG [pool-320-thread-1] UploadStagingCache.java:463 Cache
[target/junit6458090256194865475/junit8471597446455288839/upload/12/34/50/123450]
file deleted for id [123450]
11:16:57.272 INFO [pool-320-thread-1] UploadStagingCache.java:471 Finished
removal of [1] files
11:16:57.276 INFO [main] UploadStagingCache.java:525 Uploads in progress
on close [0]
11:16:57.276 INFO [main] UploadStagingCache.java:526 Uploads completed
but not cleared from cache [0]
11:16:57.276 INFO [main] UploadStagingCache.java:527 Staging cache stats
on close [StagingCacheStats{requestCount=1, hitCount=1, hitRate=1.00,
missCount=0, missRate=0.00, loadCount=2, loadSuccessCount=2, elementCount=0,
currentMemSize=0, totalWeight=0 B, maxWeight=8.2 kB}]
11:16:57.281 INFO [main] UploadStagingCache.java:237 Scheduling pending
uploads
11:16:57.282 INFO [main] UploadStagingCache.java:259 Scheduled [0]
pending uploads
11:16:57.282 INFO [main] UploadStagingCacheTest.java:431 Starting
testConcurrentSameAddRequest
11:16:57.282 INFO [main] UploadStagingCache.java:525 Uploads in progress
on close [0]
11:16:57.282 INFO [main] UploadStagingCache.java:526 Uploads completed
but not cleared from cache [0]
11:16:57.282 INFO [main] UploadStagingCache.java:527 Staging cache stats
on close [StagingCacheStats{requestCount=0, hitCount=0, hitRate=0.00,
missCount=0, missRate=0.00, loadCount=0, loadSuccessCount=0, elementCount=0,
currentMemSize=0, totalWeight=0 B, maxWeight=8.2 kB}]
11:16:57.283 INFO [main] UploadStagingCache.java:237 Scheduling pending
uploads
11:16:57.283 INFO [main] UploadStagingCache.java:259 Scheduled [0]
pending uploads
11:16:57.284 INFO [pool-323-thread-1] UploadStagingCacheTest.java:794 Starting
put
11:16:57.284 INFO [pool-323-thread-2] UploadStagingCacheTest.java:794 Starting
put
11:16:57.285 INFO [pool-323-thread-2] UploadStagingCache.java:663 After
marking request
11:16:57.285 INFO [pool-323-thread-1] UploadStagingCache.java:663 After
marking request
11:16:57.487 INFO [pool-323-thread-1] UploadStagingCache.java:332 Moved file
to staging
11:16:57.487 INFO [pool-323-thread-1] UploadStagingCache.java:338 File
[target/junit319329128684063956/junit3315586661403030831.tmp] moved to staging
cache
[target/junit319329128684063956/junit7462485732863919014/upload/12/34/50/123450]
11:16:57.487 INFO [pool-323-thread-2] UploadStagingCache.java:341 Already
exists in staging
11:16:57.487 DEBUG [pool-323-thread-1] UploadStagingCache.java:410 File
[target/junit319329128684063956/junit7462485732863919014/upload/12/34/50/123450]
scheduled for upload
[com.google.common.util.concurrent.SettableFuture@78533c67]
11:16:57.488 INFO [pool-323-thread-2] UploadStagingCacheTest.java:796 Finished
put
11:16:57.488 INFO [pool-323-thread-1] UploadStagingCacheTest.java:796 Finished
put
11:16:57.488 INFO [pool-323-thread-2] UploadStagingCacheTest.java:798
Retrieved file
target/junit319329128684063956/junit7462485732863919014/upload/12/34/50/123450,
true
11:16:57.488 INFO [pool-323-thread-1] UploadStagingCacheTest.java:798
Retrieved file
target/junit319329128684063956/junit7462485732863919014/upload/12/34/50/123450,
true
11:16:57.489 INFO [oak-async-thread-1] AbstractDataStoreCacheTest.java:91 In
TestStagingUploader after write
[target/junit319329128684063956/junit1579511893478899489/datastore/12/34/123450]
11:16:57.489 DEBUG [oak-async-thread-1] UploadStagingCache.java:367 File added
to backend
[target/junit319329128684063956/junit7462485732863919014/upload/12/34/50/123450]
11:16:57.489 INFO [oak-async-thread-1] UploadStagingCache.java:382
Successfully added [123450],
[target/junit319329128684063956/junit7462485732863919014/upload/12/34/50/123450]
11:16:57.489 INFO [oak-async-thread-1] AbstractDataStoreCacheTest.java:205
After execution....after counting down latch
11:16:57.490 INFO [pool-325-thread-1] UploadStagingCache.java:448 Starting
purge of uploaded files
11:16:57.490 DEBUG [pool-325-thread-1] UploadStagingCache.java:482 Trying to
delete file
[target/junit319329128684063956/junit7462485732863919014/upload/12/34/50/123450]
11:16:57.490 INFO [pool-325-thread-1] DataStoreCacheUtils.java:43 Deleted file
[target/junit319329128684063956/junit7462485732863919014/upload/12/34/50/123450]
11:16:57.490 DEBUG [pool-325-thread-1] DataStoreCacheUtils.java:54 Deleted
directory
[target/junit319329128684063956/junit7462485732863919014/upload/12/34/50],
[true]
11:16:57.491 DEBUG [pool-325-thread-1] DataStoreCacheUtils.java:54 Deleted
directory
[target/junit319329128684063956/junit7462485732863919014/upload/12/34], [true]
11:16:57.491 DEBUG [pool-325-thread-1] DataStoreCacheUtils.java:54 Deleted
directory [target/junit319329128684063956/junit7462485732863919014/upload/12],
[true]
11:16:57.491 DEBUG [pool-325-thread-1] UploadStagingCache.java:486 deleted file
[target/junit319329128684063956/junit7462485732863919014/upload/12/34/50/123450]
11:16:57.491 DEBUG [pool-325-thread-1] UploadStagingCache.java:463 Cache
[target/junit319329128684063956/junit7462485732863919014/upload/12/34/50/123450]
file deleted for id [123450]
11:16:57.491 INFO [pool-325-thread-1] UploadStagingCache.java:471 Finished
removal of [1] files
11:16:57.495 INFO [main] UploadStagingCacheTest.java:459 Finished
testConcurrentSameAddRequest
11:16:57.495 INFO [main] UploadStagingCache.java:525 Uploads in progress
on close [0]
11:16:57.495 INFO [main] UploadStagingCache.java:526 Uploads completed
but not cleared from cache [0]
11:16:57.495 INFO [main] UploadStagingCache.java:527 Staging cache stats
on close [StagingCacheStats{requestCount=2, hitCount=1, hitRate=0.50,
missCount=1, missRate=0.50, loadCount=2, loadSuccessCount=2, elementCount=0,
{noformat}
> UploadStagingCacheTest#testConcurrentSameAddRequest fails intermittently
> ------------------------------------------------------------------------
>
> Key: OAK-7646
> URL: https://issues.apache.org/jira/browse/OAK-7646
> Project: Jackrabbit Oak
> Issue Type: Test
> Components: blob-plugins
> Reporter: Vikas Saurabh
> Assignee: Amit Jain
> Priority: Minor
>
> As noted on VOTE mail thread for 1.9.6 \[0],
> {{UploadStagingCacheTest#testConcurrentSameAddRequest}} fails intermittently
> as:
> {noformat}
> [INFO] Running org.apache.jackrabbit.oak.plugins.blob.UploadStagingCacheTest
> [ERROR] Tests run: 22, Failures: 1, Errors: 0, Skipped: 0, Time
> elapsed: 15.595 s <<< FAILURE! - in
> org.apache.jackrabbit.oak.plugins.blob.UploadStagingCacheTest
> [ERROR]
> testConcurrentSameAddRequest(org.apache.jackrabbit.oak.plugins.blob.UploadStagingCacheTest)
> Time elapsed: 0.214 s <<< FAILURE!
> java.lang.AssertionError: expected:<2> but was:<1>
> at
> org.apache.jackrabbit.oak.plugins.blob.UploadStagingCacheTest.assertCacheStats(UploadStagingCacheTest.java:843)
> at
> org.apache.jackrabbit.oak.plugins.blob.UploadStagingCacheTest.testConcurrentSameAddRequest(UploadStagingCacheTest.java:456)
> [INFO]
> [INFO] Results:
> [INFO]
> [ERROR] Failures:
> [ERROR]
> UploadStagingCacheTest.testConcurrentSameAddRequest:456->assertCacheStats:843
> expected:<2> but was:<1>
> [INFO]
> [ERROR] Tests run: 179, Failures: 1, Errors: 0, Skipped: 0
> [INFO]
> [INFO]
> ------------------------------------------------------------------------
> [INFO] Reactor Summary:
> [INFO]
> [INFO] Oak Parent POM ..................................... SUCCESS
> [01:22 min]
> ....
> ....
> [INFO] Oak Blob Plugins ................................... FAILURE [
> 38.111 s]
> [INFO] Oak Core ........................................... SKIPPED
> ....
> ....
> [INFO] Jackrabbit Oak ..................................... SKIPPED
> [INFO]
> ------------------------------------------------------------------------
> [INFO] BUILD FAILURE
> [INFO]
> ------------------------------------------------------------------------
> {noformat}
> [~amjain], should I assign it to you?
> \[0]:
> https://lists.apache.org/thread.html/42e50349cd7e559f0b579093e56e421e6127a2fdec563debc393fcdd@%3Coak-dev.jackrabbit.apache.org%3E
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
