[DRILL-5398] Memory Allocator randomly throws an IllegalStateException when reading nested json data

• Type: Bug
• Status: Open
• Priority: Major
• Resolution: Unresolved
• Affects Version/s: 1.10.0
• Component/s: Execution - Data Types, Storage - JSON
• Assignee: Unassigned
• Reporter: Rahul Kumar Challapalli
• Created: 29/Mar/17 23:37
• Updated: 23/May/17 20:47

Description

git.commit.id.abbrev=38ef562

The below query did not fail when I ran it in isolation. However when I ran the test suite at [1], which also contains the below query, by using 50 threads submitting queries concurrently, I hit the below error.

select kvgen(bigintegercol), kvgen(float8col) from `json_kvgenflatten/kvgen1.json`
Failed with exception
java.sql.SQLException: SYSTEM ERROR: IllegalStateException: Allocator[op:0:0:2:Project] closed with outstanding buffers allocated (6).
Allocator(op:0:0:2:Project) 1000000/110592/434176/10000000000 (res/actual/peak/limit)
  child allocators: 0
  ledgers: 6
    ledger[2747] allocator: op:0:0:2:Project), isOwning: true, size: 32768, references: 1, life: 13372865831733586..0, allocatorManager: [694, life: 13372864956215117..0] holds 1 buffers. 
        DrillBuf[3165], udle: [694 0..32768]
    ledger[2756] allocator: op:0:0:2:Project), isOwning: true, size: 4096, references: 1, life: 13372865832378236..0, allocatorManager: [702, life: 13372864958396200..0] holds 1 buffers. 
        DrillBuf[3176], udle: [703 0..4096]
    ledger[2775] allocator: op:0:0:2:Project), isOwning: true, size: 32768, references: 1, life: 13372865833922897..0, allocatorManager: [706, life: 13372864959861722..0] holds 1 buffers. 
        DrillBuf[3196], udle: [707 0..32768]
    ledger[2761] allocator: op:0:0:2:Project), isOwning: true, size: 32768, references: 1, life: 13372865833009204..0, allocatorManager: [700, life: 13372864957931156..0] holds 1 buffers. 
        DrillBuf[3181], udle: [701 0..32768]
    ledger[2769] allocator: op:0:0:2:Project), isOwning: true, size: 4096, references: 1, life: 13372865833502205..0, allocatorManager: [708, life: 13372864960352194..0] holds 1 buffers. 
        DrillBuf[3189], udle: [709 0..4096]
    ledger[2741] allocator: op:0:0:2:Project), isOwning: true, size: 4096, references: 1, life: 13372865831092092..0, allocatorManager: [696, life: 13372864956764681..0] holds 1 buffers. 
        DrillBuf[3160], udle: [697 0..4096]
  reservations: 0


Fragment 0:0

[Error Id: f8d274e2-8119-495c-8a38-017c834f9931 on qa-node183.qa.lab:31010]

  (java.lang.IllegalStateException) Allocator[op:0:0:2:Project] closed with outstanding buffers allocated (6).
