Stall in trident stream

[Yeling Shi <Ye...@calix.com>]

Hi guys,
Need some help troubleshooting an issue in topology built using trident API.
We have built a topology to do stream data processing and recently we observed that there will be stalls from time to time. We tried to identify the issue and narrowed down the scope to a piece of topology that we are doing partition on stream data before they are sent to a state query function. Our stream data would be transferred to the query function but the processing didn't continue even when all the data a transferred.

After enable the debug option for the cluster, we tried to filtered out the below logs. Bolt b-21 is doing the state query while b-17 are doing aggregation and also partitioning (a custom partitioner). What we found here is some of the b-17 tasks failed to send the $coord-bg0 message in batch [52:1] and I think the b-21 was waiting until the batch times out and causing the batch to be replayed.

My questions are: are we in the right direction or does the log below looks normal? How can we look further to see why the bolt b-17 didn't send out $coord-bg0 message to tell that one batch is over?

Thanks in advance
Yeling

FYI, the log traces.
ubuntu@ipXXX:~/logs$ grep "b-21\].\+received.\+coord-bg0.\+\[51\:0" worker-670*
worker-6701.log.6:12-17 04:32:57.611 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:136, stream: $coord-bg0, id: {-7136713292474834469=-851420934578354003}, [51:0, 0]
worker-6701.log.6:12-17 04:32:57.775 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:133, stream: $coord-bg0, id: {-7136713292474834469=2440017194786342385}, [51:0, 0]
worker-6701.log.6:12-17 04:32:58.024 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:138, stream: $coord-bg0, id: {-7136713292474834469=7735035695997037324}, [51:0, 0]
worker-6701.log.6:12-17 04:32:58.045 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:127, stream: $coord-bg0, id: {-7136713292474834469=4040183849563831578}, [51:0, 0]
worker-6701.log.6:12-17 04:32:58.075 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:143, stream: $coord-bg0, id: {-7136713292474834469=8743869519057475603}, [51:0, 0]
worker-6701.log.6:12-17 04:32:58.090 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:142, stream: $coord-bg0, id: {-7136713292474834469=3600421623248941342}, [51:0, 0]
worker-6701.log.6:12-17 04:32:58.217 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:130, stream: $coord-bg0, id: {-7136713292474834469=-3328019112652800752}, [51:0, 0]
worker-6701.log.6:12-17 04:32:58.284 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:129, stream: $coord-bg0, id: {-7136713292474834469=-3738487491821459722}, [51:0, 0]
worker-6701.log.6:12-17 04:32:58.335 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:124, stream: $coord-bg0, id: {-7136713292474834469=6231704250066582606}, [51:0, 0]
worker-6701.log.6:12-17 04:32:58.432 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:141, stream: $coord-bg0, id: {-7136713292474834469=-7477334660878309416}, [51:0, 0]
worker-6701.log.6:12-17 04:32:58.469 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:126, stream: $coord-bg0, id: {-7136713292474834469=168050796225596043}, [51:0, 0]
worker-6701.log.6:12-17 04:32:58.511 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:139, stream: $coord-bg0, id: {-7136713292474834469=6953514965481684202}, [51:0, 0]
worker-6701.log.6:12-17 04:32:58.550 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:137, stream: $coord-bg0, id: {-7136713292474834469=-6398421267889633059}, [51:0, 0]
worker-6701.log.6:12-17 04:32:58.595 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:135, stream: $coord-bg0, id: {-7136713292474834469=-1856394386144516032}, [51:0, 0]
worker-6701.log.6:12-17 04:32:58.697 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:125, stream: $coord-bg0, id: {-7136713292474834469=-1779652479081346578}, [51:0, 0]
worker-6701.log.6:12-17 04:32:58.714 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:131, stream: $coord-bg0, id: {-7136713292474834469=-253596241138150373}, [51:0, 0]
worker-6701.log.6:12-17 04:32:58.833 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:128, stream: $coord-bg0, id: {-7136713292474834469=-2574071615014628831}, [51:0, 0]
worker-6701.log.6:12-17 04:32:58.946 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:132, stream: $coord-bg0, id: {-7136713292474834469=-4302616177471329449}, [51:0, 0]
worker-6701.log.6:12-17 04:32:58.967 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:134, stream: $coord-bg0, id: {-7136713292474834469=4966768859147190967}, [51:0, 0]
worker-6701.log.6:12-17 04:32:59.391 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:140, stream: $coord-bg0, id: {-7136713292474834469=7520093913876960459}, [51:0, 0]
ubuntu@ipXXX:~/logs$ grep "b-21\].\+received.\+coord-bg0.\+\[52\:0" worker-670*
worker-6701.log.6:12-17 04:33:04.814 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:132, stream: $coord-bg0, id: {2591894867587822468=7693090773101058096}, [52:0, 0]
worker-6701.log.6:12-17 04:33:05.043 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:125, stream: $coord-bg0, id: {2591894867587822468=-4763231995168893928}, [52:0, 0]
worker-6701.log.6:12-17 04:33:05.072 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:138, stream: $coord-bg0, id: {2591894867587822468=5012888072654420981}, [52:0, 0]
worker-6701.log.6:12-17 04:33:05.207 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:129, stream: $coord-bg0, id: {2591894867587822468=1531664186653117727}, [52:0, 0]
worker-6701.log.6:12-17 04:33:05.223 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:130, stream: $coord-bg0, id: {2591894867587822468=7385954631194101038}, [52:0, 0]
worker-6701.log.6:12-17 04:33:05.253 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:142, stream: $coord-bg0, id: {2591894867587822468=4496196083010077992}, [52:0, 0]
worker-6701.log.6:12-17 04:33:05.257 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:136, stream: $coord-bg0, id: {2591894867587822468=8523874508220079497}, [52:0, 0]
worker-6701.log.6:12-17 04:33:05.322 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:126, stream: $coord-bg0, id: {2591894867587822468=-6989619861546777699}, [52:0, 0]
worker-6701.log.6:12-17 04:33:05.346 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:124, stream: $coord-bg0, id: {2591894867587822468=2537270258466514056}, [52:0, 0]
worker-6701.log.6:12-17 04:33:05.481 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:134, stream: $coord-bg0, id: {2591894867587822468=3736441829967207066}, [52:0, 0]
worker-6701.log.6:12-17 04:33:05.486 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:128, stream: $coord-bg0, id: {2591894867587822468=4447728067424207151}, [52:0, 0]
worker-6701.log.6:12-17 04:33:05.528 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:133, stream: $coord-bg0, id: {2591894867587822468=-4055845633578069985}, [52:0, 0]
worker-6701.log.6:12-17 04:33:05.686 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:140, stream: $coord-bg0, id: {2591894867587822468=-2971008607810185363}, [52:0, 0]
worker-6701.log.6:12-17 04:33:05.772 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:137, stream: $coord-bg0, id: {2591894867587822468=-4674113403613652830}, [52:0, 0]
worker-6701.log.6:12-17 04:33:06.377 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:141, stream: $coord-bg0, id: {2591894867587822468=-9089824651865319735}, [52:0, 0]
worker-6701.log.6:12-17 04:33:06.771 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:135, stream: $coord-bg0, id: {2591894867587822468=-8367916461523635307}, [52:0, 0]
ubuntu@ipXXX:~/logs$ grep "b-21\].\+received.\+coord-bg0.\+\[52\:1" worker-670*
worker-6701.log.6:12-17 04:33:35.791 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:140, stream: $coord-bg0, id: {-8661870167326040675=4648554645499723233}, [52:1, 0]
worker-6701.log.6:12-17 04:33:35.948 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:136, stream: $coord-bg0, id: {-8661870167326040675=348484095349122103}, [52:1, 0]
worker-6701.log.6:12-17 04:33:35.966 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:128, stream: $coord-bg0, id: {-8661870167326040675=1881696101964944321}, [52:1, 0]
worker-6701.log.6:12-17 04:33:36.249 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:138, stream: $coord-bg0, id: {-8661870167326040675=-5351210827876891431}, [52:1, 0]
worker-6701.log.6:12-17 04:33:36.310 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:126, stream: $coord-bg0, id: {-8661870167326040675=-1551931278924159689}, [52:1, 0]
worker-6701.log.6:12-17 04:33:36.345 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:134, stream: $coord-bg0, id: {-8661870167326040675=2282913014494394740}, [52:1, 0]
worker-6701.log.6:12-17 04:33:36.390 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:131, stream: $coord-bg0, id: {-8661870167326040675=-7702908604766793910}, [52:1, 0]
worker-6701.log.6:12-17 04:33:36.420 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:143, stream: $coord-bg0, id: {-8661870167326040675=-407236442450170255}, [52:1, 0]
worker-6701.log.6:12-17 04:33:36.442 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:132, stream: $coord-bg0, id: {-8661870167326040675=-5675538948909289180}, [52:1, 0]
worker-6701.log.6:12-17 04:33:36.443 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:137, stream: $coord-bg0, id: {-8661870167326040675=-5608534857657388193}, [52:1, 0]
worker-6701.log.6:12-17 04:33:36.578 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:127, stream: $coord-bg0, id: {-8661870167326040675=3036387979937609120}, [52:1, 0]
worker-6701.log.6:12-17 04:33:36.654 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:129, stream: $coord-bg0, id: {-8661870167326040675=-3311581697327530618}, [52:1, 0]
worker-6701.log.6:12-17 04:33:36.682 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:141, stream: $coord-bg0, id: {-8661870167326040675=-3027466019563123695}, [52:1, 0]
worker-6701.log.6:12-17 04:33:36.720 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:124, stream: $coord-bg0, id: {-8661870167326040675=728782990161311378}, [52:1, 0]
worker-6701.log.6:12-17 04:33:36.794 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:125, stream: $coord-bg0, id: {-8661870167326040675=-8054262538408987029}, [52:1, 0]
worker-6701.log.6:12-17 04:33:36.822 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:133, stream: $coord-bg0, id: {-8661870167326040675=7585463731393324258}, [52:1, 0]
worker-6701.log.6:12-17 04:33:36.893 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:135, stream: $coord-bg0, id: {-8661870167326040675=2104209486014121348}, [52:1, 0]
worker-6701.log.6:12-17 04:33:37.091 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:130, stream: $coord-bg0, id: {-8661870167326040675=-5607762502001426131}, [52:1, 0]
worker-6701.log.6:12-17 04:33:37.225 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:139, stream: $coord-bg0, id: {-8661870167326040675=2575498847513810818}, [52:1, 0]
worker-6701.log.6:12-17 04:33:37.293 [Thread-23-b-21] INFO  backtype.storm.daemon.executor - Processing received message source: b-17:142, stream: $coord-bg0, id: {-8661870167326040675=8175553514248419592}, [52:1, 0]