You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@kudu.apache.org by Nick Wolf <ni...@gmail.com> on 2016/01/28 23:24:48 UTC
Query failures in KUDU
Hi KUDU Team,
We have been experimenting KUDU for a while and noticing inserts and
selects are failing intermittently with following JDBC exception.
java.sql.SQLException: [Simba][ImpalaJDBCDriver](500051) ERROR processing
> query/statement. Error Code: ERROR_STATE, SQL state: null, Query: insert
> into temp select * from delta_table;.
> at com.cloudera.hivecommon.api.HS2Client.executeStatementInternal(Unknown
> Source)
> at com.cloudera.hivecommon.api.HS2Client.executeStatement(Unknown Source)
> at
> com.cloudera.hivecommon.dataengine.HiveJDBCNativeQueryExecutor.execute(Unknown
> Source)
> at com.cloudera.jdbc.common.SStatement.executeNoParams(Unknown Source)
> at com.cloudera.jdbc.common.SStatement.executeUpdate(Unknown Source)
> at weblogic.jdbc.wrapper.Statement.executeUpdate(Statement.java:530)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
> at java.util.concurrent.FutureTask.run(FutureTask.java:138)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> Caused by: com.cloudera.support.exceptions.GeneralException:
> [Simba][ImpalaJDBCDriver](500051) ERROR processing query/statement. Error
> Code: ERROR_STATE, SQL state: null, Query: insert into temp select * from
> delta_table; ... 14 more
> ... 14 more
We have observed following warnings in KUDU logs which seems to be too
technical for users. Can someone determine what is going on?
W0126 11:29:01.108304 13392 log.cc:514] Time spent Append to log took a
> long time: real 0.053s user 0.000s sys 0.000s
> W0126 13:07:31.910331 8271 env_posix.cc:820] Time spent sync call for
> /var/lib/kudu/tserver/data/8c053de02f844f8fbbea0509cc7cc1d5.data: real
> 1.053s user 0.001s sys 0.000s
> W0126 13:10:48.706079 44714 log.cc:514] Time spent Append to log took a
> long time: real 0.071s user 0.000s sys 0.000s
> W0126 13:10:48.706204 9916 log.cc:514] Time spent Append to log took a
> long time: real 0.072s user 0.000s sys 0.000s
> W0126 13:19:57.760201 44563 log.cc:514] Time spent Append to log took a
> long time: real 0.083s user 0.000s sys 0.000s
> W0127 10:06:04.007073 8271 compaction.cc:712] Found REINSERT REDO
> truncating row history for Source Row: (string
> pk=84220108ac17201b390b5b7ea23b86a4, string PARENT_NAME=PARENT00001, int32
> LEVEL_ID=NULL, double value=NULL) Redo Mutations: [@5955247507797458944(SET
> value=0), @5955247517553405952(SET value=0), @5955247518720282624(SET
> LEVEL_ID=0), @5955247628213231616(DELETE), @5955247633470758912(REINSERT
> (string pk=84220108ac17201b390b5b7ea23b86a4, string
> PARENT_NAME=PARENT00001, int32 LEVEL_ID=NULL, double value=NULL)),
> @5955247649014562816(SET value=0), @5955247658627330048(SET LEVEL_ID=0)]
> Undo Mutations: [@5955247497295126528(DELETE)]
> Dest Row: (string pk=84220108ac17201b390b5b7ea23b86a4, string
> PARENT_NAME=PARENT00001, int32 LEVEL_ID=NULL, double value=NULL) Redo
> Mutations: [] Undo Mutations: [@5955247633470758912(DELETE)] Note: this
> warning will appear only for the first truncated row
> W0127 10:06:04.007308 8271 compaction.cc:832] Total 10 rows lost some
> history due to REINSERT after DELETE
Re: Query failures in KUDU
Posted by David Alves <da...@gmail.com>.
Hi Nick
Those are (kind of) benign. It means that we lost history because a row
was deleted and reinserted after the initial MemRowset flush (meaning you
can't observe the state of the row before it was re-inserted). We're
looking into fixing this but I'm pretty sure this isn't related to the
problem you're having.
As I said, the logs on the impala side would be the most helpful here.
Anything interesting in those?
Best
David
On Fri, Jan 29, 2016 at 4:15 PM, Nick Wolf <ni...@gmail.com> wrote:
> This is happening rarely on a particular data condition which we are not
> able to reproduce. I will surely grab the log files if it happens again. Do
> you sense anything from those warnings? I see many like these
>
> W0127 10:06:04.007308 8271 compaction.cc:832] Total 10 rows lost some
> history due to REINSERT after DELETE
>
>
> On Thu, Jan 28, 2016 at 2:48 PM, David Alves <da...@gmail.com>
> wrote:
>
>> Hi Nick
>>
>> The tablet server log doesn't seem to show anything related to error
>> that you got.
>> Can you get the impala side logs? (that's likely where the meaningful
>> error is).
>>
>> Best
>> David
>>
>> On Thu, Jan 28, 2016 at 2:24 PM, Nick Wolf <ni...@gmail.com> wrote:
>>
>>> Hi KUDU Team,
>>>
>>> We have been experimenting KUDU for a while and noticing inserts and
>>> selects are failing intermittently with following JDBC exception.
>>>
>>> java.sql.SQLException: [Simba][ImpalaJDBCDriver](500051) ERROR
>>>> processing query/statement. Error Code: ERROR_STATE, SQL state: null,
>>>> Query: insert into temp select * from delta_table;.
>>>> at
>>>> com.cloudera.hivecommon.api.HS2Client.executeStatementInternal(Unknown
>>>> Source)
>>>> at com.cloudera.hivecommon.api.HS2Client.executeStatement(Unknown
>>>> Source)
>>>> at
>>>> com.cloudera.hivecommon.dataengine.HiveJDBCNativeQueryExecutor.execute(Unknown
>>>> Source)
>>>> at com.cloudera.jdbc.common.SStatement.executeNoParams(Unknown Source)
>>>> at com.cloudera.jdbc.common.SStatement.executeUpdate(Unknown Source)
>>>> at weblogic.jdbc.wrapper.Statement.executeUpdate(Statement.java:530)
>>>> at
>>>> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
>>>> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
>>>> at java.util.concurrent.FutureTask.run(FutureTask.java:138)
>>>> at
>>>> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
>>>> at
>>>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
>>>> Caused by: com.cloudera.support.exceptions.GeneralException:
>>>> [Simba][ImpalaJDBCDriver](500051) ERROR processing query/statement. Error
>>>> Code: ERROR_STATE, SQL state: null, Query: insert into temp select *
>>>> from delta_table; ... 14 more
>>>> ... 14 more
>>>
>>>
>>>
>>> We have observed following warnings in KUDU logs which seems to be too
>>> technical for users. Can someone determine what is going on?
>>>
>>> W0126 11:29:01.108304 13392 log.cc:514] Time spent Append to log took a
>>>> long time: real 0.053s user 0.000s sys 0.000s
>>>> W0126 13:07:31.910331 8271 env_posix.cc:820] Time spent sync call for
>>>> /var/lib/kudu/tserver/data/8c053de02f844f8fbbea0509cc7cc1d5.data: real
>>>> 1.053s user 0.001s sys 0.000s
>>>> W0126 13:10:48.706079 44714 log.cc:514] Time spent Append to log took a
>>>> long time: real 0.071s user 0.000s sys 0.000s
>>>> W0126 13:10:48.706204 9916 log.cc:514] Time spent Append to log took a
>>>> long time: real 0.072s user 0.000s sys 0.000s
>>>> W0126 13:19:57.760201 44563 log.cc:514] Time spent Append to log took a
>>>> long time: real 0.083s user 0.000s sys 0.000s
>>>> W0127 10:06:04.007073 8271 compaction.cc:712] Found REINSERT REDO
>>>> truncating row history for Source Row: (string
>>>> pk=84220108ac17201b390b5b7ea23b86a4, string PARENT_NAME=PARENT00001, int32
>>>> LEVEL_ID=NULL, double value=NULL) Redo Mutations: [@5955247507797458944(SET
>>>> value=0), @5955247517553405952(SET value=0), @5955247518720282624(SET
>>>> LEVEL_ID=0), @5955247628213231616(DELETE), @5955247633470758912(REINSERT
>>>> (string pk=84220108ac17201b390b5b7ea23b86a4, string
>>>> PARENT_NAME=PARENT00001, int32 LEVEL_ID=NULL, double value=NULL)),
>>>> @5955247649014562816(SET value=0), @5955247658627330048(SET LEVEL_ID=0)]
>>>> Undo Mutations: [@5955247497295126528(DELETE)]
>>>> Dest Row: (string pk=84220108ac17201b390b5b7ea23b86a4, string
>>>> PARENT_NAME=PARENT00001, int32 LEVEL_ID=NULL, double value=NULL) Redo
>>>> Mutations: [] Undo Mutations: [@5955247633470758912(DELETE)] Note: this
>>>> warning will appear only for the first truncated row
>>>> W0127 10:06:04.007308 8271 compaction.cc:832] Total 10 rows lost some
>>>> history due to REINSERT after DELETE
>>>
>>>
>>
>
Re: Query failures in KUDU
Posted by Nick Wolf <ni...@gmail.com>.
This is happening rarely on a particular data condition which we are not
able to reproduce. I will surely grab the log files if it happens again. Do
you sense anything from those warnings? I see many like these
W0127 10:06:04.007308 8271 compaction.cc:832] Total 10 rows lost some
history due to REINSERT after DELETE
On Thu, Jan 28, 2016 at 2:48 PM, David Alves <da...@gmail.com> wrote:
> Hi Nick
>
> The tablet server log doesn't seem to show anything related to error
> that you got.
> Can you get the impala side logs? (that's likely where the meaningful
> error is).
>
> Best
> David
>
> On Thu, Jan 28, 2016 at 2:24 PM, Nick Wolf <ni...@gmail.com> wrote:
>
>> Hi KUDU Team,
>>
>> We have been experimenting KUDU for a while and noticing inserts and
>> selects are failing intermittently with following JDBC exception.
>>
>> java.sql.SQLException: [Simba][ImpalaJDBCDriver](500051) ERROR processing
>>> query/statement. Error Code: ERROR_STATE, SQL state: null, Query: insert
>>> into temp select * from delta_table;.
>>> at
>>> com.cloudera.hivecommon.api.HS2Client.executeStatementInternal(Unknown
>>> Source)
>>> at com.cloudera.hivecommon.api.HS2Client.executeStatement(Unknown Source)
>>> at
>>> com.cloudera.hivecommon.dataengine.HiveJDBCNativeQueryExecutor.execute(Unknown
>>> Source)
>>> at com.cloudera.jdbc.common.SStatement.executeNoParams(Unknown Source)
>>> at com.cloudera.jdbc.common.SStatement.executeUpdate(Unknown Source)
>>> at weblogic.jdbc.wrapper.Statement.executeUpdate(Statement.java:530)
>>> at
>>> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
>>> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
>>> at java.util.concurrent.FutureTask.run(FutureTask.java:138)
>>> at
>>> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
>>> at
>>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
>>> Caused by: com.cloudera.support.exceptions.GeneralException:
>>> [Simba][ImpalaJDBCDriver](500051) ERROR processing query/statement. Error
>>> Code: ERROR_STATE, SQL state: null, Query: insert into temp select *
>>> from delta_table; ... 14 more
>>> ... 14 more
>>
>>
>>
>> We have observed following warnings in KUDU logs which seems to be too
>> technical for users. Can someone determine what is going on?
>>
>> W0126 11:29:01.108304 13392 log.cc:514] Time spent Append to log took a
>>> long time: real 0.053s user 0.000s sys 0.000s
>>> W0126 13:07:31.910331 8271 env_posix.cc:820] Time spent sync call for
>>> /var/lib/kudu/tserver/data/8c053de02f844f8fbbea0509cc7cc1d5.data: real
>>> 1.053s user 0.001s sys 0.000s
>>> W0126 13:10:48.706079 44714 log.cc:514] Time spent Append to log took a
>>> long time: real 0.071s user 0.000s sys 0.000s
>>> W0126 13:10:48.706204 9916 log.cc:514] Time spent Append to log took a
>>> long time: real 0.072s user 0.000s sys 0.000s
>>> W0126 13:19:57.760201 44563 log.cc:514] Time spent Append to log took a
>>> long time: real 0.083s user 0.000s sys 0.000s
>>> W0127 10:06:04.007073 8271 compaction.cc:712] Found REINSERT REDO
>>> truncating row history for Source Row: (string
>>> pk=84220108ac17201b390b5b7ea23b86a4, string PARENT_NAME=PARENT00001, int32
>>> LEVEL_ID=NULL, double value=NULL) Redo Mutations: [@5955247507797458944(SET
>>> value=0), @5955247517553405952(SET value=0), @5955247518720282624(SET
>>> LEVEL_ID=0), @5955247628213231616(DELETE), @5955247633470758912(REINSERT
>>> (string pk=84220108ac17201b390b5b7ea23b86a4, string
>>> PARENT_NAME=PARENT00001, int32 LEVEL_ID=NULL, double value=NULL)),
>>> @5955247649014562816(SET value=0), @5955247658627330048(SET LEVEL_ID=0)]
>>> Undo Mutations: [@5955247497295126528(DELETE)]
>>> Dest Row: (string pk=84220108ac17201b390b5b7ea23b86a4, string
>>> PARENT_NAME=PARENT00001, int32 LEVEL_ID=NULL, double value=NULL) Redo
>>> Mutations: [] Undo Mutations: [@5955247633470758912(DELETE)] Note: this
>>> warning will appear only for the first truncated row
>>> W0127 10:06:04.007308 8271 compaction.cc:832] Total 10 rows lost some
>>> history due to REINSERT after DELETE
>>
>>
>
Re: Query failures in KUDU
Posted by David Alves <da...@gmail.com>.
Hi Nick
The tablet server log doesn't seem to show anything related to error that
you got.
Can you get the impala side logs? (that's likely where the meaningful
error is).
Best
David
On Thu, Jan 28, 2016 at 2:24 PM, Nick Wolf <ni...@gmail.com> wrote:
> Hi KUDU Team,
>
> We have been experimenting KUDU for a while and noticing inserts and
> selects are failing intermittently with following JDBC exception.
>
> java.sql.SQLException: [Simba][ImpalaJDBCDriver](500051) ERROR processing
>> query/statement. Error Code: ERROR_STATE, SQL state: null, Query: insert
>> into temp select * from delta_table;.
>> at com.cloudera.hivecommon.api.HS2Client.executeStatementInternal(Unknown
>> Source)
>> at com.cloudera.hivecommon.api.HS2Client.executeStatement(Unknown Source)
>> at
>> com.cloudera.hivecommon.dataengine.HiveJDBCNativeQueryExecutor.execute(Unknown
>> Source)
>> at com.cloudera.jdbc.common.SStatement.executeNoParams(Unknown Source)
>> at com.cloudera.jdbc.common.SStatement.executeUpdate(Unknown Source)
>> at weblogic.jdbc.wrapper.Statement.executeUpdate(Statement.java:530)
>> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
>> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
>> at java.util.concurrent.FutureTask.run(FutureTask.java:138)
>> at
>> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
>> at
>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
>> Caused by: com.cloudera.support.exceptions.GeneralException:
>> [Simba][ImpalaJDBCDriver](500051) ERROR processing query/statement. Error
>> Code: ERROR_STATE, SQL state: null, Query: insert into temp select *
>> from delta_table; ... 14 more
>> ... 14 more
>
>
>
> We have observed following warnings in KUDU logs which seems to be too
> technical for users. Can someone determine what is going on?
>
> W0126 11:29:01.108304 13392 log.cc:514] Time spent Append to log took a
>> long time: real 0.053s user 0.000s sys 0.000s
>> W0126 13:07:31.910331 8271 env_posix.cc:820] Time spent sync call for
>> /var/lib/kudu/tserver/data/8c053de02f844f8fbbea0509cc7cc1d5.data: real
>> 1.053s user 0.001s sys 0.000s
>> W0126 13:10:48.706079 44714 log.cc:514] Time spent Append to log took a
>> long time: real 0.071s user 0.000s sys 0.000s
>> W0126 13:10:48.706204 9916 log.cc:514] Time spent Append to log took a
>> long time: real 0.072s user 0.000s sys 0.000s
>> W0126 13:19:57.760201 44563 log.cc:514] Time spent Append to log took a
>> long time: real 0.083s user 0.000s sys 0.000s
>> W0127 10:06:04.007073 8271 compaction.cc:712] Found REINSERT REDO
>> truncating row history for Source Row: (string
>> pk=84220108ac17201b390b5b7ea23b86a4, string PARENT_NAME=PARENT00001, int32
>> LEVEL_ID=NULL, double value=NULL) Redo Mutations: [@5955247507797458944(SET
>> value=0), @5955247517553405952(SET value=0), @5955247518720282624(SET
>> LEVEL_ID=0), @5955247628213231616(DELETE), @5955247633470758912(REINSERT
>> (string pk=84220108ac17201b390b5b7ea23b86a4, string
>> PARENT_NAME=PARENT00001, int32 LEVEL_ID=NULL, double value=NULL)),
>> @5955247649014562816(SET value=0), @5955247658627330048(SET LEVEL_ID=0)]
>> Undo Mutations: [@5955247497295126528(DELETE)]
>> Dest Row: (string pk=84220108ac17201b390b5b7ea23b86a4, string
>> PARENT_NAME=PARENT00001, int32 LEVEL_ID=NULL, double value=NULL) Redo
>> Mutations: [] Undo Mutations: [@5955247633470758912(DELETE)] Note: this
>> warning will appear only for the first truncated row
>> W0127 10:06:04.007308 8271 compaction.cc:832] Total 10 rows lost some
>> history due to REINSERT after DELETE
>
>