[
https://issues.apache.org/jira/browse/HIVE-10746?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14552793#comment-14552793
]
Greg Senia commented on HIVE-10746:
-----------------------------------
I am guessing this JIRA could be the root of this issue:
https://issues.apache.org/jira/browse/HIVE-7156
"gss2002_20150520132600_e4199888_c149_4394_8231_238d9d9dee98_1.Map_1_crc_arsn"
-> "gss2002_20150520132600_e4199888_c149_4394_8231_238d9d9dee98_1.Map_1" [
label = "Input [inputClass=MRInputLegacy,\n initializer=HiveSplitGenerator]" ]
2015-05-20 13:26:03,760 INFO [IPC Server handler 0 on 33574] app.DAGAppMaster:
JSON dump for submitted DAG, dagId=dag_1426958683478_173250_1,
json={"dagName":"gss2002_20150520132600_e4199888-c149-4394-8231-238d9d9dee98:1","dagInfo":"{\"description\":\"\\nSELECT
appl_user_id, arsn_cd, COUNT(*) as RecordCount FROM adw.crc_arsn GROUP BY
appl_user_id,arsn_cd ORDER BY
appl_user_id\",\"context\":\"Hive\"}","version":1,"vertices":[{"vertexName":"Map
1","processorClass":"org.apache.hadoop.hive.ql.exec.tez.MapTezProcessor","outEdgeIds":["196588160"],"additionalInputs":[{"name":"crc_arsn","class":"org.apache.tez.mapreduce.input.MRInputLegacy","initializer":"org.apache.hadoop.hive.ql.exec.tez.HiveSplitGenerator"}]},{"vertexName":"Reducer
2","processorClass":"org.apache.hadoop.hive.ql.exec.tez.ReduceTezProcessor","inEdgeIds":["196588160"],"outEdgeIds":["1320926067"]},{"vertexName":"Reducer
3","processorClass":"org.apache.hadoop.hive.ql.exec.tez.ReduceTezProcessor","inEdgeIds":["1320926067"],"additionalOutputs":[{"name":"out_Reducer
3","class":"org.apache.tez.mapreduce.output.MROutput"}]}],"edges":[{"edgeId":"196588160","inputVertexName":"Map
1","outputVertexName":"Reducer
2","dataMovementType":"SCATTER_GATHER","dataSourceType":"PERSISTED","schedulingType":"SEQUENTIAL","edgeSourceClass":"org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput","edgeDestinationClass":"org.apache.tez.runtime.library.input.OrderedGroupedKVInput"},{"edgeId":"1320926067","inputVertexName":"Reducer
2","outputVertexName":"Reducer
3","dataMovementType":"SCATTER_GATHER","dataSourceType":"PERSISTED","schedulingType":"SEQUENTIAL","edgeSourceClass":"org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput","edgeDestinationClass":"org.apache.tez.runtime.library.input.OrderedGroupedKVInput"}]}
2015-05-20 13:26:03,762 INFO [IPC Server handler 0 on 33574] app.DAGAppMaster:
Generating DAG graphviz file, dagId=dag_1426958683478_173250_1,
filePath=/u01/hadoop/yarn/log/application_1426958683478_173250/container_1426958683478_173250_01_000001/dag_1426958683478_173250_1.dot
2015-05-20 13:26:05,142 DEBUG [InputInitializer [Map 1] #0]
mapred.FileInputFormat: Total # of splits generated by getSplits: 40040,
TimeTaken: 168
2015-05-20 13:26:05,144 DEBUG [Socket Reader #1 for port 33574] ipc.Server:
got #159
2015-05-20 13:26:05,145 DEBUG [IPC Server handler 0 on 33574] ipc.Server: IPC
Server handler 0 on 33574:
org.apache.tez.dag.api.client.rpc.DAGClientAMProtocolBlockingPB.getDAGStatus
from 167.69.200.206:54162 Call#159 Retry#0 for RpcKind RPC_PROTOCOL_BUFFER
2015-05-20 13:26:05,145 DEBUG [IPC Server handler 0 on 33574]
security.UserGroupInformation: PrivilegedAction as:[email protected]
(auth:TOKEN) from:org.apache.hadoop.ipc.Server$Handler.run(Server.java:2007)
2015-05-20 13:26:05,147 INFO [IPC Server handler 0 on 33574] ipc.Server:
Served: getDAGStatus queueTime= 1 procesingTime= 2
2015-05-20 13:26:05,147 DEBUG [IPC Server handler 0 on 33574] ipc.Server: IPC
Server handler 0 on 33574: responding to
org.apache.tez.dag.api.client.rpc.DAGClientAMProtocolBlockingPB.getDAGStatus
from 167.69.200.206:54162 Call#159 Retry#0
2015-05-20 13:26:05,147 DEBUG [IPC Server handler 0 on 33574] ipc.Server: IPC
Server handler 0 on 33574: responding to
org.apache.tez.dag.api.client.rpc.DAGClientAMProtocolBlockingPB.getDAGStatus
from 167.69.200.206:54162 Call#159 Retry#0 Wrote 145 bytes.
2015-05-20 13:26:05,154 INFO [InputInitializer [Map 1] #0] io.HiveInputFormat:
number of splits 40040
2015-05-20 13:26:05,154 INFO [InputInitializer [Map 1] #0] log.PerfLogger:
</PERFLOG method=getSplits start=1432142764918 end=1432142765154 duration=236
from=org.apache.hadoop.hive.ql.io.HiveInputFormat>
2015-05-20 13:26:05,155 INFO [InputInitializer [Map 1] #0]
tez.HiveSplitGenerator: Number of input splits: 40040. 23542 available slots,
1.7 waves. Input format is: org.apache.hadoop.hive.ql.io.HiveInputFormat
> Hive 0.14.x and Hive 1.2.0 w/ Tez 0.5.3/Tez 0.6.0 Slow group by/order by
> ------------------------------------------------------------------------
>
> Key: HIVE-10746
> URL: https://issues.apache.org/jira/browse/HIVE-10746
> Project: Hive
> Issue Type: Bug
> Components: Hive, Tez
> Affects Versions: 0.14.0, 0.14.1, 1.2.0, 1.1.0, 1.1.1
> Reporter: Greg Senia
> Priority: Critical
> Attachments: slow_query_output.zip
>
>
> The following query: "SELECT appl_user_id, arsn_cd, COUNT(*) as RecordCount
> FROM adw.crc_arsn GROUP BY appl_user_id,arsn_cd ORDER BY appl_user_id;" runs
> consistently fast in Spark and Mapreduce on Hive 1.2.0. When attempting to
> run this same query against Tez as the execution engine it consistently runs
> for over 300-500 seconds this seems extremely long. This is a basic external
> table delimited by tabs and is a single file in a folder. In Hive 0.13 this
> query with Tez runs fast and I tested with Hive 0.14, 0.14.1/1.0.0 and now
> Hive 1.2.0 and there clearly is something going awry with Hive w/Tez as an
> execution engine with Single or small file tables. I can attach further logs
> if someone needs them for deeper analysis.
> HDFS Output:
> hadoop fs -ls /example_dw/crc/arsn
> Found 2 items
> -rwxr-x--- 6 loaduser hadoopusers 0 2015-05-17 20:03
> /example_dw/crc/arsn/_SUCCESS
> -rwxr-x--- 6 loaduser hadoopusers 3883880 2015-05-17 20:03
> /example_dw/crc/arsn/part-m-00000
> Hive Table Describe:
> hive> describe formatted crc_arsn;
> OK
> # col_name data_type comment
>
> arsn_cd string
> clmlvl_cd string
> arclss_cd string
> arclssg_cd string
> arsn_prcsr_rmk_ind string
> arsn_mbr_rspns_ind string
> savtyp_cd string
> arsn_eff_dt string
> arsn_exp_dt string
> arsn_pstd_dts string
> arsn_lstupd_dts string
> arsn_updrsn_txt string
> appl_user_id string
> arsntyp_cd string
> pre_d_indicator string
> arsn_display_txt string
> arstat_cd string
> arsn_tracking_no string
> arsn_cstspcfc_ind string
> arsn_mstr_rcrd_ind string
> state_specific_ind string
> region_specific_in string
> arsn_dpndnt_cd string
> unit_adjustment_in string
> arsn_mbr_only_ind string
> arsn_qrmb_ind string
>
> # Detailed Table Information
> Database: adw
> Owner: [email protected]
> CreateTime: Mon Apr 28 13:28:05 EDT 2014
> LastAccessTime: UNKNOWN
> Protect Mode: None
> Retention: 0
> Location: hdfs://xhadnnm1p.example.com:8020/example_dw/crc/arsn
>
> Table Type: EXTERNAL_TABLE
> Table Parameters:
> EXTERNAL TRUE
> transient_lastDdlTime 1398706085
>
> # Storage Information
> SerDe Library: org.apache.hadoop.hive.serde2.lazy.LazySimpleSerDe
>
> InputFormat: org.apache.hadoop.mapred.TextInputFormat
> OutputFormat:
> org.apache.hadoop.hive.ql.io.HiveIgnoreKeyTextOutputFormat
> Compressed: No
> Num Buckets: -1
> Bucket Columns: []
> Sort Columns: []
> Storage Desc Params:
> field.delim \t
> line.delim \n
> serialization.format \t
> Time taken: 1.245 seconds, Fetched: 54 row(s)
> Explain Hive 1.2.0 w/Tez:
> STAGE DEPENDENCIES:
> Stage-1 is a root stage
> Stage-0 depends on stages: Stage-1
> STAGE PLANS:
> Stage: Stage-1
> Tez
> Edges:
> Reducer 2 <- Map 1 (SIMPLE_EDGE)
> Reducer 3 <- Reducer 2 (SIMPLE_EDGE)
> Explain Hive 0.13 w/Tez:
> STAGE DEPENDENCIES:
> Stage-1 is a root stage
> Stage-0 is a root stage
> STAGE PLANS:
> Stage: Stage-1
> Tez
> Edges:
> Reducer 2 <- Map 1 (SIMPLE_EDGE)
> Reducer 3 <- Reducer 2 (SIMPLE_EDGE)
> Results:
> Hive 1.2.0 w/Spark 1.3.1:
> Finished successfully in 7.09 seconds
> Hive 1.2.0 w/Mapreduce:
> Stage 1: 32 Seconds
> Stage 2: 35 Seconds
> Hive 1.2.0 w/Tez 0.5.3:
> Time taken: 565.025 seconds, Fetched: 11516 row(s)
>
> Hive 0.13 w/Tez 0.4.0:
> Time taken: 13.552 seconds, Fetched: 11516 row(s)
> And finally looking at the Dag Attempt that is stuck for 500 seconds or so in
> Tez it looks to be stuck running the same method over and over again:
> 8 duration=2561 from=org.apache.hadoop.hive.ql.exec.tez.RecordProcessor>
> 2015-05-18 19:58:41,719 INFO [TezChild] exec.Utilities: PLAN PATH =
> hdfs://xhadnnm1p.example.com:8020/tmp/hive/gss2002/dbc4b0b5-7859-4487-a56d-969440bc5e90/hive_2015-05-18_19-58-25_951_5497535752804149087-1/gss2002/_tez_scratch_dir/4e635121-c4cd-4e3f-b96b-9f08a6a7bf5d/map.xml
> 2015-05-18 19:58:41,822 INFO [TezChild] exec.MapOperator: MAP[4]: records
> read - 1
> 2015-05-18 19:58:41,835 INFO [TezChild] io.HiveContextAwareRecordReader:
> Processing file
> hdfs://xhadnnm1p.example.com:8020/example_dw/crc/arsn/part-m-00000
> 2015-05-18 19:58:41,848 INFO [TezChild] io.HiveContextAwareRecordReader:
> Processing file
> hdfs://xhadnnm1p.example.com:8020/example_dw/crc/arsn/part-m-00000
> ......
> 2015-05-18 20:07:46,560 INFO [TezChild] io.HiveContextAwareRecordReader:
> Processing file
> hdfs://xhadnnm1p.example.com:8020/example_dw/crc/arsn/part-m-00000
> 2015-05-18 20:07:46,574 INFO [TezChild] io.HiveContextAwareRecordReader:
> Processing file
> hdfs://xhadnnm1p.example.com:8020/example_dw/crc/arsn/part-m-00000
> 2015-05-18 20:07:46,587 INFO [TezChild] io.HiveContextAwareRecordReader:
> Processing file
> hdfs://xhadnnm1p.example.com:8020/example_dw/crc/arsn/part-m-00000
> 2015-05-18 20:07:46,603 INFO [TezChild] io.HiveContextAwareRecordReader:
> Processing file
> hdfs://xhadnnm1p.example.com:8020/example_dw/crc/arsn/part-m-00000
> 2015-05-18 20:07:46,603 INFO [TezChild] log.PerfLogger: </PERFLOG
> method=TezRunProcessor start=1431993518764 end=1431994066603 duration=547839
> from=org.apache.hadoop.hive.ql.exec.tez.TezProcessor>
> 2015-05-18 20:07:46,603 INFO [TezChild] exec.MapOperator: 4 finished.
> closing...
> 2015-05-18 20:07:46,603 INFO [TezChild] exec.MapOperator:
> RECORDS_IN_Map_1:13440
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
