kafka-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Dale" <li...@debndale.com>
Subject 0.9.0.0 Log4j appender slow startup
Date Sun, 05 Nov 2017 10:13:23 GMT
I am using the 0.9.0.0 log4j appender for Kafka because I have a lot of apps dependent on log4j
1.2.x that cannot be upgraded to use newer versions of log4j.   It appears that the appender
has become part of log4j code in later versions of both tools.

When I start my test app, the first message takes an exact and consistent 60 seconds plus
a couple milliseconds to go out.  The second message takes right around 200 milliseconds,
and all the messages after that take a couple of milliseconds.  The timing from message 1
to 2 could be tolerated but the 60 seconds will never work since the production use case app
would typically run for 20 to 30 seconds.

For testing, I brought the appender code into my project and added some additional console
messages so I could see what is going on.  Here’s a snippet of the console output:

********START LOG SNIPPET***********
G:\kafkademoworkspace\testlog4jgenerator>java -Dlog4j.debug -Dlog4j.configuration=file:///g:\kafkademoworkspace\testlog4jgenerator\log4j.properties
-cp .\;G:\kafkademoworkspace\testlog4jgenerator\target\testlog4jgenerator.jar;g:\kafkademoworkspace\testlog4jgenerator\target\libs\log4j-1.2.17.jar;g:\kafkademoworkspace\testlog4jgenerator\target\libs\*;g:\kafkademoworkspace\testlog4jgenerator\target\libs\kafka-clients-0.9.0.0.jar
com.mydomainname.messaging.testlog4jgenerator.LogGenerator
log4j: Using URL [file:/g:/kafkademoworkspace/testlog4jgenerator/log4j.properties] for automatic
log4j configuration.
log4j: Reading configuration from URL file:/g:/kafkademoworkspace/testlog4jgenerator/log4j.properties
log4j: Parsing for [root] with value=[DEBUG,file,KAFKA].
log4j: Level token is [DEBUG].
log4j: Category root set to DEBUG
log4j: Parsing appender named "file".
log4j: Parsing layout options for "file".
log4j: Setting property [conversionPattern] to [%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p %c{1}:%L
- %m%n].
log4j: End of parsing for "file".
log4j: Setting property [file] to [/apps/logs/logtest.log].
log4j: Setting property [maxBackupIndex] to [10].
log4j: Setting property [maxFileSize] to [10MB].
log4j: setFile called: /apps/logs/logtest.log, true
log4j: setFile ended
log4j: Parsed "file" options.
log4j: Parsing appender named "KAFKA".
log4j: Parsing layout options for "KAFKA".
log4j: Setting property [conversionPattern] to [%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p %c{1}:%L
- %m%n].
log4j: End of parsing for "KAFKA".
log4j: Setting property [compressionType] to [none].
log4j: Setting property [topic] to [test].
log4j: Setting property [brokerList] to [localhost:9092].
log4j: Setting property [syncSend] to [false].
DPLOG: 2017-11-05T09:56:16.072Z - in Producer - creating new KafkaProducer
log4j: Kafka producer connected to localhost:9092
log4j: Logging for topic: test
log4j: Parsed "KAFKA" options.
log4j: Finished configuring.
****************************************************************
DPLOG: 2017-11-05T09:56:16.338Z - append START
DPLOG: 2017-11-05T09:56:16.339Z - after subAppend.  Message is: 2017-11-05 03:56:16,333 DEBUG
Sender:123 - Starting Kafka producer I/O thread.

log4j: [Sun Nov 05 03:56:16 CST 2017]2017-11-05 03:56:16,333 DEBUG Sender:123 - Starting Kafka
producer I/O thread.

DPLOG: 2017-11-05T09:56:16.342Z - getting ready to send to producer.
DPLOG: 2017-11-05T09:57:16.347Z - after send to producer.
DPLOG: 2017-11-05T09:57:16.348Z - append END
****************************************************************
DPLOG: 2017-11-05T09:57:16.352Z - append START
DPLOG: 2017-11-05T09:57:16.353Z - after subAppend.  Message is: 2017-11-05 03:56:16,338 INFO
 root:36 - Logging message: x=0

