[
https://issues.apache.org/jira/browse/KAFKA-1350?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13955520#comment-13955520
]
Guozhang Wang edited comment on KAFKA-1350 at 3/31/14 7:51 PM:
---------------------------------------------------------------
I think if the corresponding level is not triggered, it should not invoke the
string.format function. But if we use the getLogger() and use that instance
function, then the string.format call will be triggered no matter what. This is
a small test I did:
{quote}
object TestMisc extends Logging {
def main(args: Array[String]) {
var count = 0
info("INFO Printed %d".format({count+=1;count}))
debug("DEBUG Printed %d".format({count+=1;count}))
println("Final Count %d".format(count))
val dummyLogger = Logger.getLogger(KafkaController.stateChangeLogger)
count = 0
dummyLogger.info("INFO Printed %d".format({count+=1;count}))
dummyLogger.debug("DEBUG Printed %d".format({count+=1;count}))
println("Final Count %d".format(count))
}
}
{quote}
with log4j at INFO the output:
{quote}
[2014-03-31 12:47:34,207] INFO INFO Printed 1 (kafka.TestMisc$)
Final Count 1
[2014-03-31 12:47:34,213] INFO INFO Printed 1 (state.change.logger)
Final Count 2
{quote}
with log4j at DEBUG the output:
{quote}
[2014-03-31 12:50:54,211] INFO INFO Printed 1 (kafka.TestMisc$)
[2014-03-31 12:50:54,213] DEBUG DEBUG Printed 2 (kafka.TestMisc$)
Final Count 2
[2014-03-31 12:50:54,219] INFO INFO Printed 1 (state.change.logger)
[2014-03-31 12:50:54,219] DEBUG DEBUG Printed 2 (state.change.logger)
Final Count 2
{quote}
was (Author: guozhang):
I think if the corresponding level is not triggered, it should not invoke the
string.format function. This is a small test I did:
----
object TestMisc extends Logging {
def main(args: Array[String]) {
var count = 0
info("INFO Printed %d".format({count+=1;count}))
debug("DEBUG Printed %d".format({count+=1;count}))
println("Final Count %d".format(count))
}
}
----
with log4j at INFO the output:
----
[2014-03-31 11:47:07,243] INFO INFO Printed 1 (kafka.TestMisc$)
Final Count 1
----
with log4j at DEBUG the output:
----
[2014-03-31 11:47:20,956] INFO INFO Printed 1 (kafka.TestMisc$)
[2014-03-31 11:47:20,958] DEBUG DEBUG Printed 2 (kafka.TestMisc$)
Final Count 2
----
> Fix excessive state change logging
> ----------------------------------
>
> Key: KAFKA-1350
> URL: https://issues.apache.org/jira/browse/KAFKA-1350
> Project: Kafka
> Issue Type: Bug
> Affects Versions: 0.8.1
> Reporter: Joel Koshy
> Assignee: Neha Narkhede
> Priority: Blocker
> Fix For: 0.8.1.1
>
> Attachments: KAFKA-1350.patch, KAFKA-1350_2014-03-29_23:28:07.patch
>
>
> I can provide steps to reproduce this issue. The state change logger needs
> to be guarded (to check if trace logging is turned on or not).
> The delete topic patch significantly increased the amount of logging that we
> do both on the controller. This results in higher latencies in state
> transitions and can slow down the controller (as well as the broker). This
> slow-down was how we ran into KAFKA-1342.
--
This message was sent by Atlassian JIRA
(v6.2#6252)
