You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@drill.apache.org by "Jacques Nadeau (JIRA)" <ji...@apache.org> on 2015/05/16 04:05:00 UTC

[jira] [Resolved] (DRILL-3105) OutOfMemoryError: GC overhead limit exceeded

     [ https://issues.apache.org/jira/browse/DRILL-3105?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Jacques Nadeau resolved DRILL-3105.
-----------------------------------
    Resolution: Fixed

Resolved in dd35b27

> 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)