Allocator(op:0:0:2:Project) 1000000/110592/434176/10000000000 (res/actual/peak/limit)
  child allocators: 0
  ledgers: 6
    ledger[2747] allocator: op:0:0:2:Project), isOwning: true, size: 32768, references: 1, life: 13372865831733586..0, allocatorManager: [694, life: 13372864956215117..0] holds 1 buffers. 
        DrillBuf[3165], udle: [694 0..32768]
    ledger[2756] allocator: op:0:0:2:Project), isOwning: true, size: 4096, references: 1, life: 13372865832378236..0, allocatorManager: [702, life: 13372864958396200..0] holds 1 buffers. 
        DrillBuf[3176], udle: [703 0..4096]
    ledger[2775] allocator: op:0:0:2:Project), isOwning: true, size: 32768, references: 1, life: 13372865833922897..0, allocatorManager: [706, life: 13372864959861722..0] holds 1 buffers. 
        DrillBuf[3196], udle: [707 0..32768]
    ledger[2761] allocator: op:0:0:2:Project), isOwning: true, size: 32768, references: 1, life: 13372865833009204..0, allocatorManager: [700, life: 13372864957931156..0] holds 1 buffers. 
        DrillBuf[3181], udle: [701 0..32768]
    ledger[2769] allocator: op:0:0:2:Project), isOwning: true, size: 4096, references: 1, life: 13372865833502205..0, allocatorManager: [708, life: 13372864960352194..0] holds 1 buffers. 
        DrillBuf[3189], udle: [709 0..4096]
    ledger[2741] allocator: op:0:0:2:Project), isOwning: true, size: 4096, references: 1, life: 13372865831092092..0, allocatorManager: [696, life: 13372864956764681..0] holds 1 buffers. 
        DrillBuf[3160], udle: [697 0..4096]
  reservations: 0

    org.apache.drill.exec.memory.BaseAllocator.close():486
    org.apache.drill.exec.ops.OperatorContextImpl.close():149
    org.apache.drill.exec.ops.FragmentContext.suppressingClose():422
    org.apache.drill.exec.ops.FragmentContext.close():411
    org.apache.drill.exec.work.fragment.FragmentExecutor.closeOutResources():318
    org.apache.drill.exec.work.fragment.FragmentExecutor.cleanup():155
    org.apache.drill.exec.work.fragment.FragmentExecutor.run():262
    org.apache.drill.common.SelfCleaningRunnable.run():38
    java.util.concurrent.ThreadPoolExecutor.runWorker():1142
    java.util.concurrent.ThreadPoolExecutor$Worker.run():617
    java.lang.Thread.run():745

	at org.apache.drill.jdbc.impl.DrillCursor.nextRowInternally(DrillCursor.java:489)
	at org.apache.drill.jdbc.impl.DrillCursor.next(DrillCursor.java:593)
	at oadd.org.apache.calcite.avatica.AvaticaResultSet.next(AvaticaResultSet.java:215)
	at org.apache.drill.jdbc.impl.DrillResultSetImpl.next(DrillResultSetImpl.java:140)
	at org.apache.drill.test.framework.DrillTestJdbc.executeQuery(DrillTestJdbc.java:218)
	at org.apache.drill.test.framework.DrillTestJdbc.run(DrillTestJdbc.java:101)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
Caused by: oadd.org.apache.drill.common.exceptions.UserRemoteException: SYSTEM ERROR: IllegalStateException: Allocator[op:0:0:2:Project] closed with outstanding buffers allocated (6).
Allocator(op:0:0:2:Project) 1000000/110592/434176/10000000000 (res/actual/peak/limit)
  child allocators: 0
  ledgers: 6
    ledger[2747] allocator: op:0:0:2:Project), isOwning: true, size: 32768, references: 1, life: 13372865831733586..0, allocatorManager: [694, life: 13372864956215117..0] holds 1 buffers. 
        DrillBuf[3165], udle: [694 0..32768]
    ledger[2756] allocator: op:0:0:2:Project), isOwning: true, size: 4096, references: 1, life: 13372865832378236..0, allocatorManager: [702, life: 13372864958396200..0] holds 1 buffers. 
        DrillBuf[3176], udle: [703 0..4096]
    ledger[2775] allocator: op:0:0:2:Project), isOwning: true, size: 32768, references: 1, life: 13372865833922897..0, allocatorManager: [706, life: 13372864959861722..0] holds 1 buffers. 
        DrillBuf[3196], udle: [707 0..32768]
    ledger[2761] allocator: op:0:0:2:Project), isOwning: true, size: 32768, references: 1, life: 13372865833009204..0, allocatorManager: [700, life: 13372864957931156..0] holds 1 buffers. 
        DrillBuf[3181], udle: [701 0..32768]
    ledger[2769] allocator: op:0:0:2:Project), isOwning: true, size: 4096, references: 1, life: 13372865833502205..0, allocatorManager: [708, life: 13372864960352194..0] holds 1 buffers. 
        DrillBuf[3189], udle: [709 0..4096]
    ledger[2741] allocator: op:0:0:2:Project), isOwning: true, size: 4096, references: 1, life: 13372865831092092..0, allocatorManager: [696, life: 13372864956764681..0] holds 1 buffers. 
        DrillBuf[3160], udle: [697 0..4096]
  reservations: 0


Fragment 0:0

