hi guys, Vlad: good suggestion however in my case its a 5 second query (when it works)
Gopal: Thanks for the explanation on the effect logging can have on the execution path. somewhat counter-intuitive i must say and as you can imagine a tad more challenging to debug - when debugging influences the observation. :) that said adding: set hive.fetch.task.conversion=none; forced the query plans to be the same and that made the difference. it worked. now i need to research that setting and see what the implications are. I'm sure it doesn't come for free. and as always a big thanks! lemme know if i can provide any details. the partition size is >1G btw. and this is using hive 2.1.0. Cheers, Stephen. ps here's the hdfs info - the table is bucketed by 24 fwiw. $ hdfs dfs -du -h /user/hive/warehouse/raw_logs.db/fact_www_access_datekey_by_hour/date_key=20160828 1.1 G 3.2 G /user/hive/warehouse/raw_logs.db/fact_www_access_datekey_by_hour/date_key=20160828/000000_0 1.1 G 3.2 G /user/hive/warehouse/raw_logs.db/fact_www_access_datekey_by_hour/date_key=20160828/000001_0 1.1 G 3.2 G /user/hive/warehouse/raw_logs.db/fact_www_access_datekey_by_hour/date_key=20160828/000002_0 1.1 G 3.2 G /user/hive/warehouse/raw_logs.db/fact_www_access_datekey_by_hour/date_key=20160828/000003_0 1.1 G 3.2 G /user/hive/warehouse/raw_logs.db/fact_www_access_datekey_by_hour/date_key=20160828/000004_0 1.1 G 3.2 G /user/hive/warehouse/raw_logs.db/fact_www_access_datekey_by_hour/date_key=20160828/000005_0 1.1 G 3.2 G /user/hive/warehouse/raw_logs.db/fact_www_access_datekey_by_hour/date_key=20160828/000006_0 1.1 G 3.2 G /user/hive/warehouse/raw_logs.db/fact_www_access_datekey_by_hour/date_key=20160828/000007_0 1.1 G 3.2 G /user/hive/warehouse/raw_logs.db/fact_www_access_datekey_by_hour/date_key=20160828/000008_0 1.1 G 3.2 G /user/hive/warehouse/raw_logs.db/fact_www_access_datekey_by_hour/date_key=20160828/000009_0 1.1 G 3.2 G /user/hive/warehouse/raw_logs.db/fact_www_access_datekey_by_hour/date_key=20160828/000010_0 1.1 G 3.2 G /user/hive/warehouse/raw_logs.db/fact_www_access_datekey_by_hour/date_key=20160828/000011_0 1.1 G 3.2 G /user/hive/warehouse/raw_logs.db/fact_www_access_datekey_by_hour/date_key=20160828/000012_0 1.1 G 3.2 G /user/hive/warehouse/raw_logs.db/fact_www_access_datekey_by_hour/date_key=20160828/000013_0 1.1 G 3.2 G /user/hive/warehouse/raw_logs.db/fact_www_access_datekey_by_hour/date_key=20160828/000014_0 1.1 G 3.2 G /user/hive/warehouse/raw_logs.db/fact_www_access_datekey_by_hour/date_key=20160828/000015_0 1.1 G 3.2 G /user/hive/warehouse/raw_logs.db/fact_www_access_datekey_by_hour/date_key=20160828/000016_0 1.1 G 3.2 G /user/hive/warehouse/raw_logs.db/fact_www_access_datekey_by_hour/date_key=20160828/000017_0 1.1 G 3.2 G /user/hive/warehouse/raw_logs.db/fact_www_access_datekey_by_hour/date_key=20160828/000018_0 1.1 G 3.2 G /user/hive/warehouse/raw_logs.db/fact_www_access_datekey_by_hour/date_key=20160828/000019_0 1.1 G 3.2 G /user/hive/warehouse/raw_logs.db/fact_www_access_datekey_by_hour/date_key=20160828/000020_0 1.1 G 3.2 G /user/hive/warehouse/raw_logs.db/fact_www_access_datekey_by_hour/date_key=20160828/000021_0 1.1 G 3.2 G /user/hive/warehouse/raw_logs.db/fact_www_access_datekey_by_hour/date_key=20160828/000022_0 1.1 G 3.2 G /user/hive/warehouse/raw_logs.db/fact_www_access_datekey_by_hour/date_key=20160828/000023_0 On Wed, Aug 31, 2016 at 12:19 AM, Vladimir Kroz <vladimir.k...@gmail.com> wrote: > One of the causes could be that on long-running queries your terminal > session gets disconnected and client process terminate (appearing like > query hangs). > > When debug messages are on, they will keep terminal session alive and > hence allowing your query to complete. > > I'm not sure if this is your case, but based on synopsis your provided it > could be one of the reasons. > > Cheers, > Vlad > > --------------- > From: Stephen Sprague <sprag...@gmail.com> > To: "user@hive.apache.org" <user@hive.apache.org> > Cc: > Date: Tue, 30 Aug 2016 20:28:50 -0700 > Subject: hive.root.logger influencing query plan?? so it's not so > Hi guys, > I've banged my head on this one all day and i need to surrender. I have a > query that hangs (never returns). However, when i turn on logging to DEBUG > level it works. I'm stumped. I include here the query, the different > query plans (with the only thing different being the log level) and a > traceback on the query that hangs. > > * the query > > #!/bin/bash > > sql=" > explain SELECT * > FROM raw_logs.fact_www_access_datekey_by_hour > WHERE date_key = 20160828 -- partition key > and lower(http_string) = 'foo' -- always evaluates to false > limit 1 -- if i remove limit 1 it works. I expect > an empty result set. > ; > " > > #hive -hiveconf hive.root.logger=ERROR,console -e "$sql" >stdout.bad > 2>stderr.bad #hangs > hive -hiveconf hive.root.logger=DEBUG,console -e "$sql" >stdout.good > 2>stderr.good #works > > > > * explain plan for the one that hangs (ERROR,console) > > STAGE DEPENDENCIES: > Stage-0 is a root stage > > STAGE PLANS: > Stage: Stage-0 > Fetch Operator > limit: 1 > Processor Tree: > TableScan > alias: fact_www_access_datekey_by_hour > Statistics: Num rows: 144355924 Data size: 158755813572 Basic > stats: COMPLETE Column stats: NONE > Filter Operator > predicate: (lower(http_string) = 'foo') (type: boolean) > Statistics: Num rows: 72177962 Data size: 79377906786 Basic > stats: COMPLETE Column stats: NONE > Select Operator > expressions: payload_year (type: int), payload_month (type: > int), payload_day (type: int), payload_time (type: string), > payload_gmt_offset (type: string), perf_time_micros (type: int), > http_string (type: string), http_type (type: string), http_version (type: > string), http_rc (type: int), http_size (type: int), referrer (type: > string), user_agent (type: string), bot_flag (type: string), ip_list (type: > array<string>), scalar_tags (type: map<string,string>), url_components > (type: array<string>), user_id (type: string), lt_session_id (type: > string), session_id (type: string), log_name (type: string), log_lineno > (type: int), log_line (type: string), web_server (type: string), > location_info (type: map<string,string>), dp_main_url_type (type: string), > dp_inventory_type (type: string), dp_main_url (type: > map<string,array<string>>), dp_tag_url (type: map<string,array<string>>), > dp_referrer_url (type: map<string,array<string>>), hour (type: int), > 20160828 (type: int) > outputColumnNames: _col0, _col1, _col2, _col3, _col4, _col5, > _col6, _col7, _col8, _col9, _col10, _col11, _col12, _col13, _col14, _col15, > _col16, _col17, _col18, _col19, _col20, _col21, _col22, _col23, _col24, > _col25, _col26, _col27, _col28, _col29, _col30, _col31 > Statistics: Num rows: 72177962 Data size: 79377906786 Basic > stats: COMPLETE Column stats: NONE > Limit > Number of rows: 1 > Statistics: Num rows: 1 Data size: 1099 Basic stats: > COMPLETE Column stats: NONE > ListSink > > * query plan for the one that works (DEBUG,console) > > STAGE DEPENDENCIES: > Stage-1 is a root stage > Stage-0 depends on stages: Stage-1 > > STAGE PLANS: > Stage: Stage-1 > Map Reduce > Map Operator Tree: > TableScan > alias: fact_www_access_datekey_by_hour > Statistics: Num rows: 144355924 Data size: 158755813572 Basic > stats: COMPLETE Column stats: NONE > Filter Operator > predicate: (lower(http_string) = 'foo') (type: boolean) > Statistics: Num rows: 72177962 Data size: 79377906786 Basic > stats: COMPLETE Column stats: NONE > Select Operator > expressions: payload_year (type: int), payload_month > (type: int), payload_day (type: int), payload_time (type: string), > payload_gmt_offset (type: string), perf_time_micros (type: int), > http_string (type: string), http_type (type: string), http_version (type: > string), http_rc (type: int), http_size (type: int), referrer (type: > string), user_agent (type: string), bot_flag (type: string), ip_list (type: > array<string>), scalar_tags (type: map<string,string>), url_components > (type: array<string>), user_id (type: string), lt_session_id (type: > string), session_id (type: string), log_name (type: string), log_lineno > (type: int), log_line (type: string), web_server (type: string), > location_info (type: map<string,string>), dp_main_url_type (type: string), > dp_inventory_type (type: string), dp_main_url (type: > map<string,array<string>>), dp_tag_url (type: map<string,array<string>>), > dp_referrer_url (type: map<string,array<string>>), hour (type: int), > 20160828 (type: int) > outputColumnNames: _col0, _col1, _col2, _col3, _col4, > _col5, _col6, _col7, _col8, _col9, _col10, _col11, _col12, _col13, _col14, > _col15, _col16, _col17, _col18, _col19, _col20, _col21, _col22, _col23, > _col24, _col25, _col26, _col27, _col28, _col29, _col30, _col31 > Statistics: Num rows: 72177962 Data size: 79377906786 > Basic stats: COMPLETE Column stats: NONE > Limit > Number of rows: 1 > Statistics: Num rows: 1 Data size: 1099 Basic stats: > COMPLETE Column stats: NONE > File Output Operator > compressed: true > Statistics: Num rows: 1 Data size: 1099 Basic stats: > COMPLETE Column stats: NONE > table: > input format: org.apache.hadoop.mapred. > SequenceFileInputFormat > output format: org.apache.hadoop.hive.ql.io. > HiveSequenceFileOutputFormat > serde: org.apache.hadoop.hive.serde2. > lazy.LazySimpleSerDe > > Stage: Stage-0 > Fetch Operator > limit: 1 > Processor Tree: > ListSink > > > > > * traceback when i press ctl-c on the client > > ^CFailed with exception java.io.IOException:java.io.IOException: > Filesystem closed > 16/08/30 20:16:09 [62cf87a8-2b39-47d2-b234-53631b60d84e main]: ERROR > CliDriver: - Failed with exception java.io.IOException:java.io.IOException: > Filesystem closed > java.io.IOException: java.io.IOException: Filesystem closed > at org.apache.hadoop.hive.ql.exec.FetchOperator.getNextRow( > FetchOperator.java:517) > at org.apache.hadoop.hive.ql.exec.FetchOperator.pushRow( > FetchOperator.java:424) > at org.apache.hadoop.hive.ql.exec.FetchTask.fetch( > FetchTask.java:144) > at org.apache.hadoop.hive.ql.Driver.getResults(Driver.java:1885) > at org.apache.hadoop.hive.cli.CliDriver.processLocalCmd( > CliDriver.java:252) > at org.apache.hadoop.hive.cli.CliDriver.processCmd( > CliDriver.java:183) > at org.apache.hadoop.hive.cli.CliDriver.processLine( > CliDriver.java:399) > at org.apache.hadoop.hive.cli.CliDriver.processLine( > CliDriver.java:335) > at org.apache.hadoop.hive.cli.CliDriver.executeDriver( > CliDriver.java:742) > at org.apache.hadoop.hive.cli.CliDriver.run(CliDriver.java:714) > at org.apache.hadoop.hive.cli.CliDriver.main(CliDriver.java:641) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at sun.reflect.NativeMethodAccessorImpl.invoke( > NativeMethodAccessorImpl.java:62) > at sun.reflect.DelegatingMethodAccessorImpl.invoke( > DelegatingMethodAccessorImpl.java:43) > at java.lang.reflect.Method.invoke(Method.java:483) > at org.apache.hadoop.util.RunJar.run(RunJar.java:221) > at org.apache.hadoop.util.RunJar.main(RunJar.java:136) > Caused by: java.io.IOException: Filesystem closed > at org.apache.hadoop.hdfs.DFSClient.checkOpen(DFSClient.java:794) > at org.apache.hadoop.hdfs.DFSInputStream.readWithStrategy( > DFSInputStream.java:833) > at org.apache.hadoop.hdfs.DFSInputStream.read( > DFSInputStream.java:897) > at org.apache.hadoop.hdfs.DFSInputStream.read( > DFSInputStream.java:700) > at java.io.DataInputStream.readInt(DataInputStream.java:387) > at org.apache.hadoop.io.SequenceFile$Reader.readBlock( > SequenceFile.java:2101) > at org.apache.hadoop.io.SequenceFile$Reader.next( > SequenceFile.java:2508) > at org.apache.hadoop.mapred.SequenceFileRecordReader.next( > SequenceFileRecordReader.java:82) > at org.apache.hadoop.hive.ql.exec.FetchOperator.getNextRow( > FetchOperator.java:484) > ... 16 more > > > on the one that hangs the job is never submitted to YARN. On the one that > succeeds the job is submitted. Ultimately though why does changing the log > level influence the query plan? > > any insights greatly appreciated. > > Thanks, > Stephen. >
