Page MenuHomePhabricator
Create Task
Maniphest T198046

MemoryManagerClosedException is produced even with no external queries
Open, Stalled, LowPublic
Actions

Description

Due to T198042: WDQS timeout on the public eqiad cluster, I have temporarily depooled wdq1004, but even after removing it from pool and restarting Blazegraph, I still get these exceptions:

Jun 25 03:44:15 wdqs1004 bash[20997]: 03:44:14.804 [com.bigdata.journal.Journal.executorService62] ERROR com.bigdata.util.concurrent.Haltable IP: UA: - com.bigdata.bop.join.PipelineJoin$JoinTask{ joinOp=com.bigdata.bop.join.PipelineJoin[2]()[ BOp.bopId=2, JoinAnnotations.constraints=null, AST2BOpBase.simpleJoin=true, BOp.evaluationContext=ANY, AccessPathJoinAnnotations.predicate=com.bigdata.rdf.spo.SPOPredicate[1](x=null, y=null, z=null)[ IPredicate.relationName=[wdq.spo], IPredicate.timestamp=1529898254773, BOp.bopId=1, AST2BOpBase.estimatedCardinality=5514016070, AST2BOpBase.originalIndex=SPO, IPredicate.flags=[KEYS,VALS,READONLY,PARALLEL]]]} : isFirstCause=true : com.bigdata.rwstore.sector.MemoryManagerClosedException
Jun 25 03:44:15 wdqs1004 bash[20997]: com.bigdata.rwstore.sector.MemoryManagerClosedException: null
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.rwstore.sector.MemoryManager.assertOpen(MemoryManager.java:110)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.rwstore.sector.MemoryManager.allocate(MemoryManager.java:671)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.rwstore.sector.AllocationContext.allocate(AllocationContext.java:195)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.rwstore.sector.AllocationContext.allocate(AllocationContext.java:169)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.rwstore.sector.AllocationContext.allocate(AllocationContext.java:159)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.rwstore.sector.AllocationContext.alloc(AllocationContext.java:359)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.rwstore.PSOutputStream.save(PSOutputStream.java:335)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.rwstore.PSOutputStream.getAddr(PSOutputStream.java:416)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.bop.solutions.SolutionSetStream.put(SolutionSetStream.java:297)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.bop.engine.LocalNativeChunkMessage.<init>(LocalNativeChunkMessage.java:213)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.bop.engine.LocalNativeChunkMessage.<init>(LocalNativeChunkMessage.java:147)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.bop.engine.StandaloneChunkHandler.handleChunk(StandaloneChunkHandler.java:92)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.bop.engine.ChunkedRunningQuery$HandleChunkBuffer.outputChunk(ChunkedRunningQuery.java:1699)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.bop.engine.ChunkedRunningQuery$HandleChunkBuffer.addReorderAllowed(ChunkedRunningQuery.java:1628)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.bop.engine.ChunkedRunningQuery$HandleChunkBuffer.add(ChunkedRunningQuery.java:1569)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.bop.engine.ChunkedRunningQuery$HandleChunkBuffer.add(ChunkedRunningQuery.java:1453)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.relation.accesspath.UnsyncLocalOutputBuffer.handleChunk(UnsyncLocalOutputBuffer.java:59)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.relation.accesspath.UnsyncLocalOutputBuffer.handleChunk(UnsyncLocalOutputBuffer.java:14)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.relation.accesspath.AbstractUnsynchronizedArrayBuffer.overflow(AbstractUnsynchronizedArrayBuffer.java:287)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.relation.accesspath.AbstractUnsynchronizedArrayBuffer.add2(AbstractUnsynchronizedArrayBuffer.java:215)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.relation.accesspath.AbstractUnsynchronizedArrayBuffer.add(AbstractUnsynchronizedArrayBuffer.java:173)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.bop.join.PipelineJoin$JoinTask$AccessPathTask.handleJoin2(PipelineJoin.java:1868)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.bop.join.PipelineJoin$JoinTask$AccessPathTask.call(PipelineJoin.java:1684)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.bop.join.PipelineJoin$JoinTask$BindingSetConsumerTask.runOneTask(PipelineJoin.java:1087)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.bop.join.PipelineJoin$JoinTask$BindingSetConsumerTask.call(PipelineJoin.java:995)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.bop.join.PipelineJoin$JoinTask.consumeSource(PipelineJoin.java:729)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.bop.join.PipelineJoin$JoinTask.call(PipelineJoin.java:623)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.bop.join.PipelineJoin$JoinTask.call(PipelineJoin.java:382)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at java.util.concurrent.FutureTask.run(FutureTask.java:266)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.concurrent.FutureTaskMon.run(FutureTaskMon.java:63)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.bop.engine.ChunkedRunningQuery$ChunkTask.call(ChunkedRunningQuery.java:1346)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.bop.engine.ChunkedRunningQuery$ChunkTaskWrapper.run(ChunkedRunningQuery.java:926)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at java.util.concurrent.FutureTask.run(FutureTask.java:266)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.concurrent.FutureTaskMon.run(FutureTaskMon.java:63)
Jun 25 03:44:15 wdqs1004 bash[20997]:         at com.bigdata.bop.engine.ChunkedRunningQuery$ChunkFutureTask.run(ChunkedRunningQuery.java:821)
Jun 25 03:44:16 wdqs1004 bash[20997]:         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
Jun 25 03:44:16 wdqs1004 bash[20997]:         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
Jun 25 03:44:16 wdqs1004 bash[20997]:         at java.lang.Thread.run(Thread.java:748)

