[DRILL-3105] OutOfMemoryError: GC overhead limit exceeded - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Closed
Priority: Major
Resolution: Fixed
Affects Version/s: 1.0.0
Fix Version/s: 1.0.0
Component/s: Execution - Flow
Labels:
None

Description

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

[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

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]

snippet from drillbit.log after query was Canceled

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]
~

The next query returned CONNECTION ERROR

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)

File size of file used in query is

[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

Attachments

Activity

People

Assignee:: Chris Westin

Reporter:: Khurram Faraaz

Votes:: 0 Vote for this issue

Watchers:: 2 Start watching this issue

Dates

Created:: 15/May/15 19:12

Updated:: 18/May/15 22:00

Resolved:: 16/May/15 02:04