log4j: [Sun Nov 05 03:56:16 CST 2017]2017-11-05 03:56:16,338 INFO  root:36 - Logging message:
x=0

DPLOG: 2017-11-05T09:57:16.361Z - getting ready to send to producer.
DPLOG: 2017-11-05T09:57:16.526Z - after send to producer.
DPLOG: 2017-11-05T09:57:16.526Z - append END
****************************************************************
DPLOG: 2017-11-05T09:57:16.527Z - append START
DPLOG: 2017-11-05T09:57:16.528Z - after subAppend.  Message is: 2017-11-05 03:57:16,527 INFO
 root:36 - Logging message: x=1

log4j: [Sun Nov 05 03:57:16 CST 2017]2017-11-05 03:57:16,527 INFO  root:36 - Logging message:
x=1

DPLOG: 2017-11-05T09:57:16.529Z - getting ready to send to producer.
DPLOG: 2017-11-05T09:57:16.530Z - after send to producer.
DPLOG: 2017-11-05T09:57:16.530Z - append END
****************************************************************
DPLOG: 2017-11-05T09:57:16.531Z - append START
DPLOG: 2017-11-05T09:57:16.531Z - after subAppend.  Message is: 2017-11-05 03:57:16,531 INFO
 root:36 - Logging message: x=2

log4j: [Sun Nov 05 03:57:16 CST 2017]2017-11-05 03:57:16,531 INFO  root:36 - Logging message:
x=2

DPLOG: 2017-11-05T09:57:16.532Z - getting ready to send to producer.
DPLOG: 2017-11-05T09:57:16.533Z - after send to producer.
DPLOG: 2017-11-05T09:57:16.535Z - append END
****************************************************************
DPLOG: 2017-11-05T09:57:16.536Z - append START
DPLOG: 2017-11-05T09:57:16.536Z - after subAppend.  Message is: 2017-11-05 03:57:16,536 INFO
 root:36 - Logging message: x=3

log4j: [Sun Nov 05 03:57:16 CST 2017]2017-11-05 03:57:16,536 INFO  root:36 - Logging message:
x=3

DPLOG: 2017-11-05T09:57:16.538Z - getting ready to send to producer.
DPLOG: 2017-11-05T09:57:16.538Z - after send to producer.
DPLOG: 2017-11-05T09:57:16.538Z - append END
****************************************************************
DPLOG: 2017-11-05T09:57:16.539Z - append START
DPLOG: 2017-11-05T09:57:16.540Z - after subAppend.  Message is: 2017-11-05 03:57:16,539 INFO
 root:36 - Logging message: x=4

log4j: [Sun Nov 05 03:57:16 CST 2017]2017-11-05 03:57:16,539 INFO  root:36 - Logging message:
x=4

DPLOG: 2017-11-05T09:57:16.541Z - getting ready to send to producer.
DPLOG: 2017-11-05T09:57:16.542Z - after send to producer.
DPLOG: 2017-11-05T09:57:16.542Z - append END
****************************************************************
********END LOG SNIPPET***********



The code, modified for logging, for sending to the producer is:
********START CODE SNIPPET***********
System.out.println("DPLOG: " + Instant.now().toString() + " - getting ready to send to producer.");
Future<RecordMetadata> response = producer.send(new ProducerRecord<byte[], byte[]>(topic,
message.getBytes()));
System.out.println("DPLOG: " + Instant.now().toString() + " - after send to producer.");
********END CODE SNIPPET***********

I have not been able to find any timeout of 60 seconds (60000 ms) anywhere but it is clear
that something is happening that is exactly 60 seconds at the start of the run.  Whatever
the timeout is, it is not breaking because the messages are sent to kafka.  I’ve searched
the KafkaProducer code and kafka server configuration looking for any 60 second timeout reference
and cannot find one.  In what few examples I could find online of log data using the producer,
I see the Starting kafka producer I/O thread with the next log entries in the same second
so the 60 second delay I am seeing does not always appear to be there but it’s always there
in my case.  Any ideas what could be causing it and/or how I can get rid of it?

Thanks,

Dale

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message