[
https://issues.apache.org/jira/browse/DRILL-3771?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15221289#comment-15221289
]
Deneche A. Hakim commented on DRILL-3771:
-----------------------------------------
So I was able to reproduce the leak consistently (although not every single
time) by submitting a single long running query that fetches 1M rows that I
cancel after I receive 10K rows:
{code}
private static void executeQuery(final Connection conn, final String query,
int rowsBeforeCancel) throws SQLException {
long numRows = 0;
Statement stmt = conn.createStatement();
ResultSet rs = stmt.executeQuery(query);
while (rs.next()) {
numRows++;
if (numRows == rowsBeforeCancel) {
stmt.cancel();
break;
}
}
rs.close();
stmt.close();
conn.close();
}
{code}
When you run the client code multiple, sometimes you see the following warning:
{noformat}
08:03:41.161 [main] WARN o.apache.drill.jdbc.DrillConnection - Exception while
closing client.
java.lang.RuntimeException: Exception while closing
at
oadd.org.apache.drill.common.DrillAutoCloseables.closeNoChecked(DrillAutoCloseables.java:46)
~[drill-jdbc-all-1.7.0-SNAPSHOT.jar:na]
at
oadd.org.apache.drill.exec.client.DrillClient.close(DrillClient.java:284)
~[drill-jdbc-all-1.7.0-SNAPSHOT.jar:na]
at
org.apache.drill.jdbc.impl.DrillConnectionImpl.closeOrWarn(DrillConnectionImpl.java:781)
[drill-jdbc-all-1.7.0-SNAPSHOT.jar:na]
at
org.apache.drill.jdbc.impl.DrillConnectionImpl.cleanup(DrillConnectionImpl.java:794)
[drill-jdbc-all-1.7.0-SNAPSHOT.jar:na]
at
org.apache.drill.jdbc.impl.DrillHandler.onConnectionClose(DrillHandler.java:36)
[drill-jdbc-all-1.7.0-SNAPSHOT.jar:na]
at
oadd.net.hydromatic.avatica.AvaticaConnection.close(AvaticaConnection.java:135)
[drill-jdbc-all-1.7.0-SNAPSHOT.jar:na]
at com.adeneche.ConcurrencyTest.executeQuery(ConcurrencyTest.java:45)
[classes/:na]
at com.adeneche.ConcurrencyTest.main(ConcurrencyTest.java:71)
[classes/:na]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
~[na:1.7.0_71]
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
~[na:1.7.0_71]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
~[na:1.7.0_71]
at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_71]
at com.intellij.rt.execution.application.AppMain.main(AppMain.java:140)
[idea_rt.jar:na]
Caused by: java.lang.IllegalStateException: Allocator[ROOT] closed with
outstanding buffers allocated (1).
Allocator(ROOT) 0/4194304/10027008/3817865216 (res/actual/peak/limit)
child allocators: 0
ledgers: 1
ledger[95] allocator: ROOT), isOwning: true, size: 4194304, references: 1,
life: 1459494221111783000..0, allocatorManager: [95, life:
1459494221111733000..0] holds 1 buffers.
DrillBuf[117], udle: [96 0..4194304]
reservations: 0
at
oadd.org.apache.drill.exec.memory.BaseAllocator.close(BaseAllocator.java:475)
~[drill-jdbc-all-1.7.0-SNAPSHOT.jar:na]
at
oadd.org.apache.drill.common.DrillAutoCloseables.closeNoChecked(DrillAutoCloseables.java:44)
~[drill-jdbc-all-1.7.0-SNAPSHOT.jar:na]
... 12 common frames omitted
{noformat}
I spent some time investigating this leak and here is what I found:
- the leak is happening on the client side, it's not failing the query but
merely logged as a warning
- I tracked the leaked buffer and it turns out to be the cumulation buffer used
by UserProtobufLengthDecoder.
- This buffer is still released properly by netty (I confirmed this) but it
turns out we are closing the client allocator faster than Netty is deactivating
the channel (this particular buffer is accessed one more time then released
when UserProtobufLengthDecoder.channelInactive is called, at this time the
client allocator has already been closed)
> MEMORY LEAK : Concurrent query execution
> ----------------------------------------
>
> Key: DRILL-3771
> URL: https://issues.apache.org/jira/browse/DRILL-3771
> Project: Apache Drill
> Issue Type: Bug
> Components: Execution - Flow
> Affects Versions: 1.2.0
> Environment: 4 node cluster CentOS
> Reporter: Khurram Faraaz
> Assignee: Deneche A. Hakim
> Priority: Critical
> Fix For: 1.7.0
>
>
> I am seeing a memory leak when I execute concurrent queries (16 threads).
> Total number of records in the JSON file are close to ~26M. Number of records
> that match the predicate key2 = 'm' are 1,874,177.
> I do not see the memory leak reported in the drillbit.log though.
> Query STATE is listed as CANCELLATION_REQUESTED for each of the query on the
> Web UI's query profiles page.
> master commit ID: b525692e
> Query : select key1 , key2 from `twoKeyJsn.json` where key2 = 'm';
> I see this on the prompt from where I run the java program
> {code}
> org.apache.drill.jdbc.AlreadyClosedSqlException: Connection is already closed.
> at
> org.apache.drill.jdbc.impl.DrillConnectionImpl.checkNotClosed(DrillConnectionImpl.java:150)
> at
> org.apache.drill.jdbc.impl.DrillConnectionImpl.createStatement(DrillConnectionImpl.java:331)
> at
> org.apache.drill.jdbc.impl.DrillConnectionImpl.createStatement(DrillConnectionImpl.java:61)
> at
> net.hydromatic.avatica.AvaticaConnection.createStatement(AvaticaConnection.java:91)
> at
> net.hydromatic.avatica.AvaticaConnection.createStatement(AvaticaConnection.java:30)
> at ConcurrencyTest.executeQuery(ConcurrencyTest.java:43)
> at ConcurrencyTest.selectData(ConcurrencyTest.java:33)
> at ConcurrencyTest.run(ConcurrencyTest.java:23)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:744)
> java.sql.SQLException: While closing connection
> at net.hydromatic.avatica.Helper.createException(Helper.java:40)
> at
> net.hydromatic.avatica.AvaticaConnection.close(AvaticaConnection.java:137)
> at ConcurrencyTest.executeQuery(ConcurrencyTest.java:52)
> at ConcurrencyTest.selectData(ConcurrencyTest.java:33)
> at ConcurrencyTest.run(ConcurrencyTest.java:23)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:744)
> Caused by: java.lang.IllegalStateException: Failure while closing accountor.
> Expected private and shared pools to be set to initial values. However, one
> or more were not. Stats are
> zone init allocated delta
> private 0 0 0
> shared 11246501888 11246497280 4608.
> at
> org.apache.drill.exec.memory.AtomicRemainder.close(AtomicRemainder.java:200)
> at org.apache.drill.exec.memory.Accountor.close(Accountor.java:390)
> at
> org.apache.drill.exec.memory.TopLevelAllocator.close(TopLevelAllocator.java:187)
> at org.apache.drill.exec.client.DrillClient.close(DrillClient.java:261)
> at
> org.apache.drill.jdbc.impl.DrillConnectionImpl.cleanup(DrillConnectionImpl.java:377)
> at
> org.apache.drill.jdbc.impl.DrillHandler.onConnectionClose(DrillHandler.java:36)
> at
> net.hydromatic.avatica.AvaticaConnection.close(AvaticaConnection.java:135)
> ... 8 more
> {code}
> From drillbit.log
> {code}
> 2015-09-12 02:32:04,709 [BitServer-4] INFO
> o.a.d.e.w.fragment.FragmentExecutor -
> 2a0c71c7-9adc-2222-2a97-f2f218f5b7a2:0:0: State change requested RUNNING -->
> CANCELLATION_REQUESTED
> 2015-09-12 02:32:04,709 [BitServer-4] INFO
> o.a.d.e.w.f.FragmentStatusReporter -
> 2a0c71c7-9adc-2222-2a97-f2f218f5b7a2:0:0: State to report:
> CANCELLATION_REQUESTED
> 2015-09-12 02:32:04,720 [UserServer-1] ERROR
> o.a.d.exec.rpc.RpcExceptionHandler - Exception in RPC communication.
> Connection: /10.10.100.201:31010 <--> /10.10.100.201:53620 (user client).
> Closing connection.
> java.io.IOException: syscall:writev(...)() failed: Broken pipe
> ...
> 2015-09-12 02:32:04,896 [UserServer-1] INFO
> o.a.d.e.w.fragment.FragmentExecutor -
> 2a0c71c8-76f3-fda0-f1c0-fe8b0e80471c:0:0: State change requested
> CANCELLATION_REQUESTED --> FAILED
> 2015-09-12 02:32:04,898 [UserServer-1] WARN
> o.a.d.exec.rpc.RpcExceptionHandler - Exception occurred with closed channel.
> Connection: /10.10.100.201:31010 <--> /10.10.100.201:53620 (user client)
> io.netty.handler.codec.EncoderException: RpcEncoder must produce at least one
> message.
> at
> io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:98)
> ~[netty-codec-4.0.27.Final.jar:4.0.27.Final]
> at
> io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:705)
> [netty-transport-4.0.27.Final.jar:4.0.27.Final]
> at
> io.netty.channel.AbstractChannelHandlerContext.access$1900(AbstractChannelHandlerContext.java:32)
> [netty-transport-4.0.27.Final.jar:4.0.27.Final]
> at
> io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.write(AbstractChannelHandlerContext.java:980)
> [netty-transport-4.0.27.Final.jar:4.0.27.Final]
> at
> io.netty.channel.AbstractChannelHandlerContext$WriteAndFlushTask.write(AbstractChannelHandlerContext.java:1032)
> [netty-transport-4.0.27.Final.jar:4.0.27.Final]
> at
> io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.run(AbstractChannelHandlerContext.java:965)
> [netty-transport-4.0.27.Final.jar:4.0.27.Final]
> at
> io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:357)
> [netty-common-4.0.27.Final.jar:4.0.27.Final]
> at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254)
> [netty-transport-native-epoll-4.0.27.Final-linux-x86_64.jar:na]
> at
> io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111)
> [netty-common-4.0.27.Final.jar:4.0.27.Final]
> at java.lang.Thread.run(Thread.java:744) [na:1.7.0_45]
> {code}
> Output of sys.memory before concurrent queries were executed
> {code}
> 0: jdbc:drill:schema=dfs.tmp> select * from sys.memory
> . . . . . . . . . . . . . . > ;
> +-------------------+------------+---------------+-------------+-----------------+---------------------+-------------+
> | hostname | user_port | heap_current | heap_max |
> direct_current | jvm_direct_current | direct_max |
> +-------------------+------------+---------------+-------------+-----------------+---------------------+-------------+
> | centos-01.qa.lab | 31010 | 467280040 | 4294967296 | 12799111
> | 134231174 | 8589934592 |
> | centos-03.qa.lab | 31010 | 299898648 | 4294967296 | 8750365
> | 50345094 | 8589934592 |
> | centos-04.qa.lab | 31010 | 241172480 | 4294967296 | 8750365
> | 50345094 | 8589934592 |
> | centos-02.qa.lab | 31010 | 300100088 | 4294967296 | 8750365
> | 50345094 | 8589934592 |
> +-------------------+------------+---------------+-------------+-----------------+---------------------+-------------+
> 4 rows selected (1.178 seconds)
> {code}
> Output of sys.memory after concurrent queries were executed.
> {code}
> 0: jdbc:drill:schema=dfs.tmp> select * from sys.memory;
> +-------------------+------------+---------------+-------------+-----------------+---------------------+-------------+
> | hostname | user_port | heap_current | heap_max |
> direct_current | jvm_direct_current | direct_max |
> +-------------------+------------+---------------+-------------+-----------------+---------------------+-------------+
> | centos-01.qa.lab | 31010 | 2730085456 | 4294967296 | 103535261
> | 402814086 | 8589934592 |
> | centos-03.qa.lab | 31010 | 329258776 | 4294967296 | 8750365
> | 100676742 | 8589934592 |
> | centos-04.qa.lab | 31010 | 274726912 | 4294967296 | 8750365
> | 100676742 | 8589934592 |
> | centos-02.qa.lab | 31010 | 335751672 | 4294967296 | 8750377
> | 100676742 | 8589934592 |
> +-------------------+------------+---------------+-------------+-----------------+---------------------+-------------+
> 4 rows selected (0.19 seconds)
> {code}
> To repro the leak execute this class
> {code}
> import org.apache.log4j.Logger;
> import java.sql.Connection;
> import java.sql.ResultSet;
> import java.sql.SQLException;
> import java.sql.Statement;
> import java.sql.Types;
> import java.sql.*;
> import java.util.concurrent.ExecutorService;
> import java.util.concurrent.Executors;
> public class ConcurrencyTest implements Runnable {
> Connection conn = null;
> ConcurrencyTest(Connection conn) {
> this.conn = conn;
> }
> public void run() {
> try {
> selectData();
> } catch (Exception e) {
> System.out.println(e.getMessage());
> e.printStackTrace();
> }
> }
> // SELECT data
> public void selectData() {
> try {
> executeQuery("SELECT key1 , key2 FROM `twoKeyJsn.json` where
> key2 = 'm'");
> } catch(Exception e) {
> System.out.println(e.getMessage());
> e.printStackTrace();
> }
> }
> // Execute Query
> public void executeQuery(String query) {
> try {
> Statement stmt = conn.createStatement();
> ResultSet rs = stmt.executeQuery(query);
> while(rs.next()) {
> // do nothing.
> }
> if (rs != null)
> rs.close();
> stmt.close();
> conn.close();
> } catch (Exception e) {
> System.out.println(e.getMessage());
> e.printStackTrace();
> }
> }
> public static void main(String s[]) throws Exception {
> final String URL_STRING =
> "jdbc:drill:schema=dfs.tmp;drillbit=10.10.100.201";
> Class.forName("org.apache.drill.jdbc.Driver").newInstance();
> Connection conn = DriverManager.getConnection(URL_STRING,"","");
> ExecutorService executor = Executors.newFixedThreadPool(16);
> try {
> for (int i = 1; i <= 100; i++) {
> executor.submit(new ConcurrencyTest(conn));
> }
> } catch (Exception e) {
> System.out.println(e.getMessage());
> e.printStackTrace();
> }
> }
> }
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
