search

scala / bug

Scala 2 bug reports only. Please, no questions — proper bug reports only.
https://scala-lang.org
230 stars 21 forks source link

AdaptiveWorkStealingForkJoinTasks$WrappedTask deadlock #9243

Closed scabug closed 1 year ago

scabug commented 9 years ago

I have been experiencing a deadlock on production where 2 threads (ForkJoinPool-2-worker-1 and null-SimpleThreadPoolWorker-1) of my application where in WAITING status.

The application log show them stop reporting until I restart the application at 21:55.

ForkJoinPool-2-worker-1 stopped logging at 19:32:00 :

2015-03-19 19:32:00,479 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.index.IndexBuilder - Content batch Single content id {455589366} starting...
2015-03-19 19:32:00,479 [ForkJoinPool-2-worker-1] INFO  c.g.a.i.d.LiveContentToTagDataProvider - Executing content to tag map for Single content id {455589366}...
2015-03-19 19:32:00,479 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - content-to-tag-query-template+content-single-subquery(455589366) completed in 0 ms
2015-03-19 19:32:00,481 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - tag-by-id-query(4) completed in 1 ms
2015-03-19 19:32:00,481 [ForkJoinPool-2-worker-1] INFO  c.g.a.i.d.LiveContentToTagDataProvider - Executed content to tag map query Single content id {455589366}
2015-03-19 19:32:00,481 [ForkJoinPool-2-worker-1] INFO  c.g.a.i.d.LiveContentToLeadTagMapProvider - Executing content to lead tag map for Single content id {455589366}...
2015-03-19 19:32:00,481 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - lead-content-query-template+content-single-subquery(455589366) completed in 0 ms
2015-03-19 19:32:00,481 [ForkJoinPool-2-worker-1] INFO  c.g.a.i.d.LiveContentToLeadTagMapProvider - Executed content to lead tag map query Single content id {455589366}
2015-03-19 19:32:00,482 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - content-to-factbox-query-template+content-single-subquery(455589366) completed in 1 ms
2015-03-19 19:32:00,483 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - content-to-reference-query-template+content-single-subquery(455589366) completed in 1 ms
2015-03-19 19:32:00,484 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - tables/live-standalone-header-row+content-single-subquery(455589366) completed in 0 ms
2015-03-19 19:32:00,485 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - tables/live-standalone-data-rows+content-single-subquery(455589366) completed in 1 ms
2015-03-19 19:32:00,486 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - tables/live-in-body-header-row+content-single-subquery(455589366) completed in 1 ms
2015-03-19 19:32:00,487 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - tables/live-in-body-data-rows+content-single-subquery(455589366) completed in 1 ms
2015-03-19 19:32:00,488 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - content-cartoon-media-query-template+content-single-subquery(455589366) completed in 1 ms
2015-03-19 19:32:00,488 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - content-audio-media-query-template+content-single-subquery(455589366) completed in 0 ms
2015-03-19 19:32:00,489 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - content-video-media-query-template+content-single-subquery(455589366) completed in 0 ms
2015-03-19 19:32:00,490 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - content-video-encodings-query-template+content-single-subquery(455589366) completed in 1 ms
2015-03-19 19:32:00,491 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - content-picture-media-query-template+content-single-subquery(455589366) completed in 1 ms
2015-03-19 19:32:00,492 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - content-interactive-media-query-template+content-single-subquery(455589366) completed in 1 ms
2015-03-19 19:32:00,492 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - media-asset-v2/live-content-element-main-query-template+content-single-subquery(455589366) completed in 0 ms
2015-03-19 19:32:00,493 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - media-asset-v2/live-content-main-image-media-query-template+content-single-subquery(455589366) completed in 1 ms
2015-03-19 19:32:00,493 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - media-asset-v2/live-content-main-video-media-query-template+content-single-subquery(455589366) completed in 0 ms
2015-03-19 19:32:00,494 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - media-asset-v2/live-gallery-main-assets-query-template+content-single-subquery(455589366) completed in 0 ms
2015-03-19 19:32:00,495 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - media-asset-v2/live-gallery-thumbnail-assets-query-template+content-single-subquery(455589366) completed in 1 ms
2015-03-19 19:32:00,496 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - media-asset-v2/live-content-element-thumbnail-query-template+content-single-subquery(455589366) completed in 1 ms
2015-03-19 19:32:00,496 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - media-asset-v2/live-content-assets-thumbnail-query-template+content-single-subquery(455589366) completed in 0 ms
2015-03-19 19:32:00,497 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - media-asset-v2/live-content-images-no-alternate-sizes-query-template+content-single-subquery(455589366) completed in 0 ms
2015-03-19 19:32:00,498 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - media-asset-v2/live-content-in-body-video-id-query-template+content-single-subquery(455589366) completed in 1 ms
2015-03-19 19:32:00,498 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - media-asset-v2/live-content-audio-query-template+content-single-subquery(455589366) completed in 0 ms
2015-03-19 19:32:00,499 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - media-asset-v2/poll-images-query-template+content-single-subquery(455589366) completed in 1 ms
2015-03-19 19:32:00,500 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - embed/live-in-body-youtube-embed+content-single-subquery(455589366) completed in 1 ms
2015-03-19 19:32:00,501 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - embed/live-in-body-twitter-embed+content-single-subquery(455589366) completed in 1 ms
2015-03-19 19:32:00,502 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - embed/live-in-body-spotify-embed+content-single-subquery(455589366) completed in 1 ms
2015-03-19 19:32:00,503 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - content-query-template+content-single-subquery(455589366) completed in 1 ms
2015-03-19 19:32:00,503 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.index.IndexBuilder - Content batch Single content id {455589366} completed in 24 ms
2015-03-19 21:56:50,091 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.index.IndexBuilder - Building task list...
2015-03-19 21:56:50,092 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.index.IndexBuilder - Selected indexers: [Content; Draft Content; Crosswords; Flexible Content; Flexible Content print sent content; Story Packages; ShortUrlAnalytics; Sections; Network Front; Tags; Removed From Site Content]
2015-03-19 21:56:50,092 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.Start$ - Loading reference data...
2015-03-19 21:56:50,092 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.Start$ - Loading sections...
2015-03-19 21:56:50,094 [ForkJoinPool-2-worker-1] INFO  com.gu.apiindexer.scaladb.Database - get-sections() completed in 2 ms

