You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@drill.apache.org by "Khurram Faraaz (JIRA)" <ji...@apache.org> on 2015/05/15 21:13:01 UTC
[jira] [Created] (DRILL-3105) OutOfMemoryError: GC overhead limit
exceeded
Khurram Faraaz created DRILL-3105:
-------------------------------------
Summary: OutOfMemoryError: GC overhead limit exceeded
Key: DRILL-3105
URL: https://issues.apache.org/jira/browse/DRILL-3105
Project: Apache Drill
Issue Type: Bug
Components: Execution - Flow
Affects Versions: 1.0.0
Reporter: Khurram Faraaz
Assignee: Chris Westin
On mapr-drill-1.0.0.31805-1.noarch.rpm we se OOM on sqlline prompt. Test was run on 4 node cluster on CentOS
{code}
[root@centos-01 ~]# cd /opt/mapr/drill/drill-1.0.0/bin/
[root@centos-01 bin]# ./sqlline -u "jdbc:drill:schema=dfs.tmp"
apache drill 1.0.0
"a drill in the hand is better than two in the bush"
0: jdbc:drill:schema=dfs.tmp> select * from sys.drillbits;
+-------------------+------------+---------------+------------+----------+
| hostname | user_port | control_port | data_port | current |
+-------------------+------------+---------------+------------+----------+
| centos-01.qa.lab | 31010 | 31011 | 31012 | false |
| centos-03.qa.lab | 31010 | 31011 | 31012 | false |
| centos-02.qa.lab | 31010 | 31011 | 31012 | false |
| centos-04.qa.lab | 31010 | 31011 | 31012 | true |
+-------------------+------------+---------------+------------+----------+
4 rows selected (1.977 seconds)
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-04.qa.lab | 31010 | 316917688 | 4294967296 | 11798941 | 100676587 | 8589934592 |
| centos-03.qa.lab | 31010 | 132006832 | 4294967296 | 7750365 | 50344939 | 8589934592 |
| centos-02.qa.lab | 31010 | 328204288 | 4294967296 | 7750365 | 50344939 | 8589934592 |
| centos-01.qa.lab | 31010 | 350224384 | 4294967296 | 7750365 | 50344939 | 8589934592 |
+-------------------+------------+---------------+-------------+-----------------+---------------------+-------------+
4 rows selected (0.967 seconds)
0: jdbc:drill:schema=dfs.tmp> select key1, key2 from `twoKeyJsn.json`;
java.lang.OutOfMemoryError: GC overhead limit exceeded
at sun.misc.FloatingDecimal.dtoa(FloatingDecimal.java:678)
at sun.misc.FloatingDecimal.<init>(FloatingDecimal.java:459)
at java.lang.Double.toString(Double.java:196)
at java.lang.Double.toString(Double.java:633)
at java.lang.String.valueOf(String.java:2854)
at sqlline.Rows$Row.<init>(Rows.java:157)
at sqlline.IncrementalRows.hasNext(IncrementalRows.java:63)
at sqlline.TableOutputFormat$ResizingRowsProvider.next(TableOutputFormat.java:77)
at sqlline.TableOutputFormat.print(TableOutputFormat.java:106)
at sqlline.SqlLine.print(SqlLine.java:1583)
at sqlline.Commands.execute(Commands.java:852)
at sqlline.Commands.sql(Commands.java:751)
at sqlline.SqlLine.dispatch(SqlLine.java:738)
at sqlline.SqlLine.begin(SqlLine.java:612)
at sqlline.SqlLine.start(SqlLine.java:366)
at sqlline.SqlLine.main(SqlLine.java:259)
0: jdbc:drill:schema=dfs.tmp>
0: jdbc:drill:schema=dfs.tmp> select * from `employee.csv`;
Error: CONNECTION ERROR: Connection /10.10.100.201:48746 <--> /10.10.100.204:31010 (user client) closed unexpectedly.
[Error Id: 7e0f3352-a412-49c9-83a1-7a3af324adb9 ] (state=,code=0)
The SQL query just hung, and there was nothing written to drillbit.log, I had to hit Ctrl-C and then the OOM showed up on sqlline prompt.
snippet from drillbit.log before query was Canceled
{code}
2015-05-15 18:51:17,669 [2aa9bfd9-cbfd-8c6f-44aa-411a7aa34503:foreman] INFO o.a.d.e.s.schedule.BlockMapBuilder - Get block maps: Executed 1 out of 1 using 1 threads. Time: 39ms total, 39.251707ms avg, 39ms max.
2015-05-15 18:51:17,669 [2aa9bfd9-cbfd-8c6f-44aa-411a7aa34503:foreman] INFO o.a.d.e.s.schedule.BlockMapBuilder - Get block maps: Executed 1 out of 1 using 1 threads. Earliest start: 10.168000 μs, Latest start: 10.168000 μs, Average start: 10.168000 μs .
2015-05-15 18:51:17,746 [2aa9bfd9-cbfd-8c6f-44aa-411a7aa34503:foreman] INFO o.a.drill.exec.work.foreman.Foreman - State change requested. PENDING --> RUNNING
2015-05-15 18:51:17,793 [2aa9bfd9-cbfd-8c6f-44aa-411a7aa34503:frag:0:0] INFO o.a.d.e.w.fragment.FragmentExecutor - 2aa9bfd9-cbfd-8c6f-44aa-411a7aa34503:0:0: State change requested from AWAITING_ALLOCATION --> RUNNING for
2015-05-15 18:51:17,793 [2aa9bfd9-cbfd-8c6f-44aa-411a7aa34503:frag:0:0] INFO o.a.d.e.w.f.AbstractStatusReporter - State changed for 2aa9bfd9-cbfd-8c6f-44aa-411a7aa34503:0:0. New state: RUNNING
2015-05-15 18:51:18,054 [2aa9bfd9-cbfd-8c6f-44aa-411a7aa34503:frag:0:0] INFO o.a.drill.exec.vector.UInt4Vector - Realloc vector null. [16384] -> [32768]
{code}
snippet from drillbit.log after query was Canceled
{code}
2015-05-15 18:56:19,938 [UserServer-1] INFO o.a.drill.exec.rpc.user.UserServer - RPC connection /10.10.100.204:31010 <--> /10.10.100.201:48746 (user client) timed out. Timeout was set to 30 seconds. Closing connection.
2015-05-15 18:56:19,941 [UserServer-1] INFO o.a.d.e.w.fragment.FragmentExecutor - 2aa9bfd9-cbfd-8c6f-44aa-411a7aa34503:0:0: State change requested from RUNNING --> FAILED for
2015-05-15 18:56:19,941 [UserServer-1] INFO o.a.drill.exec.work.foreman.Foreman - State change requested. RUNNING --> CANCELLATION_REQUESTED
2015-05-15 18:56:19,952 [UserServer-1] INFO o.a.d.e.w.fragment.FragmentExecutor - 2aa9bfd9-cbfd-8c6f-44aa-411a7aa34503:0:0: State change requested from FAILED --> FAILED for
2015-05-15 18:56:19,953 [BitServer-4] INFO o.a.d.e.w.fragment.FragmentExecutor - 2aa9bfd9-cbfd-8c6f-44aa-411a7aa34503:0:0: State change requested from FAILED --> CANCELLATION_REQUESTED for
2015-05-15 18:56:19,953 [BitServer-4] WARN o.a.d.e.w.fragment.FragmentExecutor - Ignoring unexpected state transition FAILED => CANCELLATION_REQUESTED.
2015-05-15 18:56:19,959 [UserServer-1] WARN o.a.d.exec.rpc.RpcExceptionHandler - Exception occurred with closed channel. Connection: /10.10.100.204:31010 <--> /10.10.100.201:48746 (user client)
java.nio.channels.ClosedChannelException: null
2015-05-15 18:56:19,959 [UserServer-1] INFO o.a.d.e.w.fragment.FragmentExecutor - 2aa9bfd9-cbfd-8c6f-44aa-411a7aa34503:0:0: State change requested from FAILED --> FAILED for
2015-05-15 18:56:19,960 [UserServer-1] WARN o.a.d.exec.rpc.RpcExceptionHandler - Exception occurred with closed channel. Connection: /10.10.100.204:31010 <--> /10.10.100.201:48746 (user client)
java.nio.channels.ClosedChannelException: null
2015-05-15 18:56:19,961 [UserServer-1] INFO o.a.d.e.w.fragment.FragmentExecutor - 2aa9bfd9-cbfd-8c6f-44aa-411a7aa34503:0:0: State change requested from FAILED --> FAILED for
2015-05-15 18:56:19,963 [UserServer-1] WARN o.a.d.exec.rpc.RpcExceptionHandler - Exception occurred with closed channel. Connection: /10.10.100.204:31010 <--> /10.10.100.201:48746 (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]
2015-05-15 18:56:19,963 [UserServer-1] INFO o.a.d.e.w.fragment.FragmentExecutor - 2aa9bfd9-cbfd-8c6f-44aa-411a7aa34503:0:0: State change requested from FAILED --> FAILED for
2015-05-15 18:56:19,964 [UserServer-1] WARN o.a.d.exec.rpc.RpcExceptionHandler - Exception occurred with closed channel. Connection: /10.10.100.204:31010 <--> /10.10.100.201:48746 (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}
The next query returned CONNECTION ERROR
{code}
0: jdbc:drill:schema=dfs.tmp>
0: jdbc:drill:schema=dfs.tmp> select * from `employee.csv`;
Error: CONNECTION ERROR: Connection /10.10.100.201:48746 <--> /10.10.100.204:31010 (user client) closed unexpectedly.
[Error Id: 7e0f3352-a412-49c9-83a1-7a3af324adb9 ] (state=,code=0)
{code}
File size of file used in query is
{code}
[root@centos-04 logs]# hadoop fs -ls /tmp/twoKeyJsn.json
-rwxr-xr-x 3 root root 888409136 2015-04-20 18:32 /tmp/twoKeyJsn.json
{code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)