You are viewing a plain text version of this content. The canonical link for it is here.
Posted to common-issues@hadoop.apache.org by "Jingguo Yao (JIRA)" <ji...@apache.org> on 2010/11/30 09:55:11 UTC
[jira] Created: (HADOOP-7055) Update of commons logging libraries
causes EventCounter to count logging events incorrectly
Update of commons logging libraries causes EventCounter to count logging events incorrectly
-------------------------------------------------------------------------------------------
Key: HADOOP-7055
URL: https://issues.apache.org/jira/browse/HADOOP-7055
Project: Hadoop Common
Issue Type: Bug
Components: metrics
Affects Versions: 0.21.0
Reporter: Jingguo Yao
Hadoop 0.20.2 uses commons logging 1.0.4. EventCounter works correctly with this version of commons logging. Hadoop 0.21.0 uses commons logging 1.1.1 which causes EventCounter to count logging events incorrectly. I have verified it with Hadoop 0.21.0. After start-up of hadoop, I checked jvmmetrics.log after several minutes. In every metrics record, "logError=0, logFatal=0, logInfo=3, logWarn=0" was shown. The following text is an example.
jvm.metrics: hostName=jingguolin, processName=DataNode, sessionId=, gcCount=3, gcTimeMillis=31, logError=0, logFatal=0, logInfo=3, logWarn=0, maxMemoryM=888.9375, memHeapCommittedM=38.0625, memHeapUsedM=3.6539612, memNonHeapCommittedM=18.25, memNonHeapUsedM=11.335686, threadsBlocked=0, threadsNew=0, threadsRunnable=8, threadsTerminated=0, threadsTimedWaiting=6, threadsWaiting=6
Then I stopped hadoop and replaced commons logging 1.1.1 with 1.0.4. After the re-start of hadoop, a lot of logging events showed up in jvmmetrics.log.
I have checked the source code of Log4JLogger for both 1.0.4 (http://svn.apache.org/viewvc/commons/proper/logging/tags/LOGGING_1_0_4/src/java/org/apache/commons/logging/impl/Log4JLogger.java?view=markup) and 1.1.1 (http://svn.apache.org/viewvc/commons/proper/logging/tags/commons-logging-1.1.1/src/java/org/apache/commons/logging/impl/Log4JLogger.java?view=markup). For 1.0.4, Level instances such as Level.INFO are used to construct LoggingEvent. But for 1.1.1, Priority instances such as Priority.INFO are used to construct LoggingEvent. So 1.1.1 version's event.getLevel() always returns Priority instances. EventCounter append method's "==" check always fails between a Level instance and a Priority instance. For "logInfo=3" metrics records produced by commons logging 1.1.1., I think that these 3 logging events are produced by log4j code directly instead of through commons logging API. The following code is EventCounter's append method.
public void append(LoggingEvent event) {
Level level = event.getLevel();
if (level == Level.INFO) {
counts.incr(INFO);
}
else if (level == Level.WARN) {
counts.incr(WARN);
}
else if (level == Level.ERROR) {
counts.incr(ERROR);
}
else if (level == Level.FATAL) {
counts.incr(FATAL);
}
}
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] [Assigned] (HADOOP-7055) Update of commons logging libraries
causes EventCounter to count logging events incorrectly
Posted by "Jingguo Yao (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-7055?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Jingguo Yao reassigned HADOOP-7055:
-----------------------------------
Assignee: Jingguo Yao
> Update of commons logging libraries causes EventCounter to count logging events incorrectly
> -------------------------------------------------------------------------------------------
>
> Key: HADOOP-7055
> URL: https://issues.apache.org/jira/browse/HADOOP-7055
> Project: Hadoop Common
> Issue Type: Bug
> Components: metrics
> Affects Versions: 0.21.0, 0.21.1, 0.22.0, 0.23.0
> Reporter: Jingguo Yao
> Assignee: Jingguo Yao
> Original Estimate: 0.5h
> Remaining Estimate: 0.5h
>
> Hadoop 0.20.2 uses commons logging 1.0.4. EventCounter works correctly with this version of commons logging. Hadoop 0.21.0 uses commons logging 1.1.1 which causes EventCounter to count logging events incorrectly. I have verified it with Hadoop 0.21.0. After start-up of hadoop, I checked jvmmetrics.log after several minutes. In every metrics record, "logError=0, logFatal=0, logInfo=3, logWarn=0" was shown. The following text is an example.
> jvm.metrics: hostName=jingguolin, processName=DataNode, sessionId=, gcCount=3, gcTimeMillis=31, logError=0, logFatal=0, logInfo=3, logWarn=0, maxMemoryM=888.9375, memHeapCommittedM=38.0625, memHeapUsedM=3.6539612, memNonHeapCommittedM=18.25, memNonHeapUsedM=11.335686, threadsBlocked=0, threadsNew=0, threadsRunnable=8, threadsTerminated=0, threadsTimedWaiting=6, threadsWaiting=6
> Then I stopped hadoop and replaced commons logging 1.1.1 with 1.0.4. After the re-start of hadoop, a lot of logging events showed up in jvmmetrics.log.
> I have checked the source code of Log4JLogger for both 1.0.4 (http://svn.apache.org/viewvc/commons/proper/logging/tags/LOGGING_1_0_4/src/java/org/apache/commons/logging/impl/Log4JLogger.java?view=markup) and 1.1.1 (http://svn.apache.org/viewvc/commons/proper/logging/tags/commons-logging-1.1.1/src/java/org/apache/commons/logging/impl/Log4JLogger.java?view=markup). For 1.0.4, Level instances such as Level.INFO are used to construct LoggingEvent. But for 1.1.1, Priority instances such as Priority.INFO are used to construct LoggingEvent. So 1.1.1 version's event.getLevel() always returns Priority instances. EventCounter append method's "==" check always fails between a Level instance and a Priority instance. For "logInfo=3" metrics records produced by commons logging 1.1.1., I think that these 3 logging events are produced by log4j code directly instead of through commons logging API. The following code is EventCounter's append method.
> public void append(LoggingEvent event) {
> Level level = event.getLevel();
> if (level == Level.INFO) {
> counts.incr(INFO);
> }
> else if (level == Level.WARN) {
> counts.incr(WARN);
> }
> else if (level == Level.ERROR) {
> counts.incr(ERROR);
> }
> else if (level == Level.FATAL) {
> counts.incr(FATAL);
> }
> }
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (HADOOP-7055) Update of commons logging
libraries causes EventCounter to count logging events incorrectly
Posted by "Jingguo Yao (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-7055?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13011724#comment-13011724 ]
Jingguo Yao commented on HADOOP-7055:
-------------------------------------
When EventCounter appender is triggered, it only updates its counts field. So equals overhead is not negligible compared to the actual logging which is counts field updating in this case.
But if we think that the overhead incurred by equals is negligible on the overall performance, we can use equals.
> Update of commons logging libraries causes EventCounter to count logging events incorrectly
> -------------------------------------------------------------------------------------------
>
> Key: HADOOP-7055
> URL: https://issues.apache.org/jira/browse/HADOOP-7055
> Project: Hadoop Common
> Issue Type: Bug
> Components: metrics
> Affects Versions: 0.21.0, 0.21.1, 0.22.0, 0.23.0
> Reporter: Jingguo Yao
> Assignee: Jingguo Yao
> Original Estimate: 0.5h
> Remaining Estimate: 0.5h
>
> Hadoop 0.20.2 uses commons logging 1.0.4. EventCounter works correctly with this version of commons logging. Hadoop 0.21.0 uses commons logging 1.1.1 which causes EventCounter to count logging events incorrectly. I have verified it with Hadoop 0.21.0. After start-up of hadoop, I checked jvmmetrics.log after several minutes. In every metrics record, "logError=0, logFatal=0, logInfo=3, logWarn=0" was shown. The following text is an example.
> jvm.metrics: hostName=jingguolin, processName=DataNode, sessionId=, gcCount=3, gcTimeMillis=31, logError=0, logFatal=0, logInfo=3, logWarn=0, maxMemoryM=888.9375, memHeapCommittedM=38.0625, memHeapUsedM=3.6539612, memNonHeapCommittedM=18.25, memNonHeapUsedM=11.335686, threadsBlocked=0, threadsNew=0, threadsRunnable=8, threadsTerminated=0, threadsTimedWaiting=6, threadsWaiting=6
> Then I stopped hadoop and replaced commons logging 1.1.1 with 1.0.4. After the re-start of hadoop, a lot of logging events showed up in jvmmetrics.log.
> I have checked the source code of Log4JLogger for both 1.0.4 (http://svn.apache.org/viewvc/commons/proper/logging/tags/LOGGING_1_0_4/src/java/org/apache/commons/logging/impl/Log4JLogger.java?view=markup) and 1.1.1 (http://svn.apache.org/viewvc/commons/proper/logging/tags/commons-logging-1.1.1/src/java/org/apache/commons/logging/impl/Log4JLogger.java?view=markup). For 1.0.4, Level instances such as Level.INFO are used to construct LoggingEvent. But for 1.1.1, Priority instances such as Priority.INFO are used to construct LoggingEvent. So 1.1.1 version's event.getLevel() always returns Priority instances. EventCounter append method's "==" check always fails between a Level instance and a Priority instance. For "logInfo=3" metrics records produced by commons logging 1.1.1., I think that these 3 logging events are produced by log4j code directly instead of through commons logging API. The following code is EventCounter's append method.
> public void append(LoggingEvent event) {
> Level level = event.getLevel();
> if (level == Level.INFO) {
> counts.incr(INFO);
> }
> else if (level == Level.WARN) {
> counts.incr(WARN);
> }
> else if (level == Level.ERROR) {
> counts.incr(ERROR);
> }
> else if (level == Level.FATAL) {
> counts.incr(FATAL);
> }
> }
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (HADOOP-7055) Update of commons logging libraries
causes EventCounter to count logging events incorrectly
Posted by "Jingguo Yao (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-7055?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Jingguo Yao updated HADOOP-7055:
--------------------------------
Attachment: HADOOP-7055.patch
> Update of commons logging libraries causes EventCounter to count logging events incorrectly
> -------------------------------------------------------------------------------------------
>
> Key: HADOOP-7055
> URL: https://issues.apache.org/jira/browse/HADOOP-7055
> Project: Hadoop Common
> Issue Type: Bug
> Components: metrics
> Affects Versions: 0.21.0, 0.21.1, 0.22.0, 0.23.0
> Reporter: Jingguo Yao
> Assignee: Jingguo Yao
> Attachments: HADOOP-7055.patch
>
> Original Estimate: 0.5h
> Remaining Estimate: 0.5h
>
> Hadoop 0.20.2 uses commons logging 1.0.4. EventCounter works correctly with this version of commons logging. Hadoop 0.21.0 uses commons logging 1.1.1 which causes EventCounter to count logging events incorrectly. I have verified it with Hadoop 0.21.0. After start-up of hadoop, I checked jvmmetrics.log after several minutes. In every metrics record, "logError=0, logFatal=0, logInfo=3, logWarn=0" was shown. The following text is an example.
> jvm.metrics: hostName=jingguolin, processName=DataNode, sessionId=, gcCount=3, gcTimeMillis=31, logError=0, logFatal=0, logInfo=3, logWarn=0, maxMemoryM=888.9375, memHeapCommittedM=38.0625, memHeapUsedM=3.6539612, memNonHeapCommittedM=18.25, memNonHeapUsedM=11.335686, threadsBlocked=0, threadsNew=0, threadsRunnable=8, threadsTerminated=0, threadsTimedWaiting=6, threadsWaiting=6
> Then I stopped hadoop and replaced commons logging 1.1.1 with 1.0.4. After the re-start of hadoop, a lot of logging events showed up in jvmmetrics.log.
> I have checked the source code of Log4JLogger for both 1.0.4 (http://svn.apache.org/viewvc/commons/proper/logging/tags/LOGGING_1_0_4/src/java/org/apache/commons/logging/impl/Log4JLogger.java?view=markup) and 1.1.1 (http://svn.apache.org/viewvc/commons/proper/logging/tags/commons-logging-1.1.1/src/java/org/apache/commons/logging/impl/Log4JLogger.java?view=markup). For 1.0.4, Level instances such as Level.INFO are used to construct LoggingEvent. But for 1.1.1, Priority instances such as Priority.INFO are used to construct LoggingEvent. So 1.1.1 version's event.getLevel() always returns Priority instances. EventCounter append method's "==" check always fails between a Level instance and a Priority instance. For "logInfo=3" metrics records produced by commons logging 1.1.1., I think that these 3 logging events are produced by log4j code directly instead of through commons logging API. The following code is EventCounter's append method.
> public void append(LoggingEvent event) {
> Level level = event.getLevel();
> if (level == Level.INFO) {
> counts.incr(INFO);
> }
> else if (level == Level.WARN) {
> counts.incr(WARN);
> }
> else if (level == Level.ERROR) {
> counts.incr(ERROR);
> }
> else if (level == Level.FATAL) {
> counts.incr(FATAL);
> }
> }
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (HADOOP-7055) Update of commons logging libraries
causes EventCounter to count logging events incorrectly
Posted by "Jingguo Yao (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-7055?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Jingguo Yao updated HADOOP-7055:
--------------------------------
Status: Patch Available (was: Open)
Per Luke's suggestion, use equals instead of == for Level check.
> Update of commons logging libraries causes EventCounter to count logging events incorrectly
> -------------------------------------------------------------------------------------------
>
> Key: HADOOP-7055
> URL: https://issues.apache.org/jira/browse/HADOOP-7055
> Project: Hadoop Common
> Issue Type: Bug
> Components: metrics
> Affects Versions: 0.21.0, 0.21.1, 0.22.0, 0.23.0
> Reporter: Jingguo Yao
> Assignee: Jingguo Yao
> Original Estimate: 0.5h
> Remaining Estimate: 0.5h
>
> Hadoop 0.20.2 uses commons logging 1.0.4. EventCounter works correctly with this version of commons logging. Hadoop 0.21.0 uses commons logging 1.1.1 which causes EventCounter to count logging events incorrectly. I have verified it with Hadoop 0.21.0. After start-up of hadoop, I checked jvmmetrics.log after several minutes. In every metrics record, "logError=0, logFatal=0, logInfo=3, logWarn=0" was shown. The following text is an example.
> jvm.metrics: hostName=jingguolin, processName=DataNode, sessionId=, gcCount=3, gcTimeMillis=31, logError=0, logFatal=0, logInfo=3, logWarn=0, maxMemoryM=888.9375, memHeapCommittedM=38.0625, memHeapUsedM=3.6539612, memNonHeapCommittedM=18.25, memNonHeapUsedM=11.335686, threadsBlocked=0, threadsNew=0, threadsRunnable=8, threadsTerminated=0, threadsTimedWaiting=6, threadsWaiting=6
> Then I stopped hadoop and replaced commons logging 1.1.1 with 1.0.4. After the re-start of hadoop, a lot of logging events showed up in jvmmetrics.log.
> I have checked the source code of Log4JLogger for both 1.0.4 (http://svn.apache.org/viewvc/commons/proper/logging/tags/LOGGING_1_0_4/src/java/org/apache/commons/logging/impl/Log4JLogger.java?view=markup) and 1.1.1 (http://svn.apache.org/viewvc/commons/proper/logging/tags/commons-logging-1.1.1/src/java/org/apache/commons/logging/impl/Log4JLogger.java?view=markup). For 1.0.4, Level instances such as Level.INFO are used to construct LoggingEvent. But for 1.1.1, Priority instances such as Priority.INFO are used to construct LoggingEvent. So 1.1.1 version's event.getLevel() always returns Priority instances. EventCounter append method's "==" check always fails between a Level instance and a Priority instance. For "logInfo=3" metrics records produced by commons logging 1.1.1., I think that these 3 logging events are produced by log4j code directly instead of through commons logging API. The following code is EventCounter's append method.
> public void append(LoggingEvent event) {
> Level level = event.getLevel();
> if (level == Level.INFO) {
> counts.incr(INFO);
> }
> else if (level == Level.WARN) {
> counts.incr(WARN);
> }
> else if (level == Level.ERROR) {
> counts.incr(ERROR);
> }
> else if (level == Level.FATAL) {
> counts.incr(FATAL);
> }
> }
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] Updated: (HADOOP-7055) Update of commons logging libraries
causes EventCounter to count logging events incorrectly
Posted by "Eli Collins (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-7055?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Eli Collins updated HADOOP-7055:
--------------------------------
Affects Version/s: 0.23.0
0.22.0
0.21.1
Fix Version/s: 0.23.0
0.22.0
0.21.1
Good catch Jingguo. Sounds like append needs to check Priority rather than Level? Seems like we shouldn't need to check both given that we've updated the library.
> Update of commons logging libraries causes EventCounter to count logging events incorrectly
> -------------------------------------------------------------------------------------------
>
> Key: HADOOP-7055
> URL: https://issues.apache.org/jira/browse/HADOOP-7055
> Project: Hadoop Common
> Issue Type: Bug
> Components: metrics
> Affects Versions: 0.21.0, 0.21.1, 0.22.0, 0.23.0
> Reporter: Jingguo Yao
> Fix For: 0.21.1, 0.22.0, 0.23.0
>
> Original Estimate: 0.5h
> Remaining Estimate: 0.5h
>
> Hadoop 0.20.2 uses commons logging 1.0.4. EventCounter works correctly with this version of commons logging. Hadoop 0.21.0 uses commons logging 1.1.1 which causes EventCounter to count logging events incorrectly. I have verified it with Hadoop 0.21.0. After start-up of hadoop, I checked jvmmetrics.log after several minutes. In every metrics record, "logError=0, logFatal=0, logInfo=3, logWarn=0" was shown. The following text is an example.
> jvm.metrics: hostName=jingguolin, processName=DataNode, sessionId=, gcCount=3, gcTimeMillis=31, logError=0, logFatal=0, logInfo=3, logWarn=0, maxMemoryM=888.9375, memHeapCommittedM=38.0625, memHeapUsedM=3.6539612, memNonHeapCommittedM=18.25, memNonHeapUsedM=11.335686, threadsBlocked=0, threadsNew=0, threadsRunnable=8, threadsTerminated=0, threadsTimedWaiting=6, threadsWaiting=6
> Then I stopped hadoop and replaced commons logging 1.1.1 with 1.0.4. After the re-start of hadoop, a lot of logging events showed up in jvmmetrics.log.
> I have checked the source code of Log4JLogger for both 1.0.4 (http://svn.apache.org/viewvc/commons/proper/logging/tags/LOGGING_1_0_4/src/java/org/apache/commons/logging/impl/Log4JLogger.java?view=markup) and 1.1.1 (http://svn.apache.org/viewvc/commons/proper/logging/tags/commons-logging-1.1.1/src/java/org/apache/commons/logging/impl/Log4JLogger.java?view=markup). For 1.0.4, Level instances such as Level.INFO are used to construct LoggingEvent. But for 1.1.1, Priority instances such as Priority.INFO are used to construct LoggingEvent. So 1.1.1 version's event.getLevel() always returns Priority instances. EventCounter append method's "==" check always fails between a Level instance and a Priority instance. For "logInfo=3" metrics records produced by commons logging 1.1.1., I think that these 3 logging events are produced by log4j code directly instead of through commons logging API. The following code is EventCounter's append method.
> public void append(LoggingEvent event) {
> Level level = event.getLevel();
> if (level == Level.INFO) {
> counts.incr(INFO);
> }
> else if (level == Level.WARN) {
> counts.incr(WARN);
> }
> else if (level == Level.ERROR) {
> counts.incr(ERROR);
> }
> else if (level == Level.FATAL) {
> counts.incr(FATAL);
> }
> }
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] [Commented] (HADOOP-7055) Update of commons logging
libraries causes EventCounter to count logging events incorrectly
Posted by "Luke Lu (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-7055?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13011825#comment-13011825 ]
Luke Lu commented on HADOOP-7055:
---------------------------------
bq. When EventCounter appender is triggered, it only updates its counts field. So equals overhead is not negligible compared to the actual logging which is counts field updating in this case.
When the appender is triggered, a new LoggingEvent object is created and at least one synchronization happened which is probably 100x more expensive then the method call. Note, updating the counts field is a *synchronized* call, which is about 30x more expensive then the equals call. If don't believe it, just benchmark it and make sure you have at least two threads doing the update, so jvm doesn't elide the locks.
> Update of commons logging libraries causes EventCounter to count logging events incorrectly
> -------------------------------------------------------------------------------------------
>
> Key: HADOOP-7055
> URL: https://issues.apache.org/jira/browse/HADOOP-7055
> Project: Hadoop Common
> Issue Type: Bug
> Components: metrics
> Affects Versions: 0.21.0, 0.21.1, 0.22.0, 0.23.0
> Reporter: Jingguo Yao
> Assignee: Jingguo Yao
> Original Estimate: 0.5h
> Remaining Estimate: 0.5h
>
> Hadoop 0.20.2 uses commons logging 1.0.4. EventCounter works correctly with this version of commons logging. Hadoop 0.21.0 uses commons logging 1.1.1 which causes EventCounter to count logging events incorrectly. I have verified it with Hadoop 0.21.0. After start-up of hadoop, I checked jvmmetrics.log after several minutes. In every metrics record, "logError=0, logFatal=0, logInfo=3, logWarn=0" was shown. The following text is an example.
> jvm.metrics: hostName=jingguolin, processName=DataNode, sessionId=, gcCount=3, gcTimeMillis=31, logError=0, logFatal=0, logInfo=3, logWarn=0, maxMemoryM=888.9375, memHeapCommittedM=38.0625, memHeapUsedM=3.6539612, memNonHeapCommittedM=18.25, memNonHeapUsedM=11.335686, threadsBlocked=0, threadsNew=0, threadsRunnable=8, threadsTerminated=0, threadsTimedWaiting=6, threadsWaiting=6
> Then I stopped hadoop and replaced commons logging 1.1.1 with 1.0.4. After the re-start of hadoop, a lot of logging events showed up in jvmmetrics.log.
> I have checked the source code of Log4JLogger for both 1.0.4 (http://svn.apache.org/viewvc/commons/proper/logging/tags/LOGGING_1_0_4/src/java/org/apache/commons/logging/impl/Log4JLogger.java?view=markup) and 1.1.1 (http://svn.apache.org/viewvc/commons/proper/logging/tags/commons-logging-1.1.1/src/java/org/apache/commons/logging/impl/Log4JLogger.java?view=markup). For 1.0.4, Level instances such as Level.INFO are used to construct LoggingEvent. But for 1.1.1, Priority instances such as Priority.INFO are used to construct LoggingEvent. So 1.1.1 version's event.getLevel() always returns Priority instances. EventCounter append method's "==" check always fails between a Level instance and a Priority instance. For "logInfo=3" metrics records produced by commons logging 1.1.1., I think that these 3 logging events are produced by log4j code directly instead of through commons logging API. The following code is EventCounter's append method.
> public void append(LoggingEvent event) {
> Level level = event.getLevel();
> if (level == Level.INFO) {
> counts.incr(INFO);
> }
> else if (level == Level.WARN) {
> counts.incr(WARN);
> }
> else if (level == Level.ERROR) {
> counts.incr(ERROR);
> }
> else if (level == Level.FATAL) {
> counts.incr(FATAL);
> }
> }
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (HADOOP-7055) Update of commons logging
libraries causes EventCounter to count logging events incorrectly
Posted by "Hadoop QA (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-7055?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13021495#comment-13021495 ]
Hadoop QA commented on HADOOP-7055:
-----------------------------------
-1 overall. Here are the results of testing the latest attachment
http://issues.apache.org/jira/secure/attachment/12474763/HADOOP-7055.patch
against trunk revision 1094750.
+1 @author. The patch does not contain any @author tags.
-1 tests included. The patch doesn't appear to include any new or modified tests.
Please justify why no new tests are needed for this patch.
Also please list what manual steps were performed to verify this patch.
+1 javadoc. The javadoc tool did not generate any warning messages.
+1 javac. The applied patch does not increase the total number of javac compiler warnings.
+1 findbugs. The patch does not introduce any new Findbugs (version 1.3.9) warnings.
+1 release audit. The applied patch does not increase the total number of release audit warnings.
+1 core tests. The patch passed core unit tests.
+1 contrib tests. The patch passed contrib unit tests.
+1 system test framework. The patch passed system test framework compile.
Test results: https://hudson.apache.org/hudson/job/PreCommit-HADOOP-Build/365//testReport/
Findbugs warnings: https://hudson.apache.org/hudson/job/PreCommit-HADOOP-Build/365//artifact/trunk/build/test/findbugs/newPatchFindbugsWarnings.html
Console output: https://hudson.apache.org/hudson/job/PreCommit-HADOOP-Build/365//console
This message is automatically generated.
> Update of commons logging libraries causes EventCounter to count logging events incorrectly
> -------------------------------------------------------------------------------------------
>
> Key: HADOOP-7055
> URL: https://issues.apache.org/jira/browse/HADOOP-7055
> Project: Hadoop Common
> Issue Type: Bug
> Components: metrics
> Affects Versions: 0.21.0, 0.21.1, 0.22.0, 0.23.0
> Reporter: Jingguo Yao
> Assignee: Jingguo Yao
> Attachments: HADOOP-7055.patch
>
> Original Estimate: 0.5h
> Remaining Estimate: 0.5h
>
> Hadoop 0.20.2 uses commons logging 1.0.4. EventCounter works correctly with this version of commons logging. Hadoop 0.21.0 uses commons logging 1.1.1 which causes EventCounter to count logging events incorrectly. I have verified it with Hadoop 0.21.0. After start-up of hadoop, I checked jvmmetrics.log after several minutes. In every metrics record, "logError=0, logFatal=0, logInfo=3, logWarn=0" was shown. The following text is an example.
> jvm.metrics: hostName=jingguolin, processName=DataNode, sessionId=, gcCount=3, gcTimeMillis=31, logError=0, logFatal=0, logInfo=3, logWarn=0, maxMemoryM=888.9375, memHeapCommittedM=38.0625, memHeapUsedM=3.6539612, memNonHeapCommittedM=18.25, memNonHeapUsedM=11.335686, threadsBlocked=0, threadsNew=0, threadsRunnable=8, threadsTerminated=0, threadsTimedWaiting=6, threadsWaiting=6
> Then I stopped hadoop and replaced commons logging 1.1.1 with 1.0.4. After the re-start of hadoop, a lot of logging events showed up in jvmmetrics.log.
> I have checked the source code of Log4JLogger for both 1.0.4 (http://svn.apache.org/viewvc/commons/proper/logging/tags/LOGGING_1_0_4/src/java/org/apache/commons/logging/impl/Log4JLogger.java?view=markup) and 1.1.1 (http://svn.apache.org/viewvc/commons/proper/logging/tags/commons-logging-1.1.1/src/java/org/apache/commons/logging/impl/Log4JLogger.java?view=markup). For 1.0.4, Level instances such as Level.INFO are used to construct LoggingEvent. But for 1.1.1, Priority instances such as Priority.INFO are used to construct LoggingEvent. So 1.1.1 version's event.getLevel() always returns Priority instances. EventCounter append method's "==" check always fails between a Level instance and a Priority instance. For "logInfo=3" metrics records produced by commons logging 1.1.1., I think that these 3 logging events are produced by log4j code directly instead of through commons logging API. The following code is EventCounter's append method.
> public void append(LoggingEvent event) {
> Level level = event.getLevel();
> if (level == Level.INFO) {
> counts.incr(INFO);
> }
> else if (level == Level.WARN) {
> counts.incr(WARN);
> }
> else if (level == Level.ERROR) {
> counts.incr(ERROR);
> }
> else if (level == Level.FATAL) {
> counts.incr(FATAL);
> }
> }
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] Commented: (HADOOP-7055) Update of commons logging libraries
causes EventCounter to count logging events incorrectly
Posted by "Luke Lu (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-7055?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12971129#action_12971129 ]
Luke Lu commented on HADOOP-7055:
---------------------------------
This looks like a regression in the common log 1.1.1 implementation (passes in Priority.* instances instead of recommended Level.*) to me. Priority.* are deprecated and they should just use Level.* everywhere.
In any case, using equals is a reasonable fix that works with all cases and the performance overhead is negligible compared with actual logging by time the appender is triggered.
> Update of commons logging libraries causes EventCounter to count logging events incorrectly
> -------------------------------------------------------------------------------------------
>
> Key: HADOOP-7055
> URL: https://issues.apache.org/jira/browse/HADOOP-7055
> Project: Hadoop Common
> Issue Type: Bug
> Components: metrics
> Affects Versions: 0.21.0, 0.21.1, 0.22.0, 0.23.0
> Reporter: Jingguo Yao
> Fix For: 0.21.1, 0.22.0, 0.23.0
>
> Original Estimate: 0.5h
> Remaining Estimate: 0.5h
>
> Hadoop 0.20.2 uses commons logging 1.0.4. EventCounter works correctly with this version of commons logging. Hadoop 0.21.0 uses commons logging 1.1.1 which causes EventCounter to count logging events incorrectly. I have verified it with Hadoop 0.21.0. After start-up of hadoop, I checked jvmmetrics.log after several minutes. In every metrics record, "logError=0, logFatal=0, logInfo=3, logWarn=0" was shown. The following text is an example.
> jvm.metrics: hostName=jingguolin, processName=DataNode, sessionId=, gcCount=3, gcTimeMillis=31, logError=0, logFatal=0, logInfo=3, logWarn=0, maxMemoryM=888.9375, memHeapCommittedM=38.0625, memHeapUsedM=3.6539612, memNonHeapCommittedM=18.25, memNonHeapUsedM=11.335686, threadsBlocked=0, threadsNew=0, threadsRunnable=8, threadsTerminated=0, threadsTimedWaiting=6, threadsWaiting=6
> Then I stopped hadoop and replaced commons logging 1.1.1 with 1.0.4. After the re-start of hadoop, a lot of logging events showed up in jvmmetrics.log.
> I have checked the source code of Log4JLogger for both 1.0.4 (http://svn.apache.org/viewvc/commons/proper/logging/tags/LOGGING_1_0_4/src/java/org/apache/commons/logging/impl/Log4JLogger.java?view=markup) and 1.1.1 (http://svn.apache.org/viewvc/commons/proper/logging/tags/commons-logging-1.1.1/src/java/org/apache/commons/logging/impl/Log4JLogger.java?view=markup). For 1.0.4, Level instances such as Level.INFO are used to construct LoggingEvent. But for 1.1.1, Priority instances such as Priority.INFO are used to construct LoggingEvent. So 1.1.1 version's event.getLevel() always returns Priority instances. EventCounter append method's "==" check always fails between a Level instance and a Priority instance. For "logInfo=3" metrics records produced by commons logging 1.1.1., I think that these 3 logging events are produced by log4j code directly instead of through commons logging API. The following code is EventCounter's append method.
> public void append(LoggingEvent event) {
> Level level = event.getLevel();
> if (level == Level.INFO) {
> counts.incr(INFO);
> }
> else if (level == Level.WARN) {
> counts.incr(WARN);
> }
> else if (level == Level.ERROR) {
> counts.incr(ERROR);
> }
> else if (level == Level.FATAL) {
> counts.incr(FATAL);
> }
> }
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] [Updated] (HADOOP-7055) Update of commons logging libraries
causes EventCounter to count logging events incorrectly
Posted by "Luke Lu (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-7055?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Luke Lu updated HADOOP-7055:
----------------------------
Resolution: Fixed
Fix Version/s: 0.23.0
Hadoop Flags: [Reviewed]
Status: Resolved (was: Patch Available)
> Update of commons logging libraries causes EventCounter to count logging events incorrectly
> -------------------------------------------------------------------------------------------
>
> Key: HADOOP-7055
> URL: https://issues.apache.org/jira/browse/HADOOP-7055
> Project: Hadoop Common
> Issue Type: Bug
> Components: metrics
> Affects Versions: 0.21.0, 0.21.1, 0.22.0, 0.23.0
> Reporter: Jingguo Yao
> Assignee: Jingguo Yao
> Fix For: 0.23.0
>
> Attachments: HADOOP-7055.patch
>
> Original Estimate: 0.5h
> Remaining Estimate: 0.5h
>
> Hadoop 0.20.2 uses commons logging 1.0.4. EventCounter works correctly with this version of commons logging. Hadoop 0.21.0 uses commons logging 1.1.1 which causes EventCounter to count logging events incorrectly. I have verified it with Hadoop 0.21.0. After start-up of hadoop, I checked jvmmetrics.log after several minutes. In every metrics record, "logError=0, logFatal=0, logInfo=3, logWarn=0" was shown. The following text is an example.
> jvm.metrics: hostName=jingguolin, processName=DataNode, sessionId=, gcCount=3, gcTimeMillis=31, logError=0, logFatal=0, logInfo=3, logWarn=0, maxMemoryM=888.9375, memHeapCommittedM=38.0625, memHeapUsedM=3.6539612, memNonHeapCommittedM=18.25, memNonHeapUsedM=11.335686, threadsBlocked=0, threadsNew=0, threadsRunnable=8, threadsTerminated=0, threadsTimedWaiting=6, threadsWaiting=6
> Then I stopped hadoop and replaced commons logging 1.1.1 with 1.0.4. After the re-start of hadoop, a lot of logging events showed up in jvmmetrics.log.
> I have checked the source code of Log4JLogger for both 1.0.4 (http://svn.apache.org/viewvc/commons/proper/logging/tags/LOGGING_1_0_4/src/java/org/apache/commons/logging/impl/Log4JLogger.java?view=markup) and 1.1.1 (http://svn.apache.org/viewvc/commons/proper/logging/tags/commons-logging-1.1.1/src/java/org/apache/commons/logging/impl/Log4JLogger.java?view=markup). For 1.0.4, Level instances such as Level.INFO are used to construct LoggingEvent. But for 1.1.1, Priority instances such as Priority.INFO are used to construct LoggingEvent. So 1.1.1 version's event.getLevel() always returns Priority instances. EventCounter append method's "==" check always fails between a Level instance and a Priority instance. For "logInfo=3" metrics records produced by commons logging 1.1.1., I think that these 3 logging events are produced by log4j code directly instead of through commons logging API. The following code is EventCounter's append method.
> public void append(LoggingEvent event) {
> Level level = event.getLevel();
> if (level == Level.INFO) {
> counts.incr(INFO);
> }
> else if (level == Level.WARN) {
> counts.incr(WARN);
> }
> else if (level == Level.ERROR) {
> counts.incr(ERROR);
> }
> else if (level == Level.FATAL) {
> counts.incr(FATAL);
> }
> }
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] Commented: (HADOOP-7055) Update of commons logging libraries
causes EventCounter to count logging events incorrectly
Posted by "Jingguo Yao (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-7055?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12970582#action_12970582 ]
Jingguo Yao commented on HADOOP-7055:
-------------------------------------
Yes. But we need to make sure that no log4j API is used directly for logging. log4j API uses Level instances such as Level.INFO to create LoggingEvent. Otherwise, such kind of logging will not be taken into account by EventCounter. And Level instances such as Priority.INFO are deprecated in log4j.
Another option is to use equals instead of ==. Priority has the following equals method.
/**
Two priorities are equal if their level fields are equal.
@since 1.2
*/
public
boolean equals(Object o) {
if(o instanceof Priority) {
Priority r = (Priority) o;
return (this.level == r.level);
} else {
return false;
}
}
Level does not define equals method by itself. So it inherits this method. This method will return true if level fields (int type) are equal. It will return true for things like Level.INFO and Priority.INFO. So LoggingEvent created by both commons logging API and log4j API will be taken into account for this option. The downside for this option is that equals check is slow than == check.
And there are some mistakes in my original comment. Let me correct them here.
For 1.0.4, Level instances such as Level.INFO are used to construct LoggingEvent. But for 1.1.1, Level instances such as Priority.INFO are used to construct LoggingEvent. Level.INFO and Priority.INFO are different Level instances. 1.1.1 version's event.getLevel() always returns Level instances from Priority. So EventCounter append method's "==" check always fails between different Level instances from Level and Priority.
public class Priority {
//...
final static public Priority INFO = new Level(INFO_INT, "INFO", 6);
//...
}
public class Level extends Priority implements Serializable {
//...
final static public Level INFO = new Level(INFO_INT, "INFO", 6);
//...
}
> Update of commons logging libraries causes EventCounter to count logging events incorrectly
> -------------------------------------------------------------------------------------------
>
> Key: HADOOP-7055
> URL: https://issues.apache.org/jira/browse/HADOOP-7055
> Project: Hadoop Common
> Issue Type: Bug
> Components: metrics
> Affects Versions: 0.21.0, 0.21.1, 0.22.0, 0.23.0
> Reporter: Jingguo Yao
> Fix For: 0.21.1, 0.22.0, 0.23.0
>
> Original Estimate: 0.5h
> Remaining Estimate: 0.5h
>
> Hadoop 0.20.2 uses commons logging 1.0.4. EventCounter works correctly with this version of commons logging. Hadoop 0.21.0 uses commons logging 1.1.1 which causes EventCounter to count logging events incorrectly. I have verified it with Hadoop 0.21.0. After start-up of hadoop, I checked jvmmetrics.log after several minutes. In every metrics record, "logError=0, logFatal=0, logInfo=3, logWarn=0" was shown. The following text is an example.
> jvm.metrics: hostName=jingguolin, processName=DataNode, sessionId=, gcCount=3, gcTimeMillis=31, logError=0, logFatal=0, logInfo=3, logWarn=0, maxMemoryM=888.9375, memHeapCommittedM=38.0625, memHeapUsedM=3.6539612, memNonHeapCommittedM=18.25, memNonHeapUsedM=11.335686, threadsBlocked=0, threadsNew=0, threadsRunnable=8, threadsTerminated=0, threadsTimedWaiting=6, threadsWaiting=6
> Then I stopped hadoop and replaced commons logging 1.1.1 with 1.0.4. After the re-start of hadoop, a lot of logging events showed up in jvmmetrics.log.
> I have checked the source code of Log4JLogger for both 1.0.4 (http://svn.apache.org/viewvc/commons/proper/logging/tags/LOGGING_1_0_4/src/java/org/apache/commons/logging/impl/Log4JLogger.java?view=markup) and 1.1.1 (http://svn.apache.org/viewvc/commons/proper/logging/tags/commons-logging-1.1.1/src/java/org/apache/commons/logging/impl/Log4JLogger.java?view=markup). For 1.0.4, Level instances such as Level.INFO are used to construct LoggingEvent. But for 1.1.1, Priority instances such as Priority.INFO are used to construct LoggingEvent. So 1.1.1 version's event.getLevel() always returns Priority instances. EventCounter append method's "==" check always fails between a Level instance and a Priority instance. For "logInfo=3" metrics records produced by commons logging 1.1.1., I think that these 3 logging events are produced by log4j code directly instead of through commons logging API. The following code is EventCounter's append method.
> public void append(LoggingEvent event) {
> Level level = event.getLevel();
> if (level == Level.INFO) {
> counts.incr(INFO);
> }
> else if (level == Level.WARN) {
> counts.incr(WARN);
> }
> else if (level == Level.ERROR) {
> counts.incr(ERROR);
> }
> else if (level == Level.FATAL) {
> counts.incr(FATAL);
> }
> }
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.