null-SimpleThreadPoolWorker-1 stopped logging at 19:30:10 :

2015-03-19 19:30:10,410 [null-SimpleThreadPoolWorker-1] INFO  com.gu.apiindexer.scaladb.Database - preview-content-id-for-path(global/2015/mar/19/cam, global/2015/mar/19/cam) completed in 2 ms
2015-03-19 19:30:10,411 [null-SimpleThreadPoolWorker-1] INFO  com.gu.apiindexer.scaladb.Database - preview-content-id-for-path(music/2015/mar/19/zomba-prison-project-i-have-no-everything-here-review-malawi-prison-music-ian-brenna, music/2015/mar/19/zomba-prison-project-i-have-no-everything-here-review-malawi-prison-music-ian-brenna) completed in 1 ms
2015-03-19 19:30:10,415 [null-SimpleThreadPoolWorker-1] INFO  com.gu.apiindexer.scaladb.Database - preview-content-id-for-path(global/550b22a6e4b0c360811ba748, global/550b22a6e4b0c360811ba748) completed in 4 ms
2015-03-19 19:30:10,416 [null-SimpleThreadPoolWorker-1] INFO  com.gu.apiindexer.scaladb.Database - preview-content-id-for-path(books/2015/mar/20/happy-city-transforming-our-lives-through-urban-design-charles-montgomery-review, books/2015/mar/20/happy-city-transforming-our-lives-through-urban-design-charles-montgomery-review) completed in 1 ms
2015-03-19 19:30:10,417 [null-SimpleThreadPoolWorker-1] INFO  com.gu.apiindexer.scaladb.Database - preview-content-id-for-path(world/2015/mar/19/isis-claims-responsibility-for-tunisia-murders, world/2015/mar/19/isis-claims-responsibility-for-tunisia-murders) completed in 1 ms
2015-03-19 19:30:10,417 [null-SimpleThreadPoolWorker-1] INFO  c.g.a.i.i.PrintSentFlexibleContentIndexer - Content ids which require updating (notified by Composer): (456033625,456050463,456043903,456050671,456034362,456043110,456034521,456051352,456040005,456050670)
2015-03-19 19:30:10,421 [null-SimpleThreadPoolWorker-1] INFO  com.gu.apiindexer.scaladb.Database - removed-content-ids-in-date-range-subquery()[Thu Mar 19 19:29:55 GMT 2015 -> Thu Mar 19 19:30:08 GMT 2015] completed in 4 ms
2015-03-19 19:30:10,422 [null-SimpleThreadPoolWorker-1] INFO  c.g.a.i.i.RemovedFromSiteContentIndexer - Updated ids: List()
2015-03-19 19:30:10,422 [null-SimpleThreadPoolWorker-1] INFO  com.gu.apiindexer.index.IndexBuilder - dateBased index starting...
2015-03-19 19:30:10,422 [null-SimpleThreadPoolWorker-1] INFO  com.gu.apiindexer.index.IndexBuilder - Indexing...
2015-03-19 21:55:22,692 [null-SimpleThreadPoolWorker-1] INFO  c.g.a.w.s.IndexJobs$FlexibleContentJob - Triggering flexible content index
2015-03-19 21:55:22,766 [null-SimpleThreadPoolWorker-1] INFO  com.gu.apiindexer.index.IndexBuilder - Building task list...
2015-03-19 21:55:22,771 [null-SimpleThreadPoolWorker-1] INFO  com.gu.apiindexer.index.IndexBuilder - Selected indexers: [Flexible Content]
2015-03-19 21:55:22,771 [null-SimpleThreadPoolWorker-1] INFO  com.gu.apiindexer.Start$ - Loading reference data...
2015-03-19 21:55:23,719 [null-SimpleThreadPoolWorker-1] INFO  com.gu.apiindexer.Start$ - Loading sections...
2015-03-19 21:55:23,959 [null-SimpleThreadPoolWorker-1] INFO  com.gu.apiindexer.scaladb.Database - get-sections() completed in 215 ms

