jbweeks
commented
9 years ago Logs with streams=6:
[WARN] [07/25/2015 01:31:51.784] [Archival-akka.actor.default-dispatcher-4] [akka://Archival/user/KafkaLogProcessor-prod.log.general-128922017278319960/prod.log.general.connector8922017278628763] state=WaitingToSendBatch msg=StateTimeout outstanding=4 streams=6 [WARN] [07/25/2015 01:31:52.175] [Archival-akka.actor.default-dispatcher-16] [akka://Archival/user/KafkaLogProcessor-dev.log.general-18921902258509568/dev.log.general.connector8921902259063803] state=WaitingToSendBatch msg=StateTimeout outstanding=1268 streams=6 [WARN] [07/25/2015 01:31:52.804] [Archival-akka.actor.default-dispatcher-44] [akka://Archival/user/KafkaLogProcessor-prod.log.general-128922017278319960/prod.log.general.connector8922017278628763] state=WaitingToSendBatch msg=StateTimeout outstanding=4 streams=6 [WARN] [07/25/2015 01:31:53.184] [Archival-akka.actor.default-dispatcher-38] [akka://Archival/user/KafkaLogProcessor-dev.log.general-18921902258509568/dev.log.general.connector8921902259063803] state=WaitingToSendBatch msg=StateTimeout outstanding=1268 streams=6 [WARN] [07/25/2015 01:31:53.841] [Archival-akka.actor.default-dispatcher-21] [akka://Archival/user/KafkaLogProcessor-prod.log.general-128922017278319960/prod.log.general.connector8922017278628763] state=WaitingToSendBatch msg=StateTimeout outstanding=4 streams=6 [WARN] [07/25/2015 01:31:54.209] [Archival-akka.actor.default-dispatcher-41] [akka://Archival/user/KafkaLogProcessor-dev.log.general-18921902258509568/dev.log.general.connector8921902259063803] state=WaitingToSendBatch msg=StateTimeout outstanding=1267 streams=6 2015-07-25T01:31:54.770+0000 INFO Archival-akka.actor.default-dispatcher-52 com.whitepages.ait.archival.Archival Finished dispatch/ack batch of size: 39996 to LogWriters in 25 millis from actor: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128922017278319960#-1828359622] 2015-07-25T01:31:54.770+0000 INFO Archival-akka.actor.default-dispatcher-52 com.whitepages.logging.LogProcessor In prod.log.general LogProcessor, got Ack from: Actor[akka://Archival/deadLetters] with count: 39996; status: 39996 / 39996} 2015-07-25T01:31:54.770+0000 INFO Archival-akka.actor.default-dispatcher-52 com.whitepages.logging.LogProcessor In processAck from Actor[akka://Archival/deadLetters], sending BatchProcessed to: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128922017278319960/prod.log.general.connector8922017278628763#-1479910542] 2015-07-25T01:31:56.736+0000 WARN Archival-akka.actor.default-dispatcher-21 c.whitepages.ait.archival.LogWriter$ LogWriter not yet registered service: zeus, category: errors, host: lbi3.prod.pages, adding... 2015-07-25T01:31:56.749+0000 INFO Archival-akka.actor.default-dispatcher-21 com.whitepages.ait.archival.Archival Finished dispatch/ack batch of size: 40000 to LogWriters in 24 millis from actor: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128922017278319960#-1828359622] 2015-07-25T01:31:56.749+0000 INFO Archival-akka.actor.default-dispatcher-21 com.whitepages.logging.LogProcessor In prod.log.general LogProcessor, got Ack from: Actor[akka://Archival/deadLetters] with count: 40000; status: 40000 / 40000} 2015-07-25T01:31:56.750+0000 INFO Archival-akka.actor.default-dispatcher-21 com.whitepages.logging.LogProcessor In processAck from Actor[akka://Archival/deadLetters], sending BatchProcessed to: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128922017278319960/prod.log.general.connector8922017278628763#-1479910542] 2015-07-25T01:31:56.782+0000 INFO Archival-akka.actor.default-dispatcher-21 c.whitepages.ait.archival.LogWriter Target file, total path: Path(/mnt/local/data/2015/07/25/zeus/errors/lbi3.prod.pages.h01.m31.s56.gz) doesn't exist, creating... [WARN] [07/25/2015 01:31:57.134] [Archival-akka.actor.default-dispatcher-4] [akka://Archival/user/KafkaLogProcessor-dev.log.general-18921902258509568/dev.log.general.connector8921902259063803] state=WaitingToSendBatch msg=StateTimeout outstanding=1262 streams=6 [WARN] [07/25/2015 01:31:57.985] [Archival-akka.actor.default-dispatcher-14] [akka://Archival/user/KafkaLogProcessor-prod.log.general-128922017278319960/prod.log.general.connector8922017278628763] state=WaitingToSendBatch msg=StateTimeout outstanding=2 streams=6 [WARN] [07/25/2015 01:31:58.204] [Archival-akka.actor.default-dispatcher-26] [akka://Archival/user/KafkaLogProcessor-dev.log.general-18921902258509568/dev.log.general.connector8921902259063803] state=WaitingToSendBatch msg=StateTimeout outstanding=1261 streams=6 [WARN] [07/25/2015 01:31:59.004] [Archival-akka.actor.default-dispatcher-12] [akka://Archival/user/KafkaLogProcessor-prod.log.general-128922017278319960/prod.log.general.connector8922017278628763] state=WaitingToSendBatch msg=StateTimeout outstanding=2 streams=6 [WARN] [07/25/2015 01:32:00.029] [Archival-akka.actor.default-dispatcher-20] [akka://Archival/user/KafkaLogProcessor-prod.log.general-128922017278319960/prod.log.general.connector8922017278628763] state=WaitingToSendBatch msg=StateTimeout outstanding=2 streams=6 [WARN] [07/25/2015 01:32:00.174] [Archival-akka.actor.default-dispatcher-8] [akka://Archival/user/KafkaLogProcessor-dev.log.general-18921902258509568/dev.log.general.connector8921902259063803] state=WaitingToSendBatch msg=StateTimeout outstanding=1256 streams=6 2015-07-25T01:32:00.985+0000 INFO Archival-akka.actor.default-dispatcher-40 com.whitepages.ait.archival.Archival Finished dispatch/ack batch of size: 39998 to LogWriters in 26 millis from actor: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128922017278319960#-1828359622] 2015-07-25T01:32:00.986+0000 INFO Archival-akka.actor.default-dispatcher-40 com.whitepages.logging.LogProcessor In prod.log.general LogProcessor, got Ack from: Actor[akka://Archival/deadLetters] with count: 39998; status: 39998 / 39998} 2015-07-25T01:32:00.986+0000 INFO Archival-akka.actor.default-dispatcher-40 com.whitepages.logging.LogProcessor In processAck from Actor[akka://Archival/deadLetters], sending BatchProcessed to: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128922017278319960/prod.log.general.connector8922017278628763#-1479910542] 2015-07-25T01:32:01.325+0000 INFO Archival-akka.actor.default-dispatcher-40 com.whitepages.ait.archival.Archival Finished dispatch/ack batch of size: 40000 to LogWriters in 31 millis from actor: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128922017278319960#-1828359622] 2015-07-25T01:32:01.325+0000 INFO Archival-akka.actor.default-dispatcher-40 com.whitepages.logging.LogProcessor In prod.log.general LogProcessor, got Ack from: Actor[akka://Archival/deadLetters] with count: 40000; status: 40000 / 40000} 2015-07-25T01:32:01.325+0000 INFO Archival-akka.actor.default-dispatcher-40 com.whitepages.logging.LogProcessor In processAck from Actor[akka://Archival/deadLetters], sending BatchProcessed to: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128922017278319960/prod.log.general.connector8922017278628763#-1479910542] [WARN] [07/25/2015 01:32:02.195] [Archival-akka.actor.default-dispatcher-20] [akka://Archival/user/KafkaLogProcessor-dev.log.general-18921902258509568/dev.log.general.connector8921902259063803] state=WaitingToSendBatch msg=StateTimeout outstanding=1255 streams=6 [WARN] [07/25/2015 01:32:02.584] [Archival-akka.actor.default-dispatcher-26] [akka://Archival/user/KafkaLogProcessor-prod.log.general-128922017278319960/prod.log.general.connector8922017278628763] state=WaitingToSendBatch msg=StateTimeout outstanding=3 streams=6 [WARN] [07/25/2015 01:32:03.605] [Archival-akka.actor.default-dispatcher-46] [akka://Archival/user/KafkaLogProcessor-prod.log.general-128922017278319960/prod.log.general.connector8922017278628763] state=WaitingToSendBatch msg=StateTimeout outstanding=3 streams=6 [WARN] [07/25/2015 01:32:04.175] [Archival-akka.actor.default-dispatcher-49] [akka://Archival/user/KafkaLogProcessor-dev.log.general-18921902258509568/dev.log.general.connector8921902259063803] state=WaitingToSendBatch msg=StateTimeout outstanding=1250 streams=6 [WARN] [07/25/2015 01:32:04.625] [Archival-akka.actor.default-dispatcher-26] [akka://Archival/user/KafkaLogProcessor-prod.log.general-128922017278319960/prod.log.general.connector8922017278628763] state=WaitingToSendBatch msg=StateTimeout outstanding=3 streams=6 2015-07-25T01:32:05.564+0000 INFO Archival-akka.actor.default-dispatcher-60 com.whitepages.ait.archival.Archival Finished dispatch/ack batch of size: 39997 to LogWriters in 27 millis from actor: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128922017278319960#-1828359622] 2015-07-25T01:32:05.564+0000 INFO Archival-akka.actor.default-dispatcher-60 com.whitepages.logging.LogProcessor In prod.log.general LogProcessor, got Ack from: Actor[akka://Archival/deadLetters] with count: 39997; status: 39997 / 39997} 2015-07-25T01:32:05.564+0000 INFO Archival-akka.actor.default-dispatcher-60 com.whitepages.logging.LogProcessor In processAck from Actor[akka://Archival/deadLetters], sending BatchProcessed to: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128922017278319960/prod.log.general.connector8922017278628763#-1479910542]
sclasen
Hi Scott,
We are running 0.1.0 on a large 48 core box, and the service keeps choking in BatchConnectorFSM in the WaitingToSendBatch state, no matter what the value of the BatchTimeout. Furthermore, when I increase the number of streams past a certain state (e.g. 16), the system spends all its time blocked on the LinkedBlockingQueue (even though the topic has 48 partitions):
"Archival-akka.actor.default-dispatcher-49" prio=10 tid=0x00007f0df4003800 nid=0x9e65 waiting on condition [0x00007f0aa25e4000] java.lang.Thread.State: TIMED_WAITING (parking) at sun.misc.Unsafe.park(Native Method)
The ConsumerGroup is subscribing to some topics with 48 partitions, and they are full of billions of messages for each partition. I have been forced to only run a couple streams in order to make progress, because as the stream count increases, throughput decreases.
I haven't been able to figure out why the progress is choking in WaitingToSendBatch. The server has 10GigE, and isn't limited by any of: CPU, disk, network, but rather a locking/concurrency issue.
More logs of the main topic here:
2015-07-25T00:54:45.920+0000 INFO Archival-akka.actor.default-dispatcher-55 com.whitepages.ait.archival.Archival Finished dispatch/ack batch of size: 39999 to LogWriters in 59 millis from actor: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306#-1505022696] 2015-07-25T00:54:45.920+0000 INFO Archival-akka.actor.default-dispatcher-55 com.whitepages.logging.LogProcessor In prod.log.general LogProcessor, got Ack from: Actor[akka://Archival/deadLetters] with count: 39999; status: 39999 / 39999} 2015-07-25T00:54:45.920+0000 INFO Archival-akka.actor.default-dispatcher-55 com.whitepages.logging.LogProcessor In processAck from Actor[akka://Archival/deadLetters], sending BatchProcessed to: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630#-1171870480] 2015-07-25T00:54:46.435+0000 INFO Archival-akka.actor.default-dispatcher-59 com.whitepages.ait.archival.Archival Finished dispatch/ack batch of size: 40000 to LogWriters in 43 millis from actor: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306#-1505022696] 2015-07-25T00:54:46.435+0000 INFO Archival-akka.actor.default-dispatcher-59 com.whitepages.logging.LogProcessor In prod.log.general LogProcessor, got Ack from: Actor[akka://Archival/deadLetters] with count: 40000; status: 40000 / 40000} 2015-07-25T00:54:46.435+0000 INFO Archival-akka.actor.default-dispatcher-59 com.whitepages.logging.LogProcessor In processAck from Actor[akka://Archival/deadLetters], sending BatchProcessed to: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630#-1171870480] [WARN] [07/25/2015 00:54:47.892] [Archival-akka.actor.default-dispatcher-46] [akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630] state=WaitingToSendBatch msg=StateTimeout outstanding=1 streams=2 [WARN] [07/25/2015 00:54:48.902] [Archival-akka.actor.default-dispatcher-64] [akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630] state=WaitingToSendBatch msg=StateTimeout outstanding=1 streams=2 [WARN] [07/25/2015 00:54:49.922] [Archival-akka.actor.default-dispatcher-37] [akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630] state=WaitingToSendBatch msg=StateTimeout outstanding=1 streams=2 2015-07-25T00:54:50.782+0000 INFO Archival-akka.actor.default-dispatcher-21 com.whitepages.ait.archival.Archival Finished dispatch/ack batch of size: 39999 to LogWriters in 28 millis from actor: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306#-1505022696] 2015-07-25T00:54:50.782+0000 INFO Archival-akka.actor.default-dispatcher-21 com.whitepages.logging.LogProcessor In prod.log.general LogProcessor, got Ack from: Actor[akka://Archival/deadLetters] with count: 39999; status: 39999 / 39999} 2015-07-25T00:54:50.782+0000 INFO Archival-akka.actor.default-dispatcher-21 com.whitepages.logging.LogProcessor In processAck from Actor[akka://Archival/deadLetters], sending BatchProcessed to: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630#-1171870480] 2015-07-25T00:54:51.263+0000 INFO Archival-akka.actor.default-dispatcher-48 com.whitepages.ait.archival.Archival Finished dispatch/ack batch of size: 40000 to LogWriters in 46 millis from actor: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306#-1505022696] 2015-07-25T00:54:51.263+0000 INFO Archival-akka.actor.default-dispatcher-48 com.whitepages.logging.LogProcessor In prod.log.general LogProcessor, got Ack from: Actor[akka://Archival/deadLetters] with count: 40000; status: 40000 / 40000} 2015-07-25T00:54:51.263+0000 INFO Archival-akka.actor.default-dispatcher-48 com.whitepages.logging.LogProcessor In processAck from Actor[akka://Archival/deadLetters], sending BatchProcessed to: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630#-1171870480] 2015-07-25T00:54:51.751+0000 INFO Archival-akka.actor.default-dispatcher-49 com.whitepages.ait.archival.Archival Finished dispatch/ack batch of size: 40000 to LogWriters in 55 millis from actor: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306#-1505022696] 2015-07-25T00:54:51.752+0000 INFO Archival-akka.actor.default-dispatcher-49 com.whitepages.logging.LogProcessor In prod.log.general LogProcessor, got Ack from: Actor[akka://Archival/deadLetters] with count: 40000; status: 40000 / 40000} 2015-07-25T00:54:51.752+0000 INFO Archival-akka.actor.default-dispatcher-49 com.whitepages.logging.LogProcessor In processAck from Actor[akka://Archival/deadLetters], sending BatchProcessed to: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630#-1171870480] 2015-07-25T00:54:52.121+0000 INFO Archival-akka.actor.default-dispatcher-6 com.whitepages.ait.archival.Archival Finished dispatch/ack batch of size: 40000 to LogWriters in 51 millis from actor: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306#-1505022696] 2015-07-25T00:54:52.121+0000 INFO Archival-akka.actor.default-dispatcher-6 com.whitepages.logging.LogProcessor In prod.log.general LogProcessor, got Ack from: Actor[akka://Archival/deadLetters] with count: 40000; status: 40000 / 40000} 2015-07-25T00:54:52.121+0000 INFO Archival-akka.actor.default-dispatcher-6 com.whitepages.logging.LogProcessor In processAck from Actor[akka://Archival/deadLetters], sending BatchProcessed to: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630#-1171870480] [WARN] [07/25/2015 00:54:53.522] [Archival-akka.actor.default-dispatcher-62] [akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630] state=WaitingToSendBatch msg=StateTimeout outstanding=1 streams=2 [WARN] [07/25/2015 00:54:54.542] [Archival-akka.actor.default-dispatcher-4] [akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630] state=WaitingToSendBatch msg=StateTimeout outstanding=1 streams=2 [WARN] [07/25/2015 00:54:55.563] [Archival-akka.actor.default-dispatcher-60] [akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630] state=WaitingToSendBatch msg=StateTimeout outstanding=1 streams=2 2015-07-25T00:54:56.558+0000 INFO Archival-akka.actor.default-dispatcher-9 com.whitepages.ait.archival.Archival Finished dispatch/ack batch of size: 39999 to LogWriters in 96 millis from actor: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306#-1505022696] 2015-07-25T00:54:56.559+0000 INFO Archival-akka.actor.default-dispatcher-9 com.whitepages.logging.LogProcessor In prod.log.general LogProcessor, got Ack from: Actor[akka://Archival/deadLetters] with count: 39999; status: 39999 / 39999} 2015-07-25T00:54:56.559+0000 INFO Archival-akka.actor.default-dispatcher-9 com.whitepages.logging.LogProcessor In processAck from Actor[akka://Archival/deadLetters], sending BatchProcessed to: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630#-1171870480] 2015-07-25T00:54:56.933+0000 INFO Archival-akka.actor.default-dispatcher-25 com.whitepages.ait.archival.Archival Finished dispatch/ack batch of size: 40000 to LogWriters in 42 millis from actor: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306#-1505022696] 2015-07-25T00:54:56.934+0000 INFO Archival-akka.actor.default-dispatcher-25 com.whitepages.logging.LogProcessor In prod.log.general LogProcessor, got Ack from: Actor[akka://Archival/deadLetters] with count: 40000; status: 40000 / 40000} 2015-07-25T00:54:56.934+0000 INFO Archival-akka.actor.default-dispatcher-25 com.whitepages.logging.LogProcessor In processAck from Actor[akka://Archival/deadLetters], sending BatchProcessed to: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630#-1171870480] 2015-07-25T00:54:57.409+0000 INFO Archival-akka.actor.default-dispatcher-56 com.whitepages.ait.archival.Archival Finished dispatch/ack batch of size: 40000 to LogWriters in 45 millis from actor: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306#-1505022696] 2015-07-25T00:54:57.409+0000 INFO Archival-akka.actor.default-dispatcher-56 com.whitepages.logging.LogProcessor In prod.log.general LogProcessor, got Ack from: Actor[akka://Archival/deadLetters] with count: 40000; status: 40000 / 40000} 2015-07-25T00:54:57.409+0000 INFO Archival-akka.actor.default-dispatcher-56 com.whitepages.logging.LogProcessor In processAck from Actor[akka://Archival/deadLetters], sending BatchProcessed to: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630#-1171870480] 2015-07-25T00:54:57.899+0000 INFO Archival-akka.actor.default-dispatcher-48 com.whitepages.ait.archival.Archival Finished dispatch/ack batch of size: 40000 to LogWriters in 41 millis from actor: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306#-1505022696] 2015-07-25T00:54:57.899+0000 INFO Archival-akka.actor.default-dispatcher-48 com.whitepages.logging.LogProcessor In prod.log.general LogProcessor, got Ack from: Actor[akka://Archival/deadLetters] with count: 40000; status: 40000 / 40000} 2015-07-25T00:54:57.899+0000 INFO Archival-akka.actor.default-dispatcher-48 com.whitepages.logging.LogProcessor In processAck from Actor[akka://Archival/deadLetters], sending BatchProcessed to: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630#-1171870480] [WARN] [07/25/2015 00:54:59.343] [Archival-akka.actor.default-dispatcher-2] [akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630] state=WaitingToSendBatch msg=StateTimeout outstanding=1 streams=2 [WARN] [07/25/2015 00:55:00.352] [Archival-akka.actor.default-dispatcher-26] [akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630] state=WaitingToSendBatch msg=StateTimeout outstanding=1 streams=2 [WARN] [07/25/2015 00:55:01.362] [Archival-akka.actor.default-dispatcher-7] [akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630] state=WaitingToSendBatch msg=StateTimeout outstanding=1 streams=2 2015-07-25T00:55:02.220+0000 INFO Archival-akka.actor.default-dispatcher-35 com.whitepages.ait.archival.Archival Finished dispatch/ack batch of size: 39999 to LogWriters in 46 millis from actor: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306#-1505022696] 2015-07-25T00:55:02.220+0000 INFO Archival-akka.actor.default-dispatcher-35 com.whitepages.logging.LogProcessor In prod.log.general LogProcessor, got Ack from: Actor[akka://Archival/deadLetters] with count: 39999; status: 39999 / 39999} 2015-07-25T00:55:02.220+0000 INFO Archival-akka.actor.default-dispatcher-35 com.whitepages.logging.LogProcessor In processAck from Actor[akka://Archival/deadLetters], sending BatchProcessed to: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630#-1171870480] [WARN] [07/25/2015 00:55:03.552] [Archival-akka.actor.default-dispatcher-62] [akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630] state=WaitingToSendBatch msg=StateTimeout outstanding=1 streams=2 [WARN] [07/25/2015 00:55:04.562] [Archival-akka.actor.default-dispatcher-30] [akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630] state=WaitingToSendBatch msg=StateTimeout outstanding=1 streams=2 [WARN] [07/25/2015 00:55:05.582] [Archival-akka.actor.default-dispatcher-25] [akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630] state=WaitingToSendBatch msg=StateTimeout outstanding=1 streams=2 2015-07-25T00:55:06.496+0000 INFO Archival-akka.actor.default-dispatcher-7 com.whitepages.ait.archival.Archival Finished dispatch/ack batch of size: 39999 to LogWriters in 30 millis from actor: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306#-1505022696] 2015-07-25T00:55:06.496+0000 INFO Archival-akka.actor.default-dispatcher-7 com.whitepages.logging.LogProcessor In prod.log.general LogProcessor, got Ack from: Actor[akka://Archival/deadLetters] with count: 39999; status: 39999 / 39999} 2015-07-25T00:55:06.496+0000 INFO Archival-akka.actor.default-dispatcher-7 com.whitepages.logging.LogProcessor In processAck from Actor[akka://Archival/deadLetters], sending BatchProcessed to: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630#-1171870480] 2015-07-25T00:55:06.957+0000 INFO Archival-akka.actor.default-dispatcher-49 com.whitepages.ait.archival.Archival Finished dispatch/ack batch of size: 40000 to LogWriters in 43 millis from actor: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306#-1505022696] 2015-07-25T00:55:06.957+0000 INFO Archival-akka.actor.default-dispatcher-49 com.whitepages.logging.LogProcessor In prod.log.general LogProcessor, got Ack from: Actor[akka://Archival/deadLetters] with count: 40000; status: 40000 / 40000} 2015-07-25T00:55:06.957+0000 INFO Archival-akka.actor.default-dispatcher-49 com.whitepages.logging.LogProcessor In processAck from Actor[akka://Archival/deadLetters], sending BatchProcessed to: Actor[akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630#-1171870480] q[WARN] [07/25/2015 00:55:08.383] [Archival-akka.actor.default-dispatcher-45] [akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630] state=WaitingToSendBatch msg=StateTimeout outstanding=1 streams=2 [WARN] [07/25/2015 00:55:09.402] [Archival-akka.actor.default-dispatcher-17] [akka://Archival/user/KafkaLogProcessor-prod.log.general-128919660836139306/prod.log.general.connector8919660836712630] state=WaitingToSendBatch msg=StateTimeout outstanding=1 streams=2
I see the same pattern recurring (a full batch of e.g. 40k exactly) moves quite quickly. When it isn't moving quickly, there are three WaitingToSendBatch warnings followed by a batch size of (FullBatch-1)...
Once delivered, the time spent processing and Acking batches is on the order of 50ms (just streaming to files), and GC isn't an issue either, as the box has 80GB RAM and the JVM isn't too busy collecting...
So there may be one issue here or two (the WaitingToSendBatch and the inability to have a reasonably high number of streams; both symptoms may be related to a single root cause, or not...)
Help! (Thanks!)