[
https://issues.apache.org/jira/browse/DRILL-3771?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15217466#comment-15217466
]
Deneche A. Hakim edited comment on DRILL-3771 at 4/1/16 9:25 AM:
-----------------------------------------------------------------
although I couldn't reproduce the leak by following the described reproduction,
I am actually able to reproduce it if I cancel one of the queries. Reproduction
code can be on [Github|https://github.com/adeneche/repro3771/tree/DRILL-3771].
To reproduce the issue:
- clone the linked repository
- run {{mvn clean package}}
- run {{java -jar target/repro3771-1.0-SNAPSHOT-jar-with-dependencies.jar -d
<drillbit ip>}}
in the logs you will see the following exception:
{noformat}
2016-03-30 06:33:08,845 [pool-2-thread-10] 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:68)
[classes/:na]
at com.adeneche.ConcurrencyTest.run(ConcurrencyTest.java:38)
[classes/:na]
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
[na:1.7.0_71]
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
[na:1.7.0_71]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[na:1.7.0_71]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[na:1.7.0_71]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_71]
Caused by: java.lang.IllegalStateException: Allocator[ROOT] closed with
outstanding buffers allocated (1).
Allocator(ROOT) 0/131072/270336/3817865216 (res/actual/peak/limit)
child allocators: 0
ledgers: 1
ledger[530] allocator: ROOT), isOwning: true, size: 131072, references: 0,
life: 1459315982985436000..1459315988841107000, allocatorManager: [530, life:
1459315982985345000..0] holds 1 buffers.
DrillBuf[690], udle: [531 0..131072]
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}
was (Author: adeneche):
although I couldn't reproduce the leak by following the described reproduction,
I am actually able to reproduce it if I cancel one of the queries. Reproduction
code can be on [Github|https://github.com/adeneche/repro3771/tree/DRILL-3763].
To reproduce the issue:
- clone the linked repository
- run {{mvn clean package}}
- run {{java -jar target/repro3771-1.0-SNAPSHOT-jar-with-dependencies.jar -d
<drillbit ip>}}
in the logs you will see the following exception:
{noformat}
2016-03-30 06:33:08,845 [pool-2-thread-10] 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:68)
[classes/:na]
at com.adeneche.ConcurrencyTest.run(ConcurrencyTest.java:38)
[classes/:na]
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
[na:1.7.0_71]
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
[na:1.7.0_71]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[na:1.7.0_71]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[na:1.7.0_71]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_71]
Caused by: java.lang.IllegalStateException: Allocator[ROOT] closed with
outstanding buffers allocated (1).
Allocator(ROOT) 0/131072/270336/3817865216 (res/actual/peak/limit)
child allocators: 0
ledgers: 1
ledger[530] allocator: ROOT), isOwning: true, size: 131072, references: 0,
life: 1459315982985436000..1459315988841107000, allocatorManager: [530, life:
1459315982985345000..0] holds 1 buffers.
DrillBuf[690], udle: [531 0..131072]
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}
> Memory Leak in JDBC Client when canceling a query and closing the connection
> immediately
> ----------------------------------------------------------------------------------------
>
> Key: DRILL-3771
> URL: https://issues.apache.org/jira/browse/DRILL-3771
> Project: Apache Drill
> Issue Type: Bug
> Components: Client - JDBC
> Affects Versions: 1.2.0
> Environment: 4 node cluster CentOS
> Reporter: Khurram Faraaz
> Assignee: Deneche A. Hakim
> Priority: Minor
> Fix For: Future
>
>
> 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)
