using kafka consumer, 2 mins batch, tasks process take 2 ~ 5 seconds in
general, but a part of tasks take more than 40 seconds. I guess
*CachedKafkaConsumer#poll* could be problem.
private def poll(timeout: Long): Unit = {
val p = consumer.poll(timeout)
val r = p.records(topicPartition)
logDebug(s"Polled ${p.partitions()} ${r.size}")
buffer = r.iterator
}
make changes on that method. add time consuming log
private def poll(timeout: Long): Unit = {
val start = System.currentTimeMillis()
val p = consumer.poll(timeout)
val end = System.currentTimeMillis()
val r = p.records(topicPartition)
logInfo(s"Polled ${p.partitions()} ${r.size} cost ${end-start}" +
s" ${System.currentTimeMillis() - end} timeout setting ${timeout}")
buffer = r.iterator
}
task log below:
19/08/15 16:46:00 INFO executor.CoarseGrainedExecutorBackend: Got assigned
task 124
19/08/15 16:46:00 INFO executor.Executor: Running task 3.0 in stage 10.0
(TID 124)
19/08/15 16:46:00 INFO broadcast.TorrentBroadcast: Started reading broadcast
variable 10
19/08/15 16:46:00 INFO memory.MemoryStore: Block broadcast_10_piece0 stored
as bytes in memory (estimated size 2.1 KB, free 366.2 MB)
19/08/15 16:46:00 INFO broadcast.TorrentBroadcast: Reading broadcast
variable 10 took 10 ms
19/08/15 16:46:00 INFO memory.MemoryStore: Block broadcast_10 stored as
values in memory (estimated size 3.6 KB, free 366.2 MB)
19/08/15 16:46:00 INFO kafka010.KafkaRDD: Computing topic test_topic,
partition 9 offsets 4382382407 -> 4382457892
*19/08/15 16:46:40 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
705 cost 40050 0 timeout setting 120000
*19/08/15 16:46:40 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
691 cost 26 0 timeout setting 120000
19/08/15 16:46:40 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
725 cost 16 0 timeout setting 120000
19/08/15 16:46:40 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
714 cost 16 0 timeout setting 120000
19/08/15 16:46:40 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
721 cost 17 0 timeout setting 120000
19/08/15 16:46:40 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
709 cost 13 0 timeout setting 120000
19/08/15 16:46:40 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
719 cost 16 0 timeout setting 120000
19/08/15 16:46:40 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
734 cost 17 0 timeout setting 120000
19/08/15 16:46:40 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
728 cost 17 0 timeout setting 120000
19/08/15 16:46:40 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
724 cost 17 0 timeout setting 120000
19/08/15 16:46:40 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
719 cost 17 0 timeout setting 120000
19/08/15 16:46:40 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
738 cost 12 0 timeout setting 120000
19/08/15 16:46:40 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
709 cost 16 0 timeout setting 120000
19/08/15 16:46:40 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
701 cost 18 0 timeout setting 120000
19/08/15 16:46:40 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
718 cost 16 0 timeout setting 120000
19/08/15 16:46:40 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
734 cost 16 0 timeout setting 120000
19/08/15 16:46:40 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
702 cost 17 0 timeout setting 120000
19/08/15 16:46:40 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
717 cost 16 0 timeout setting 120000
19/08/15 16:46:40 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
711 cost 17 0 timeout setting 120000
19/08/15 16:46:40 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
715 cost 33 0 timeout setting 120000
19/08/15 16:46:40 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
726 cost 11 0 timeout setting 120000
19/08/15 16:46:40 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
713 cost 16 0 timeout setting 120000
19/08/15 16:46:40 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
697 cost 16 0 timeout setting 120000
19/08/15 16:46:40 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
719 cost 22 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
750 cost 13 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
707 cost 11 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
743 cost 13 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
746 cost 12 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
737 cost 11 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
715 cost 17 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
725 cost 16 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
712 cost 17 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
703 cost 13 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
722 cost 12 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
709 cost 18 1 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
709 cost 19 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
702 cost 19 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
734 cost 15 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
716 cost 17 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
716 cost 18 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
716 cost 12 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
710 cost 17 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
737 cost 12 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
728 cost 13 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
710 cost 15 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
710 cost 15 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
713 cost 15 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
738 cost 16 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
722 cost 17 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
734 cost 16 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
729 cost 14 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
733 cost 15 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
727 cost 17 0 timeout setting 120000
19/08/15 16:46:41 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
734 cost 16 0 timeout setting 120000
19/08/15 16:46:42 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
723 cost 17 0 timeout setting 120000
19/08/15 16:46:42 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
735 cost 13 0 timeout setting 120000
19/08/15 16:46:42 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
729 cost 23 0 timeout setting 120000
19/08/15 16:46:42 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
718 cost 11 0 timeout setting 120000
19/08/15 16:46:42 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
720 cost 13 0 timeout setting 120000
19/08/15 16:46:42 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
729 cost 43 0 timeout setting 120000
19/08/15 16:46:42 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
746 cost 13 0 timeout setting 120000
19/08/15 16:46:42 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
742 cost 17 0 timeout setting 120000
19/08/15 16:46:42 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
716 cost 16 0 timeout setting 120000
19/08/15 16:46:42 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
730 cost 17 0 timeout setting 120000
19/08/15 16:46:42 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
713 cost 16 0 timeout setting 120000
19/08/15 16:46:42 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
724 cost 17 0 timeout setting 120000
19/08/15 16:46:42 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
710 cost 17 0 timeout setting 120000
19/08/15 16:46:42 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
706 cost 17 0 timeout setting 120000
19/08/15 16:46:42 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
703 cost 16 0 timeout setting 120000
19/08/15 16:46:42 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
734 cost 17 0 timeout setting 120000
19/08/15 16:46:42 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
729 cost 41 0 timeout setting 120000
19/08/15 16:46:42 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
711 cost 16 0 timeout setting 120000
19/08/15 16:46:42 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
720 cost 19 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
717 cost 366 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
722 cost 23 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
706 cost 16 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
717 cost 17 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
703 cost 22 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
708 cost 14 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
706 cost 20 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
715 cost 13 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
705 cost 11 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
719 cost 12 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
747 cost 12 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
742 cost 17 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
743 cost 35 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
717 cost 13 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
729 cost 22 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
724 cost 12 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
731 cost 17 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
736 cost 17 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
716 cost 20 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
698 cost 11 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
717 cost 12 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
751 cost 10 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
735 cost 12 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
690 cost 13 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
715 cost 12 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
723 cost 13 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
720 cost 11 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
713 cost 12 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
735 cost 11 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
727 cost 13 0 timeout setting 120000
19/08/15 16:46:43 INFO kafka010.CachedKafkaConsumer: Polled [test_topic-9]
721 cost 12 0 timeout setting 120000
19/08/15 16:46:43 INFO executor.Executor: Finished task 3.0 in stage 10.0
(TID 124). 1813 bytes result sent to driver
19/08/15 16:46:46 INFO storage.BlockManager: Removing RDD 9
seems /consumer.poll(timeout)/ takes too long when first poll in task
Version information:
spark 2.11
kafka 0.10.0.1
--
Sent from: http://apache-spark-user-list.1001560.n3.nabble.com/
---------------------------------------------------------------------
To unsubscribe e-mail: user-unsubscr...@spark.apache.org
