Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Ensure cache gets properly updated with concurrent access for action with attachments #4183

Merged
merged 4 commits into from Dec 17, 2018

Conversation

chetanmeh
Copy link
Member

@tysonnorris notices with concurrent action invocation scenario that same attachment is being fetched multiple times in case of cache miss.

Description

If multiple request try to load an action with attachment which is not present in cache then currently it leads to multiple request to load the same attachment from backing store. This PR adds a new test which demonstrate this behavior. This test would try to concurrently read action (5 threads). Without fix you would see logs like below which show that attachment is being read multiple times

db logs [2018-12-17T08:50:49.800Z] [DEBUG] [#tid_7] [LocalEntitlementProvider] checking user 'anon-nKWrAIa7elnkH4XMmEEsb75ZB9v' has privilege 'READ' for 'actions/anon-nKWrAIa7elnkH4XMmEEsb75ZB9v/action_tests_name2'
[2018-12-17T08:50:49.800Z] [DEBUG] [#tid_6] [LocalEntitlementProvider] checking user 'anon-nKWrAIa7elnkH4XMmEEsb75ZB9v' has privilege 'READ' for 'actions/anon-nKWrAIa7elnkH4XMmEEsb75ZB9v/action_tests_name2'
[2018-12-17T08:50:49.800Z] [DEBUG] [#tid_4] [LocalEntitlementProvider] checking user 'anon-nKWrAIa7elnkH4XMmEEsb75ZB9v' has privilege 'READ' for 'actions/anon-nKWrAIa7elnkH4XMmEEsb75ZB9v/action_tests_name2'
[2018-12-17T08:50:49.800Z] [DEBUG] [#tid_3] [LocalEntitlementProvider] checking user 'anon-nKWrAIa7elnkH4XMmEEsb75ZB9v' has privilege 'READ' for 'actions/anon-nKWrAIa7elnkH4XMmEEsb75ZB9v/action_tests_name2'
[2018-12-17T08:50:49.800Z] [DEBUG] [#tid_5] [LocalEntitlementProvider] checking user 'anon-nKWrAIa7elnkH4XMmEEsb75ZB9v' has privilege 'READ' for 'actions/anon-nKWrAIa7elnkH4XMmEEsb75ZB9v/action_tests_name2'
[2018-12-17T08:50:49.801Z] [DEBUG] [#tid_3] [LocalEntitlementProvider] authorized
[2018-12-17T08:50:49.801Z] [DEBUG] [#tid_7] [LocalEntitlementProvider] authorized
[2018-12-17T08:50:49.801Z] [DEBUG] [#tid_4] [LocalEntitlementProvider] authorized
[2018-12-17T08:50:49.801Z] [DEBUG] [#tid_5] [LocalEntitlementProvider] authorized
[2018-12-17T08:50:49.802Z] [DEBUG] [#tid_6] [LocalEntitlementProvider] authorized
[2018-12-17T08:50:49.803Z] [DEBUG] [#tid_5] [WhiskAction] read initiated
[2018-12-17T08:50:49.803Z] [INFO] [#tid_5] [WhiskAction] [GET] serving from datastore: CacheKey(anon-nKWrAIa7elnkH4XMmEEsb75ZB9v/action_tests_name2) [marker:database_cacheMiss_count:5]
[2018-12-17T08:50:49.803Z] [INFO] [#tid_5] [CouchDbRestStore] [GET] 'whisk_local_whisks' finding document: 'id: anon-nKWrAIa7elnkH4XMmEEsb75ZB9v/action_tests_name2' [marker:database_getDocument_start:5]
[2018-12-17T08:50:49.804Z] [DEBUG] [#tid_4] [WhiskAction] coalesced read
[2018-12-17T08:50:49.804Z] [DEBUG] [#tid_7] [WhiskAction] coalesced read
[2018-12-17T08:50:49.805Z] [DEBUG] [#tid_6] [WhiskAction] coalesced read
[2018-12-17T08:50:49.805Z] [INFO] [#tid_4] [WhiskAction] [GET] serving from cache: CacheKey(anon-nKWrAIa7elnkH4XMmEEsb75ZB9v/action_tests_name2) [marker:database_cacheHit_count:7]
[2018-12-17T08:50:49.805Z] [INFO] [#tid_7] [WhiskAction] [GET] serving from cache: CacheKey(anon-nKWrAIa7elnkH4XMmEEsb75ZB9v/action_tests_name2) [marker:database_cacheHit_count:7]
[2018-12-17T08:50:49.805Z] [INFO] [#tid_6] [WhiskAction] [GET] serving from cache: CacheKey(anon-nKWrAIa7elnkH4XMmEEsb75ZB9v/action_tests_name2) [marker:database_cacheHit_count:7]
[2018-12-17T08:50:49.806Z] [DEBUG] [#tid_3] [WhiskAction] coalesced read
[2018-12-17T08:50:49.806Z] [INFO] [#tid_3] [WhiskAction] [GET] serving from cache: CacheKey(anon-nKWrAIa7elnkH4XMmEEsb75ZB9v/action_tests_name2) [marker:database_cacheHit_count:8]
[2018-12-17T08:50:49.814Z] [INFO] [#tid_5] [CouchDbRestStore] [marker:database_getDocument_finish:16:11]
[2018-12-17T08:50:49.824Z] [DEBUG] [#tid_5] [WhiskAction] read backend part done, now marking cache entry as done
[2018-12-17T08:50:49.825Z] [DEBUG] [#tid_5] [Entry] read finished
[2018-12-17T08:50:49.828Z] [INFO] [#tid_6] [CouchDbRestStore] [ATT_GET] 'whisk_local_whisks' finding attachment '75ee1112-fcdb-4043-ae11-12fcdbb043e7' of document 'id: anon-nKWrAIa7elnkH4XMmEEsb75ZB9v/action_tests_name2, rev: 2-d43fa9eb21253e04d440162630082ce9' [marker:database_getDocumentAttachment_start:30]
[2018-12-17T08:50:49.830Z] [INFO] [#tid_4] [CouchDbRestStore] [ATT_GET] 'whisk_local_whisks' finding attachment '75ee1112-fcdb-4043-ae11-12fcdbb043e7' of document 'id: anon-nKWrAIa7elnkH4XMmEEsb75ZB9v/action_tests_name2, rev: 2-d43fa9eb21253e04d440162630082ce9' [marker:database_getDocumentAttachment_start:32]
[2018-12-17T08:50:49.831Z] [INFO] [#tid_5] [CouchDbRestStore] [ATT_GET] 'whisk_local_whisks' finding attachment '75ee1112-fcdb-4043-ae11-12fcdbb043e7' of document 'id: anon-nKWrAIa7elnkH4XMmEEsb75ZB9v/action_tests_name2, rev: 2-d43fa9eb21253e04d440162630082ce9' [marker:database_getDocumentAttachment_start:33]
[2018-12-17T08:50:49.831Z] [INFO] [#tid_7] [CouchDbRestStore] [ATT_GET] 'whisk_local_whisks' finding attachment '75ee1112-fcdb-4043-ae11-12fcdbb043e7' of document 'id: anon-nKWrAIa7elnkH4XMmEEsb75ZB9v/action_tests_name2, rev: 2-d43fa9eb21253e04d440162630082ce9' [marker:database_getDocumentAttachment_start:33]
[2018-12-17T08:50:49.832Z] [INFO] [#tid_3] [CouchDbRestStore] [ATT_GET] 'whisk_local_whisks' finding attachment '75ee1112-fcdb-4043-ae11-12fcdbb043e7' of document 'id: anon-nKWrAIa7elnkH4XMmEEsb75ZB9v/action_tests_name2, rev: 2-d43fa9eb21253e04d440162630082ce9' [marker:database_getDocumentAttachment_start:34]
[2018-12-17T08:50:49.872Z] [INFO] [#tid_6] [CouchDbRestStore] [marker:database_getDocumentAttachment_finish:74:44]
[2018-12-17T08:50:49.875Z] [INFO] [#tid_6] [WhiskAction] write initiated on new cache entry
[2018-12-17T08:50:49.875Z] [DEBUG] [#tid_6] [ActionsApiTests] [GET] entity success
[2018-12-17T08:50:49.875Z] [DEBUG] [#tid_6] [WhiskAction] write backend part done, now marking cache entry as done
[2018-12-17T08:50:49.875Z] [DEBUG] [#tid_6] [Entry] write finished
[2018-12-17T08:50:49.876Z] [INFO] [#tid_6] [WhiskAction] write all done, caching CacheKey(anon-nKWrAIa7elnkH4XMmEEsb75ZB9v/action_tests_name2) Cached
[2018-12-17T08:50:49.890Z] [INFO] [#tid_4] [CouchDbRestStore] [marker:database_getDocumentAttachment_finish:92:59]
[2018-12-17T08:50:49.891Z] [DEBUG] [#tid_4] [ActionsApiTests] [GET] entity success
[2018-12-17T08:50:49.891Z] [INFO] [#tid_4] [WhiskAction] write initiated on existing cache entry, invalidating CacheKey(anon-nKWrAIa7elnkH4XMmEEsb75ZB9v/action_tests_name2), tid 4, state WriteInProgress
[2018-12-17T08:50:49.892Z] [DEBUG] [#tid_4] [WhiskAction] write backend part done, now marking cache entry as done
[2018-12-17T08:50:49.892Z] [INFO] [#tid_5] [CouchDbRestStore] [marker:database_getDocumentAttachment_finish:94:61]
[2018-12-17T08:50:49.892Z] [DEBUG] [#tid_4] [Entry] write finished
[2018-12-17T08:50:49.892Z] [INFO] [#tid_4] [WhiskAction] write all done, caching CacheKey(anon-nKWrAIa7elnkH4XMmEEsb75ZB9v/action_tests_name2) Cached
[2018-12-17T08:50:49.892Z] [DEBUG] [#tid_5] [ActionsApiTests] [GET] entity success
[2018-12-17T08:50:49.892Z] [INFO] [#tid_5] [WhiskAction] write initiated on existing cache entry, invalidating CacheKey(anon-nKWrAIa7elnkH4XMmEEsb75ZB9v/action_tests_name2), tid 5, state WriteInProgress
[2018-12-17T08:50:49.893Z] [DEBUG] [#tid_5] [WhiskAction] write backend part done, now marking cache entry as done
[2018-12-17T08:50:49.893Z] [DEBUG] [#tid_5] [Entry] write finished
[2018-12-17T08:50:49.893Z] [INFO] [#tid_5] [WhiskAction] write all done, caching CacheKey(anon-nKWrAIa7elnkH4XMmEEsb75ZB9v/action_tests_name2) Cached
[2018-12-17T08:50:49.914Z] [INFO] [#tid_3] [CouchDbRestStore] [marker:database_getDocumentAttachment_finish:116:82]
[2018-12-17T08:50:49.914Z] [INFO] [#tid_3] [WhiskAction] write initiated on existing cache entry, invalidating CacheKey(anon-nKWrAIa7elnkH4XMmEEsb75ZB9v/action_tests_name2), tid 3, state WriteInProgress
[2018-12-17T08:50:49.915Z] [DEBUG] [#tid_3] [ActionsApiTests] [GET] entity success
[2018-12-17T08:50:49.915Z] [DEBUG] [#tid_3] [WhiskAction] write backend part done, now marking cache entry as done
[2018-12-17T08:50:49.915Z] [DEBUG] [#tid_3] [Entry] write finished
[2018-12-17T08:50:49.915Z] [INFO] [#tid_3] [WhiskAction] write all done, caching CacheKey(anon-nKWrAIa7elnkH4XMmEEsb75ZB9v/action_tests_name2) Cached
[2018-12-17T08:50:49.921Z] [INFO] [#tid_7] [CouchDbRestStore] [marker:database_getDocumentAttachment_finish:123:90]
[2018-12-17T08:50:49.921Z] [INFO] [#tid_7] [WhiskAction] write initiated on existing cache entry, invalidating CacheKey(anon-nKWrAIa7elnkH4XMmEEsb75ZB9v/action_tests_name2), tid 7, state WriteInProgress
[2018-12-17T08:50:49.921Z] [DEBUG] [#tid_7] [ActionsApiTests] [GET] entity success
[2018-12-17T08:50:49.922Z] [DEBUG] [#tid_7] [WhiskAction] write backend part done, now marking cache entry as done
[2018-12-17T08:50:49.922Z] [DEBUG] [#tid_7] [Entry] write finished
[2018-12-17T08:50:49.922Z] [INFO] [#tid_7] [WhiskAction] write all done, caching CacheKey(anon-nKWrAIa7elnkH4XMmEEsb75ZB9v/action_tests_name2) Cached
5 was not equal to 1
ScalaTestFailureLocation: org.apache.openwhisk.core.controller.test.ActionsApiTests at (ActionsApiTests.scala:1079)

As a fix now the cache update operation also includes the inline logic. So a cache update would be considered complete only when the action code is also inlined. This ensures even with concurrent reader threads only one thread performs the db access and others make use of the cache

Related issue and scope

  • I opened an issue to propose and discuss this change (#????)

My changes affect the following components

  • API
  • Controller
  • Message Bus (e.g., Kafka)
  • Loadbalancer
  • Invoker
  • Intrinsic actions (e.g., sequences, conductors)
  • Data stores (e.g., CouchDB)
  • Tests
  • Deployment
  • CLI
  • General tooling
  • Documentation

Types of changes

  • Bug fix (generally a non-breaking change which closes an issue).
  • Enhancement or new feature (adds new functionality).
  • Breaking change (a bug fix or enhancement which changes existing behavior).

Checklist:

  • I signed an Apache CLA.
  • I reviewed the style guides and followed the recommendations (Travis CI will check :).
  • I added tests to cover my changes.
  • My changes require further changes to the documentation.
  • I updated the documentation where necessary.

Copy link
Contributor

@markusthoemmes markusthoemmes left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM in principle, left two nits.

@@ -198,23 +198,40 @@ trait DocumentFactory[W <: DocumentRevisionProvider] extends MultipleReadersSing
doc: DocId,
rev: DocRevision = DocRevision.empty,
fromCache: Boolean = cacheEnabled)(implicit transid: TransactionId, mw: Manifest[W]): Future[W] = {
getWithAttachment(db, doc, rev, fromCache, None)
Try {
require(db != null, "db undefined")
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we should get rid of all of these. Do we ever use null anywhere?

Try {
require(db != null, "db undefined")
} map {
implicit val logger = db.logging
implicit val ec = db.executionContext
val key = doc.asDocInfo(rev)
_ =>
cacheLookup(CacheKey(key), db.get[W](key, attachmentHandler), fromCache)
cacheLookup(CacheKey(key), db.get[W](key, Some(attachmentHandler)) flatMap { postProcess }, fromCache)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nit: I find the combinators a bit hard to read

db.get[W](key, Some(attachmentHandler)).flatMap(postProcess)

Is imo a bit clearer.

@codecov-io
Copy link

Codecov Report

Merging #4183 into master will decrease coverage by 4.84%.
The diff coverage is 100%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master    #4183      +/-   ##
==========================================
- Coverage   86.03%   81.19%   -4.85%     
==========================================
  Files         152      152              
  Lines        7292     7275      -17     
  Branches      472      477       +5     
==========================================
- Hits         6274     5907     -367     
- Misses       1018     1368     +350
Impacted Files Coverage Δ
...org/apache/openwhisk/core/entity/WhiskAction.scala 86.74% <100%> (+0.49%) ⬆️
...ache/openwhisk/core/database/DocumentFactory.scala 100% <100%> (+10.52%) ⬆️
...core/database/cosmosdb/RxObservableImplicits.scala 0% <0%> (-100%) ⬇️
...core/database/cosmosdb/CosmosDBArtifactStore.scala 0% <0%> (-95.54%) ⬇️
...sk/core/database/cosmosdb/CosmosDBViewMapper.scala 0% <0%> (-92.6%) ⬇️
...whisk/core/database/cosmosdb/CosmosDBSupport.scala 0% <0%> (-83.34%) ⬇️
...abase/cosmosdb/CosmosDBArtifactStoreProvider.scala 0% <0%> (-62.5%) ⬇️
...in/scala/org/apache/openwhisk/common/Counter.scala 40% <0%> (-20%) ⬇️
...rg/apache/openwhisk/common/ForcibleSemaphore.scala 88.46% <0%> (-7.7%) ⬇️
...penwhisk/core/database/cosmosdb/CosmosDBUtil.scala 92% <0%> (-4%) ⬇️
... and 1 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 780c98c...7a91803. Read the comment docs.

Copy link
Contributor

@tysonnorris tysonnorris left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM - thanks!

@tysonnorris tysonnorris merged commit 1bd21bc into apache:master Dec 17, 2018
BillZong pushed a commit to BillZong/openwhisk that referenced this pull request Nov 18, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

4 participants