There should not be any queries running that time out, only Updater queries that do not timeout, but the exception still happens.

Log attached:

log1943 KBDownload

Details

SubjectRepoBranchLines +/-
wdqs: don't log MemoryManagerClosedExceptionoperations/puppetproduction+1 -0
Customize query in gerrit

Related Objects

Event Timeline

Smalyshev created this task.Jun 25 2018, 4:13 AM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptJun 25 2018, 4:13 AM
Smalyshev triaged this task as High priority.Jun 25 2018, 4:13 AM
Smalyshev added a subscriber: Gehel.

Maybe caused by the system "ping" from icinga? But that shouldn't be timing out either, so it's weird it is appearing. If it's normal, it should be suppressed and not pollute the logs at the minimum.

gerritbot subscribed.Jun 25 2018, 8:08 AM

Change 441774 had a related patch set uploaded (by Gehel; owner: Gehel):
[operations/puppet@production] wdqs: don't log MemoryManagerClosedException

https://gerrit.wikimedia.org/r/441774

gerritbot added a project: Patch-For-Review.Jun 25 2018, 8:08 AM
Gehel added a comment.Jun 25 2018, 8:10 AM

The above change would suppress the MemoryManagerClosedExceptions and all log messages from com.bigdata.util.concurrent.Haltable. I'm not entirely convinced this is the right thing to do, since it is hiding an error that we don't entirely understand. But if there is nothing we can do about it, it does not make sense to log it.

Smalyshev added projects: Wikidata-Query-Service, Discovery-Wikidata-Query-Service-Sprint.Jun 25 2018, 5:18 PM
Restricted Application added projects: Wikidata, Discovery-ARCHIVED. · View Herald TranscriptJun 25 2018, 5:18 PM
gerritbot added a comment.Jun 25 2018, 5:22 PM

Change 441774 merged by Gehel:
[operations/puppet@production] wdqs: don't log MemoryManagerClosedException

https://gerrit.wikimedia.org/r/441774

Smalyshev lowered the priority of this task from High to Medium.Jun 25 2018, 5:35 PM
Smalyshev added a comment.Jun 26 2018, 12:23 AM

Still seeing those exceptions, e.g. see on wdqs1009 (that serves no traffic, therefore should not have any timeouts?)

Lydia_Pintscher moved this task from incoming to monitoring on the Wikidata board.Jun 26 2018, 7:36 AM
Smalyshev moved this task from Backlog to Done on the Discovery-Wikidata-Query-Service-Sprint board.Jun 27 2018, 8:11 PM
Smalyshev moved this task from Incoming to Current work on the Wikidata-Query-Service board.Jun 28 2018, 5:30 AM
Smalyshev added a comment.Jun 29 2018, 8:35 PM

We've disabled it on the logger level, but I'd probably still do two things there:

  1. maybe change the cutoff from com.bigdata.util.concurrent.Haltable to only the one caused by com.bigdata.rwstore.sector.MemoryManagerClosedException - using evaluators in logback config.
  1. Figure out if it's a legit exception and shouldn't it be caught and handled somewhere more quietly? I feel it may be some overzealous handling of LIMIT (i.e. some background threads trying to supply data that aren't needed already because of LIMIT) but can be wrong.
Smalyshev removed projects: Discovery-Wikidata-Query-Service-Sprint, Patch-For-Review.Jun 29 2018, 8:35 PM
Smalyshev moved this task from Current work to Incoming on the Wikidata-Query-Service board.
• Vvjjkkii renamed this task from MemoryManagerClosedException is produced even with no external queries to 1daaaaaaaa.Jul 1 2018, 1:02 AM
• Vvjjkkii raised the priority of this task from Medium to High.
• Vvjjkkii added projects: CheckUser, Connected-Open-Heritage-Batch-uploads (RAÄ-KMB_1_2017-02), Tamil-Sites, Gamepress, Hashtags, Jade, KartoEditor, Language-2018-Apr-June, New-Editor-Experiences, Mail, TCB-Team (now WMDE-TechWish).
• Vvjjkkii updated the task description. (Show Details)
• Vvjjkkii removed subscribers: gerritbot, Aklapper.
CommunityTechBot renamed this task from 1daaaaaaaa to MemoryManagerClosedException is produced even with no external queries.Jul 2 2018, 10:22 AM
CommunityTechBot lowered the priority of this task from High to Medium.
CommunityTechBot updated the task description. (Show Details)
CommunityTechBot removed projects: TCB-Team (now WMDE-TechWish), Mail, New-Editor-Experiences, Language-2018-Apr-June, KartoEditor, Jade, Hashtags, Gamepress, Tamil-Sites, Connected-Open-Heritage-Batch-uploads (RAÄ-KMB_1_2017-02), CheckUser.
CommunityTechBot added subscribers: gerritbot, Aklapper.
Smalyshev moved this task from Incoming to Current work on the Wikidata-Query-Service board.Jul 12 2018, 6:20 PM
Smalyshev moved this task from Current work to Incoming on the Wikidata-Query-Service board.Jul 30 2018, 9:30 PM
Smalyshev changed the task status from Open to Stalled.Jun 18 2019, 10:30 PM
Smalyshev lowered the priority of this task from Medium to Low.
Gehel moved this task from Incoming to Blazegraph on the Wikidata-Query-Service board.May 6 2020, 12:49 PM
Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL