You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@hive.apache.org by "Antonio Piccolboni (JIRA)" <ji...@apache.org> on 2016/02/10 21:52:18 UTC
[jira] [Created] (HIVE-13037) Query with UDF never terminate
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)