Before restarting the application I have taken a thread dump. :

"ForkJoinPool-2-worker-1" daemon prio=10 tid=0x00007f3e38070800 nid=0x6359 in Object.wait() [0x00007f3e2c651000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000d474ffc0> (a scala.collection.parallel.AdaptiveWorkStealingForkJoinTasks$WrappedTask)
        at java.lang.Object.wait(Object.java:503)
        at scala.concurrent.forkjoin.ForkJoinPool.awaitJoin(ForkJoinPool.java:2386)
        - locked <0x00000000d474ffc0> (a scala.collection.parallel.AdaptiveWorkStealingForkJoinTasks$WrappedTask)
        at scala.concurrent.forkjoin.ForkJoinTask.doJoin(ForkJoinTask.java:341)
        at scala.concurrent.forkjoin.ForkJoinTask.join(ForkJoinTask.java:673)
        at scala.collection.parallel.ForkJoinTasks$WrappedTask$class.sync(Tasks.scala:378)
        at scala.collection.parallel.AdaptiveWorkStealingForkJoinTasks$WrappedTask.sync(Tasks.scala:443)
        at scala.collection.parallel.AdaptiveWorkStealingTasks$WrappedTask$class.internal(Tasks.scala:173)
        at scala.collection.parallel.AdaptiveWorkStealingForkJoinTasks$WrappedTask.internal(Tasks.scala:443)
        at scala.collection.parallel.AdaptiveWorkStealingTasks$WrappedTask$class.compute(Tasks.scala:149)
        at scala.collection.parallel.AdaptiveWorkStealingForkJoinTasks$WrappedTask.compute(Tasks.scala:443)
        at scala.concurrent.forkjoin.RecursiveAction.exec(RecursiveAction.java:160)
        at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
        at scala.concurrent.forkjoin.ForkJoinTask.doJoin(ForkJoinTask.java:341)
        at scala.concurrent.forkjoin.ForkJoinTask.join(ForkJoinTask.java:673)
        at scala.collection.parallel.ForkJoinTasks$WrappedTask$class.sync(Tasks.scala:378)
        at scala.collection.parallel.AdaptiveWorkStealingForkJoinTasks$WrappedTask.sync(Tasks.scala:443)
        at scala.collection.parallel.ForkJoinTasks$class.executeAndWaitResult(Tasks.scala:426)
        at scala.collection.parallel.ForkJoinTaskSupport.executeAndWaitResult(TaskSupport.scala:56)
        at scala.collection.parallel.ParIterableLike$class.foreach(ParIterableLike.scala:463)
        at scala.collection.parallel.immutable.ParVector.foreach(ParVector.scala:38)
        at com.gu.apiindexer.index.IndexBuilder$BaseIndexer$$anonfun$com$gu$apiindexer$index$IndexBuilder$BaseIndexer$$runTasks$1.apply$mcV$sp(IndexBuilder.scala:65)
        at com.gu.apiindexer.index.IndexBuilder$BaseIndexer$$anonfun$com$gu$apiindexer$index$IndexBuilder$BaseIndexer$$runTasks$1.apply(IndexBuilder.scala:58)
        at com.gu.apiindexer.index.IndexBuilder$BaseIndexer$$anonfun$com$gu$apiindexer$index$IndexBuilder$BaseIndexer$$runTasks$1.apply(IndexBuilder.scala:58)
        at com.gu.apiindexer.timing.LoggingStopWatch$class.logTime(LoggingStopWatch.scala:14)
        at com.gu.apiindexer.index.IndexBuilder.logTime(IndexBuilder.scala:19)
        at com.gu.apiindexer.timing.LoggingStopWatch$class.verboseTime(LoggingStopWatch.scala:28)
        at com.gu.apiindexer.index.IndexBuilder.verboseTime(IndexBuilder.scala:19)
        at com.gu.apiindexer.index.IndexBuilder$BaseIndexer.com$gu$apiindexer$index$IndexBuilder$BaseIndexer$$runTasks(IndexBuilder.scala:58)
        at com.gu.apiindexer.index.IndexBuilder$BaseIndexer$$anonfun$start$1.apply$mcV$sp(IndexBuilder.scala:49)
        at com.gu.apiindexer.index.IndexBuilder$BaseIndexer.mutex(IndexBuilder.scala:93)
        at com.gu.apiindexer.index.IndexBuilder$BaseIndexer.start(IndexBuilder.scala:38)
        at com.gu.apiindexer.webapp.IndexBuilderServlet$$anonfun$doPost$1.apply$mcV$sp(IndexBuilderServlet.scala:199)
        at com.gu.apiindexer.webapp.IndexBuilderServlet$$anonfun$doPost$1.apply(IndexBuilderServlet.scala:199)
        at com.gu.apiindexer.webapp.IndexBuilderServlet$$anonfun$doPost$1.apply(IndexBuilderServlet.scala:199)
        at scala.concurrent.impl.Future$PromiseCompletingRunnable.liftedTree1$1(Future.scala:24)
        at scala.concurrent.impl.Future$PromiseCompletingRunnable.run(Future.scala:24)
        at scala.concurrent.impl.ExecutionContextImpl$AdaptedForkJoinTask.exec(ExecutionContextImpl.scala:121)
        at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
        at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
        at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
        at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)

   Locked ownable synchronizers:
        - <0x00000000d758e138> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)

