Antonio Piccolboni created HIVE-13037:
-----------------------------------------
Summary: Query with UDF never terminate
Key: HIVE-13037
URL: https://issues.apache.org/jira/browse/HIVE-13037
Project: Hive
Issue Type: Bug
Components: HiveServer2
Affects Versions: 1.0.0
Reporter: Antonio Piccolboni
Assignee: Vaibhav Gumashta
I am writing a client for HS2 that uses the JDBC interface. I can execute a
simple select query. When I add a UDF to the query, the client hangs. I looked
at the logs (larger excerpt below) and there is this bit that looks suspect,
and repeats ad infinitum
{code}
2016-02-10 20:26:49,571 INFO
[hiveServer2.async.multi_dest.batch_hiveServer2.async.multi_dest.batch.db_destWriter]:
queue.AuditFileSpool (AuditFileSpool.java:runDoAs(780)) - Destination is down.
sleeping for 30000 milli seconds. indexQueue=0,
queueName=hiveServer2.async.multi_dest.batch,
consumer=hiveServer2.async.multi_dest.batch.db
{code}
No tez dag is ever submitted or executed, per log and web UI. The only special
thing about this UDF may be that it accesses a file that has been added with
ADD FILE from hdfs.
Log from query submission to infinite loop first few iterations:
{code}
2016-02-10 20:24:32,695 INFO [HiveServer2-Handler-Pool: Thread-4907]:
parse.ParseDriver (ParseDriver.java:parse(185)) - Parsing command: SELECT
count(*) FROM (SELECT `mpg`, `cyl`,
`disp`, `hp`, `drat`, `wt`, `qsec`, `vs`, `am`, `gear`, `carb`,
rudfdouble('/tmp/8d4a5fc1-a5d1-4048-81dc-e1e3b86b3074_resources/squareudf',
`carb`) AS `sq`
FROM `mtcars`) AS `master`
2016-02-10 20:24:32,698 INFO [HiveServer2-Handler-Pool: Thread-4907]:
parse.ParseDriver (ParseDriver.java:parse(209)) - Parse Completed
2016-02-10 20:24:32,699 INFO [HiveServer2-Handler-Pool: Thread-4907]:
log.PerfLogger (PerfLogger.java:PerfLogEnd(148)) - </PERFLOG method=parse
start=1455135872695 end=145513587269
9 duration=4 from=org.apache.hadoop.hive.ql.Driver>
2016-02-10 20:24:32,704 INFO [HiveServer2-Handler-Pool: Thread-4907]:
log.PerfLogger (PerfLogger.java:PerfLogBegin(121)) - <PERFLOG
method=semanticAnalyze from=org.apache.hadoop.hi
ve.ql.Driver>
2016-02-10 20:24:32,704 INFO [HiveServer2-Handler-Pool: Thread-4907]:
parse.CalcitePlanner (SemanticAnalyzer.java:analyzeInternal(10105)) - Starting
Semantic Analysis
2016-02-10 20:24:32,704 INFO [HiveServer2-Handler-Pool: Thread-4907]:
parse.CalcitePlanner (SemanticAnalyzer.java:genResolvedParseTree(10052)) -
Completed phase 1 of Semantic Analy
sis
2016-02-10 20:24:32,705 INFO [HiveServer2-Handler-Pool: Thread-4907]:
parse.CalcitePlanner (SemanticAnalyzer.java:getMetaData(1534)) - Get metadata
for source tables
2016-02-10 20:24:32,705 INFO [HiveServer2-Handler-Pool: Thread-4907]:
parse.CalcitePlanner (SemanticAnalyzer.java:getMetaData(1686)) - Get metadata
for subqueries
2016-02-10 20:24:32,705 INFO [HiveServer2-Handler-Pool: Thread-4907]:
parse.CalcitePlanner (SemanticAnalyzer.java:getMetaData(1534)) - Get metadata
for source tables
2016-02-10 20:24:32,706 INFO [HiveServer2-Handler-Pool: Thread-4907]:
metastore.ObjectStore (ObjectStore.java:initialize(290)) - ObjectStore,
initialize called
2016-02-10 20:24:32,708 WARN [HiveServer2-Handler-Pool: Thread-4907]:
metastore.MetaStoreDirectSql (MetaStoreDirectSql.java:determineDbType(160)) -
DB Product name[MySQL] obtained,
but not used to determine db type. Falling back to using SQL to determine
which db we're using
2016-02-10 20:24:32,713 INFO [HiveServer2-Handler-Pool: Thread-4907]:
metastore.MetaStoreDirectSql (MetaStoreDirectSql.java:<init>(140)) - Using
direct SQL, underlying DB is MYSQL
2016-02-10 20:24:32,713 INFO [HiveServer2-Handler-Pool: Thread-4907]:
metastore.ObjectStore (ObjectStore.java:setConf(273)) - Initialized ObjectStore
2016-02-10 20:24:32,714 INFO [HiveServer2-Handler-Pool: Thread-4907]:
metastore.HiveMetaStore (HiveMetaStore.java:logInfo(747)) - 213: get_table :
db=default tbl=mtcars
2016-02-10 20:24:32,714 INFO [HiveServer2-Handler-Pool: Thread-4907]:
HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(372)) - ugi=hive
ip=unknown-ip-addr cmd=get_table
: db=default tbl=mtcars
2016-02-10 20:24:32,753 INFO [HiveServer2-Handler-Pool: Thread-4907]:
parse.CalcitePlanner (SemanticAnalyzer.java:getMetaData(1686)) - Get metadata
for subqueries
2016-02-10 20:24:32,753 INFO [HiveServer2-Handler-Pool: Thread-4907]:
parse.CalcitePlanner (SemanticAnalyzer.java:getMetaData(1710)) - Get metadata
for destination tables
2016-02-10 20:24:32,753 INFO [HiveServer2-Handler-Pool: Thread-4907]:
parse.CalcitePlanner (SemanticAnalyzer.java:getMetaData(1710)) - Get metadata
for destination tables
2016-02-10 20:24:32,772 INFO [HiveServer2-Handler-Pool: Thread-4907]:
ql.Context (Context.java:getMRScratchDir(330)) - New scratch dir is
hdfs://sandbox.hortonworks.com:8020/tmp/hi
ve/hive/8d4a5fc1-a5d1-4048-81dc-e1e3b86b3074/hive_2016-02-10_20-24-32_695_972448943093277787-40
2016-02-10 20:24:32,772 INFO [HiveServer2-Handler-Pool: Thread-4907]:
parse.CalcitePlanner (SemanticAnalyzer.java:genResolvedParseTree(10056)) -
Completed getting MetaData in Seman
tic Analysis
2016-02-10 20:24:32,772 INFO [HiveServer2-Handler-Pool: Thread-4907]:
parse.BaseSemanticAnalyzer (CalcitePlanner.java:canCBOHandleAst(392)) - Not
invoking CBO because the statement
has too few joins
2016-02-10 20:24:33,382 INFO [HiveServer2-Handler-Pool: Thread-4907]:
log.PerfLogger (PerfLogger.java:PerfLogEnd(148)) - </PERFLOG method=compile
start=1455135872694 end=1455135873382 duration=688
from=org.apache.hadoop.hive.ql.Driver>
2016-02-10 20:24:49,568 INFO
[hiveServer2.async.multi_dest.batch_hiveServer2.async.multi_dest.batch.db_destWriter]:
queue.AuditFileSpool (AuditFileSpool.java:runDoAs(780)) - Destination is down.
sleeping for 30000 milli seconds. indexQueue=0,
queueName=hiveServer2.async.multi_dest.batch,
consumer=hiveServer2.async.multi_dest.batch.db
2016-02-10 20:24:52,083 INFO [org.apache.ranger.audit.queue.AuditBatchQueue1]:
provider.BaseAuditHandler (BaseAuditHandler.java:logStatus(301)) - Audit Status
Log: name=hiveServer2.async.multi_dest.batch,
finalDestination=hiveServer2.async.multi_dest.batch.hdfs, interval=01:00.009
minutes, events=14, succcessCount=5, totalEvents=420, totalSuccessCount=111,
totalStashedCount=184
2016-02-10 20:25:03,352 INFO [org.apache.ranger.audit.queue.AuditBatchQueue0]:
provider.BaseAuditHandler (BaseAuditHandler.java:logStatus(301)) - Audit Status
Log: name=hiveServer2.async.multi_dest.batch,
finalDestination=hiveServer2.async.multi_dest.batch.db, interval=01:02.999
minutes, events=5, succcessCount=2, totalEvents=717, totalSuccessCount=295
2016-02-10 20:25:31,635 INFO [HiveServer2-Handler-Pool: Thread-5400]:
thrift.ThriftCLIService (ThriftCLIService.java:OpenSession(294)) - Client
protocol version: HIVE_CLI_SERVICE_PROTOCOL_V8
2016-02-10 20:25:31,653 INFO [HiveServer2-Handler-Pool: Thread-5400]:
session.SessionState (SessionState.java:createPath(641)) - Created local
directory: /tmp/47f78843-0f14-4db5-ad7c-318b37ac44c9_resources
2016-02-10 20:25:31,662 INFO [HiveServer2-Handler-Pool: Thread-5400]:
session.SessionState (SessionState.java:createPath(641)) - Created HDFS
directory: /tmp/hive/hive/47f78843-0f14-4db5-ad7c-318b37ac44c9
2016-02-10 20:25:31,665 INFO [HiveServer2-Handler-Pool: Thread-5400]:
session.SessionState (SessionState.java:createPath(641)) - Created local
directory: /tmp/hive/47f78843-0f14-4db5-ad7c-318b37ac44c9
2016-02-10 20:25:31,672 INFO [HiveServer2-Handler-Pool: Thread-5400]:
session.SessionState (SessionState.java:createPath(641)) - Created HDFS
directory: /tmp/hive/hive/47f78843-0f14-4db5-ad7c-318b37ac44c9/_tmp_space.db
2016-02-10 20:25:31,675 INFO [HiveServer2-Handler-Pool: Thread-5400]:
session.HiveSessionImpl (HiveSessionImpl.java:setOperationLogSessionDir(236)) -
Operation log session directory is created:
/home/hive/${system:java.io.tmpdir}/${system:user.name}/operation_logs/47f78843-0f14-4db5-ad7c-318b37ac44c9
2016-02-10 20:25:49,569 INFO
[hiveServer2.async.multi_dest.batch_hiveServer2.async.multi_dest.batch.db_destWriter]:
queue.AuditFileSpool (AuditFileSpool.java:runDoAs(780)) - Destination is down.
sleeping for 30000 milli seconds. indexQueue=0,
queueName=hiveServer2.async.multi_dest.batch,
consumer=hiveServer2.async.multi_dest.batch.db
2016-02-10 20:26:30,890 INFO [HiveServer2-Handler-Pool: Thread-5400]:
thrift.ThriftCLIService (ThriftCLIService.java:OpenSession(294)) - Client
protocol version: HIVE_CLI_SERVICE_PROTOCOL_V8
2016-02-10 20:26:30,902 INFO [HiveServer2-Handler-Pool: Thread-5400]:
session.SessionState (SessionState.java:createPath(641)) - Created local
directory: /tmp/2ca839b8-f6e5-465d-9ae7-3cbe5418be64_resources
2016-02-10 20:26:30,910 INFO [HiveServer2-Handler-Pool: Thread-5400]:
session.SessionState (SessionState.java:createPath(641)) - Created HDFS
directory: /tmp/hive/hive/2ca839b8-f6e5-465d-9ae7-3cbe5418be64
2016-02-10 20:26:30,914 INFO [HiveServer2-Handler-Pool: Thread-5400]:
session.SessionState (SessionState.java:createPath(641)) - Created local
directory: /tmp/hive/2ca839b8-f6e5-465d-9ae7-3cbe5418be64
2016-02-10 20:26:30,922 INFO [HiveServer2-Handler-Pool: Thread-5400]:
session.SessionState (SessionState.java:createPath(641)) - Created HDFS
directory: /tmp/hive/hive/2ca839b8-f6e5-465d-9ae7-3cbe5418be64/_tmp_space.db
2016-02-10 20:26:30,926 INFO [HiveServer2-Handler-Pool: Thread-5400]:
session.HiveSessionImpl (HiveSessionImpl.java:setOperationLogSessionDir(236)) -
Operation log session directory is created:
/home/hive/${system:java.io.tmpdir}/${system:user.name}/operation_logs/2ca839b8-f6e5-465d-9ae7-3cbe5418be64
2016-02-10 20:26:49,571 INFO
[hiveServer2.async.multi_dest.batch_hiveServer2.async.multi_dest.batch.db_destWriter]:
queue.AuditFileSpool (AuditFileSpool.java:runDoAs(780)) - Destination is down.
sleeping for 30000 milli seconds. indexQueue=0,
queueName=hiveServer2.async.multi_dest.batch,
consumer=hiveServer2.async.multi_dest.batch.db
2016-02-10 20:27:31,748 INFO [HiveServer2-Handler-Pool: Thread-5400]:
thrift.ThriftCLIService (ThriftCLIService.java:OpenSession(294)) - Client
protocol version: HIVE_CLI_SERVICE_PROTOCOL_V8
2016-02-10 20:27:31,763 INFO [HiveServer2-Handler-Pool: Thread-5400]:
session.SessionState (SessionState.java:createPath(641)) - Created local
directory: /tmp/701b1cef-63c4-4c13-a275-fe28469eccc8_resources
2016-02-10 20:27:31,771 INFO [HiveServer2-Handler-Pool: Thread-5400]:
session.SessionState (SessionState.java:createPath(641)) - Created HDFS
directory: /tmp/hive/hive/701b1cef-63c4-4c13-a275-fe28469eccc8
2016-02-10 20:27:31,776 INFO [HiveServer2-Handler-Pool: Thread-5400]:
session.SessionState (SessionState.java:createPath(641)) - Created local
directory: /tmp/hive/701b1cef-63c4-4c13-a275-fe28469eccc8
2016-02-10 20:27:31,783 INFO [HiveServer2-Handler-Pool: Thread-5400]:
session.SessionState (SessionState.java:createPath(641)) - Created HDFS
directory: /tmp/hive/hive/701b1cef-63c4-4c13-a275-fe28469eccc8/_tmp_space.db
2016-02-10 20:27:31,787 INFO [HiveServer2-Handler-Pool: Thread-5400]:
session.HiveSessionImpl (HiveSessionImpl.java:setOperationLogSessionDir(236)) -
Operation log session directory is created:
/home/hive/${system:java.io.tmpdir}/${system:user.name}/operation_logs/701b1cef-63c4-4c13-a275-fe28469eccc8
2016-02-10 20:27:49,572 INFO
[hiveServer2.async.multi_dest.batch_hiveServer2.async.multi_dest.batch.db_destWriter]:
queue.AuditFileSpool (AuditFileSpool.java:runDoAs(780)) - Destination is down.
sleeping for 30000 milli seconds. indexQueue=0,
queueName=hiveServer2.async.multi_dest.batch,
consumer=hiveServer2.async.multi_dest.batch.db
2016-02-10 20:28:31,397 INFO [HiveServer2-Handler-Pool: Thread-5400]:
thrift.ThriftCLIService (ThriftCLIService.java:OpenSession(294)) - Client
protocol version: HIVE_CLI_SERVICE_PROTOCOL_V8
{code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
