[ 
https://issues.apache.org/jira/browse/HIVE-22416?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16961601#comment-16961601
 ] 

Hive QA commented on HIVE-22416:
--------------------------------

| (/) *{color:green}+1 overall{color}* |
\\
\\
|| Vote || Subsystem || Runtime || Comment ||
|| || || || {color:brown} Prechecks {color} ||
| {color:green}+1{color} | {color:green} @author {color} | {color:green}  0m  
0s{color} | {color:green} The patch does not contain any @author tags. {color} |
|| || || || {color:brown} master Compile Tests {color} ||
| {color:green}+1{color} | {color:green} mvninstall {color} | {color:green}  8m 
30s{color} | {color:green} master passed {color} |
| {color:green}+1{color} | {color:green} compile {color} | {color:green}  1m  
5s{color} | {color:green} master passed {color} |
| {color:green}+1{color} | {color:green} checkstyle {color} | {color:green}  0m 
38s{color} | {color:green} master passed {color} |
| {color:blue}0{color} | {color:blue} findbugs {color} | {color:blue}  3m 
57s{color} | {color:blue} ql in master has 1545 extant Findbugs warnings. 
{color} |
| {color:green}+1{color} | {color:green} javadoc {color} | {color:green}  1m  
0s{color} | {color:green} master passed {color} |
|| || || || {color:brown} Patch Compile Tests {color} ||
| {color:green}+1{color} | {color:green} mvninstall {color} | {color:green}  1m 
23s{color} | {color:green} the patch passed {color} |
| {color:green}+1{color} | {color:green} compile {color} | {color:green}  1m  
7s{color} | {color:green} the patch passed {color} |
| {color:green}+1{color} | {color:green} javac {color} | {color:green}  1m  
7s{color} | {color:green} the patch passed {color} |
| {color:green}+1{color} | {color:green} checkstyle {color} | {color:green}  0m 
38s{color} | {color:green} the patch passed {color} |
| {color:green}+1{color} | {color:green} whitespace {color} | {color:green}  0m 
 0s{color} | {color:green} The patch has no whitespace issues. {color} |
| {color:green}+1{color} | {color:green} findbugs {color} | {color:green}  4m  
9s{color} | {color:green} the patch passed {color} |
| {color:green}+1{color} | {color:green} javadoc {color} | {color:green}  1m  
0s{color} | {color:green} the patch passed {color} |
|| || || || {color:brown} Other Tests {color} ||
| {color:green}+1{color} | {color:green} asflicense {color} | {color:green}  0m 
15s{color} | {color:green} The patch does not generate ASF License warnings. 
{color} |
| {color:black}{color} | {color:black} {color} | {color:black} 24m 14s{color} | 
{color:black} {color} |
\\
\\
|| Subsystem || Report/Notes ||
| Optional Tests |  asflicense  javac  javadoc  findbugs  checkstyle  compile  |
| uname | Linux hiveptest-server-upstream 3.16.0-4-amd64 #1 SMP Debian 
3.16.43-2+deb8u5 (2017-09-19) x86_64 GNU/Linux |
| Build tool | maven |
| Personality | 
/data/hiveptest/working/yetus_PreCommit-HIVE-Build-19183/dev-support/hive-personality.sh
 |
| git revision | master / aceb8b6 |
| Default Java | 1.8.0_111 |
| findbugs | v3.0.1 |
| modules | C: ql U: ql |
| Console output | 
http://104.198.109.242/logs//PreCommit-HIVE-Build-19183/yetus.txt |
| Powered by | Apache Yetus    http://yetus.apache.org |


This message was automatically generated.