"null-SimpleThreadPoolWorker-1" prio=10 tid=0x00007f3e58279000 nid=0x62f3 in Object.wait() [0x00007f3e4c857000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000cfeccd30> (a scala.collection.parallel.AdaptiveWorkStealingForkJoinTasks$WrappedTask)
        at java.lang.Object.wait(Object.java:503)
        at scala.concurrent.forkjoin.ForkJoinTask.externalAwaitDone(ForkJoinTask.java:295)
        - locked <0x00000000cfeccd30> (a scala.collection.parallel.AdaptiveWorkStealingForkJoinTasks$WrappedTask)
        at scala.concurrent.forkjoin.ForkJoinTask.doJoin(ForkJoinTask.java:341)
        at scala.concurrent.forkjoin.ForkJoinTask.join(ForkJoinTask.java:673)
        at scala.collection.parallel.ForkJoinTasks$WrappedTask$class.sync(Tasks.scala:378)
        at scala.collection.parallel.AdaptiveWorkStealingForkJoinTasks$WrappedTask.sync(Tasks.scala:443)
        at scala.collection.parallel.ForkJoinTasks$class.executeAndWaitResult(Tasks.scala:426)
        at scala.collection.parallel.ForkJoinTaskSupport.executeAndWaitResult(TaskSupport.scala:56)
        at scala.collection.parallel.ParIterableLike$class.foreach(ParIterableLike.scala:463)
        at scala.collection.parallel.immutable.ParVector.foreach(ParVector.scala:38)
        at com.gu.apiindexer.index.IndexBuilder$BaseIndexer$$anonfun$com$gu$apiindexer$index$IndexBuilder$BaseIndexer$$runTasks$1.apply$mcV$sp(IndexBuilder.scala:65)
        at com.gu.apiindexer.index.IndexBuilder$BaseIndexer$$anonfun$com$gu$apiindexer$index$IndexBuilder$BaseIndexer$$runTasks$1.apply(IndexBuilder.scala:58)
        at com.gu.apiindexer.index.IndexBuilder$BaseIndexer$$anonfun$com$gu$apiindexer$index$IndexBuilder$BaseIndexer$$runTasks$1.apply(IndexBuilder.scala:58)
        at com.gu.apiindexer.timing.LoggingStopWatch$class.logTime(LoggingStopWatch.scala:14)
        at com.gu.apiindexer.index.IndexBuilder.logTime(IndexBuilder.scala:19)
        at com.gu.apiindexer.timing.LoggingStopWatch$class.verboseTime(LoggingStopWatch.scala:28)
        at com.gu.apiindexer.index.IndexBuilder.verboseTime(IndexBuilder.scala:19)
        at com.gu.apiindexer.index.IndexBuilder$BaseIndexer.com$gu$apiindexer$index$IndexBuilder$BaseIndexer$$runTasks(IndexBuilder.scala:58)
        at com.gu.apiindexer.index.IndexBuilder$BaseIndexer$$anonfun$start$1.apply$mcV$sp(IndexBuilder.scala:49)
        at com.gu.apiindexer.index.IndexBuilder$BaseIndexer.mutex(IndexBuilder.scala:93)
        at com.gu.apiindexer.index.IndexBuilder$BaseIndexer.start(IndexBuilder.scala:38)
        at com.gu.apiindexer.webapp.scheduling.IndexJobs$FlexibleContentJob$$anonfun$execute$2.apply$mcV$sp(IndexJob.scala:63)
        at com.gu.apiindexer.webapp.scheduling.IndexJobs$FlexibleContentJob$$anonfun$execute$2.apply(IndexJob.scala:57)
        at com.gu.apiindexer.webapp.scheduling.IndexJobs$FlexibleContentJob$$anonfun$execute$2.apply(IndexJob.scala:57)
        at scala.util.control.Exception$Catch.apply(Exception.scala:103)
        at com.gu.apiindexer.webapp.scheduling.IndexJobs$FlexibleContentJob.execute(IndexJob.scala:56)
        at org.quartz.core.JobRunShell.run(JobRunShell.java:216)
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:549)

   Locked ownable synchronizers:
        - <0x00000000d6618468> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)

I have not been able to reproduce the problem, and this the first time we have experienced this issue on the codebase.

scabug commented 9 years ago

Imported From: https://issues.scala-lang.org/browse/SI-9243?orig=1 Reporter: Mariot Chauvin (mchv) Affected Versions: 2.11.5

SethTisue commented 1 year ago

closing as we don't have a reproduction, the issue hasn't garnered significant attention from other users, and while a Scala bug could be the root cause, it also seems possible the root cause is user error. 🤷