another case of a query hangin' in v2.1.0. hive> select 1 from raw_logs.fact_mweb_datekey_by_hour where date_key=20160904 and hour=15 limit 1;
* date_key is a partition key and 20160904 exists. * hour is a bucketed column but does not exist. not sure it matters if it bucketed or not for the query to hang. * so empty result expected. as Gopal mentioned previously this does indeed fix it: * set hive.fetch.task.conversion=none; but not sure its the right thing to set globally just yet. Anyhoo users beware. Regards, Stephen On Wed, Aug 31, 2016 at 7:01 AM, Stephen Sprague <sprag...@gmail.com> wrote: > 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.Seque >> nceFileInputFormat >> output format: org.apache.hadoop.hive.ql.io.H >> iveSequenceFileOutputFormat >> 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(Fetc >> hOperator.java:517) >> at org.apache.hadoop.hive.ql.exec.FetchOperator.pushRow(FetchOp >> erator.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(CliDriv >> er.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(NativeMethodAcce >> ssorImpl.java:62) >> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMe >> thodAccessorImpl.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(DFSIn >> putStream.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(SequenceF >> ile.java:2101) >> at org.apache.hadoop.io.SequenceFile$Reader.next(SequenceFile. >> java:2508) >> at org.apache.hadoop.mapred.SequenceFileRecordReader.next(Seque >> nceFileRecordReader.java:82) >> at org.apache.hadoop.hive.ql.exec.FetchOperator.getNextRow(Fetc >> hOperator.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. >> > >