>  MR-related operation logs missing when parallel execution is enabled
> ---------------------------------------------------------------------
>
>                 Key: HIVE-22416
>                 URL: https://issues.apache.org/jira/browse/HIVE-22416
>             Project: Hive
>          Issue Type: Bug
>            Reporter: Karen Coppage
>            Assignee: Karen Coppage
>            Priority: Major
>         Attachments: HIVE-22416.01.patch
>
>
> Repro steps:
>  1. Happy path, parallel execution disabled
> {code:java}
> 0: jdbc:hive2://localhost:10000> set hive.exec.parallel=false;
> No rows affected (0.023 seconds)
> 0: jdbc:hive2://localhost:10000> select count  (*) from t1;
> INFO  : Compiling 
> command(queryId=karencoppage_20191028152610_a26c25e1-9834-446a-9a56-c676cb693e7d):
>  select count  (*) from t1
> INFO  : Semantic Analysis Completed
> INFO  : Returning Hive schema: Schema(fieldSchemas:[FieldSchema(name:c0, 
> type:bigint, comment:null)], properties:null)
> INFO  : Completed compiling 
> command(queryId=karencoppage_20191028152610_a26c25e1-9834-446a-9a56-c676cb693e7d);
>  Time taken: 0.309 seconds
> INFO  : Executing 
> command(queryId=karencoppage_20191028152610_a26c25e1-9834-446a-9a56-c676cb693e7d):
>  select count  (*) from t1
> WARN  : 
> INFO  : Query ID = 
> karencoppage_20191028152610_a26c25e1-9834-446a-9a56-c676cb693e7d
> INFO  : Total jobs = 1
> INFO  : Launching Job 1 out of 1
> INFO  : Starting task [Stage-1:MAPRED] in serial mode
> INFO  : Number of reduce tasks determined at compile time: 1
> INFO  : In order to change the average load for a reducer (in bytes):
> INFO  :   set hive.exec.reducers.bytes.per.reducer=<number>
> INFO  : In order to limit the maximum number of reducers:
> INFO  :   set hive.exec.reducers.max=<number>
> INFO  : In order to set a constant number of reducers:
> INFO  :   set mapreduce.job.reduces=<number>
> DEBUG : Configuring job job_local495362389_0008 with 
> file:/tmp/hadoop/mapred/staging/karencoppage495362389/.staging/job_local495362389_0008
>  as the submit dir
> DEBUG : adding the following namenodes' delegation tokens:[file:///]
> DEBUG : Creating splits at 
> file:/tmp/hadoop/mapred/staging/karencoppage495362389/.staging/job_local495362389_0008
> INFO  : number of splits:0
> INFO  : Submitting tokens for job: job_local495362389_0008
> INFO  : Executing with tokens: []
> INFO  : The url to track the job: http://localhost:8080/
> INFO  : Job running in-process (local Hadoop)
> INFO  : 2019-10-28 15:26:22,537 Stage-1 map = 0%,  reduce = 100%
> INFO  : Ended Job = job_local495362389_0008
> INFO  : MapReduce Jobs Launched: 
> INFO  : Stage-Stage-1:  HDFS Read: 0 HDFS Write: 0 SUCCESS
> INFO  : Total MapReduce CPU Time Spent: 0 msec
> INFO  : Completed executing 
> command(queryId=karencoppage_20191028152610_a26c25e1-9834-446a-9a56-c676cb693e7d);
>  Time taken: 6.497 seconds
> INFO  : OK
> DEBUG : Shutting down query select count  (*) from t1
> +-----+
> | c0  |
> +-----+
> | 0   |
> +-----+
> 1 row selected (11.874 seconds)
> {code}
> 2. Faulty path, parallel execution enabled
> {code:java}
> 0: jdbc:hive2://localhost:10000> set 
> hive.server2.logging.operation.level=EXECUTION;
> No rows affected (0.236 seconds)
> 0: jdbc:hive2://localhost:10000> set hive.exec.parallel=true;
> No rows affected (0.01 seconds)
> 0: jdbc:hive2://localhost:10000> select count  (*) from t1;
> INFO  : Compiling 
> command(queryId=karencoppage_20191028155346_4e7b793b-654e-4d69-b588-f3f0d3ae0c77):
>  select count  (*) from t1
> INFO  : Semantic Analysis Completed
> INFO  : Returning Hive schema: Schema(fieldSchemas:[FieldSchema(name:c0, 
> type:bigint, comment:null)], properties:null)
> INFO  : Completed compiling 
> command(queryId=karencoppage_20191028155346_4e7b793b-654e-4d69-b588-f3f0d3ae0c77);
>  Time taken: 4.707 seconds
> INFO  : Executing 
> command(queryId=karencoppage_20191028155346_4e7b793b-654e-4d69-b588-f3f0d3ae0c77):
>  select count  (*) from t1
> WARN  : 
> INFO  : Query ID = 
> karencoppage_20191028155346_4e7b793b-654e-4d69-b588-f3f0d3ae0c77
> INFO  : Total jobs = 1
> INFO  : Launching Job 1 out of 1
> INFO  : Starting task [Stage-1:MAPRED] in parallel
> INFO  : MapReduce Jobs Launched: 
> INFO  : Stage-Stage-1:  HDFS Read: 0 HDFS Write: 0 SUCCESS
> INFO  : Total MapReduce CPU Time Spent: 0 msec
> INFO  : Completed executing 
> command(queryId=karencoppage_20191028155346_4e7b793b-654e-4d69-b588-f3f0d3ae0c77);
>  Time taken: 44.577 seconds
> INFO  : OK
> DEBUG : Shutting down query select count  (*) from t1
> +-----+
> | c0  |
> +-----+
> | 0   |
> +-----+
> 1 row selected (54.665 seconds)
> {code}
> The issue is that Log4J stores the session ID and query ID in some atomic 
> thread metadata 
> (org.apache.logging.log4j.ThreadContext.getImmutableContext()). If the 
> queryId is missing from this metadata, then the RoutingAppender (which is 
> defined programmatically in LogDivertAppender) will route the log to a 
> NullAppender, which logs nothing. If the queryId is present, then the 
> RoutingAppender routes the event to the "query-appender", which will log the 
> line in the operation log/Beeline. This is not happening in a multi-threaded 
> context since new threads created for parallel query execution do not have 
> the queryId/sessionId metadata.
> The solution is to add the queryId/sessionId metadata to any new threads 
> created for MR work.



--
This message was sent by Atlassian Jira
(v8.3.4#803005)

Reply via email to