[Error Id: f8d274e2-8119-495c-8a38-017c834f9931 on qa-node183.qa.lab:31010]

  (java.lang.IllegalStateException) Allocator[op:0:0:2:Project] closed with outstanding buffers allocated (6).
Allocator(op:0:0:2:Project) 1000000/110592/434176/10000000000 (res/actual/peak/limit)
  child allocators: 0
  ledgers: 6
    ledger[2747] allocator: op:0:0:2:Project), isOwning: true, size: 32768, references: 1, life: 13372865831733586..0, allocatorManager: [694, life: 13372864956215117..0] holds 1 buffers. 
        DrillBuf[3165], udle: [694 0..32768]
    ledger[2756] allocator: op:0:0:2:Project), isOwning: true, size: 4096, references: 1, life: 13372865832378236..0, allocatorManager: [702, life: 13372864958396200..0] holds 1 buffers. 
        DrillBuf[3176], udle: [703 0..4096]
    ledger[2775] allocator: op:0:0:2:Project), isOwning: true, size: 32768, references: 1, life: 13372865833922897..0, allocatorManager: [706, life: 13372864959861722..0] holds 1 buffers. 
        DrillBuf[3196], udle: [707 0..32768]
    ledger[2761] allocator: op:0:0:2:Project), isOwning: true, size: 32768, references: 1, life: 13372865833009204..0, allocatorManager: [700, life: 13372864957931156..0] holds 1 buffers. 
        DrillBuf[3181], udle: [701 0..32768]
    ledger[2769] allocator: op:0:0:2:Project), isOwning: true, size: 4096, references: 1, life: 13372865833502205..0, allocatorManager: [708, life: 13372864960352194..0] holds 1 buffers. 
        DrillBuf[3189], udle: [709 0..4096]
    ledger[2741] allocator: op:0:0:2:Project), isOwning: true, size: 4096, references: 1, life: 13372865831092092..0, allocatorManager: [696, life: 13372864956764681..0] holds 1 buffers. 
        DrillBuf[3160], udle: [697 0..4096]
  reservations: 0

    org.apache.drill.exec.memory.BaseAllocator.close():486
    org.apache.drill.exec.ops.OperatorContextImpl.close():149
    org.apache.drill.exec.ops.FragmentContext.suppressingClose():422
    org.apache.drill.exec.ops.FragmentContext.close():411
    org.apache.drill.exec.work.fragment.FragmentExecutor.closeOutResources():318
    org.apache.drill.exec.work.fragment.FragmentExecutor.cleanup():155
    org.apache.drill.exec.work.fragment.FragmentExecutor.run():262
    org.apache.drill.common.SelfCleaningRunnable.run():38
    java.util.concurrent.ThreadPoolExecutor.runWorker():1142
    java.util.concurrent.ThreadPoolExecutor$Worker.run():617
    java.lang.Thread.run():745

	at oadd.org.apache.drill.exec.rpc.user.QueryResultHandler.resultArrived(QueryResultHandler.java:123)
	at oadd.org.apache.drill.exec.rpc.user.UserClient.handle(UserClient.java:343)
	at oadd.org.apache.drill.exec.rpc.user.UserClient.handle(UserClient.java:88)
	at oadd.org.apache.drill.exec.rpc.RpcBus$InboundHandler.decode(RpcBus.java:274)
	at oadd.org.apache.drill.exec.rpc.RpcBus$InboundHandler.decode(RpcBus.java:244)
	at oadd.io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:89)
	at oadd.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:339)
	at oadd.io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:324)
	at oadd.io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:254)
	at oadd.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:339)
	at oadd.io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:324)
	at oadd.io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)
	at oadd.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:339)
	at oadd.io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:324)
	at oadd.io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:242)
	at oadd.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:339)
	at oadd.io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:324)
	at oadd.io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
	at oadd.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:339)
	at oadd.io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:324)
	at oadd.io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:847)
	at oadd.io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)
	at oadd.io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
	at oadd.io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
	at oadd.io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
	at oadd.io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
	at oadd.io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111)
	... 1 more

[1] https://github.com/mapr/drill-test-framework/tree/master/framework/resources/Functional/json/json_kvgenflatten

Issue Links

• relates to: DRILL-5399 Fix race condition in DrillComplexWriterFuncHolder