hive-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Stephen Sprague <sprag...@gmail.com>
Subject Re: hive.root.logger influencing query plan?? so it's not so
Date Sun, 04 Sep 2016 22:53:47 GMT
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 <spragues@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.kroz@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 <spragues@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.
>>
>
>

Mime
View raw message