GapAwareTrackingToken: growing # of gaps

Hello,

During startup I’m seeing an every growing number of gaps reported in the logs by GapAwareTrackingToken
I’ve copy/pasted the snip from the log at the end of this message.

I looked around for docs on the theory of operations of the TrackingEventProcessor.

The closest thing I’ve found is https://docs.axoniq.io/reference-guide/appendices/rdbms-tuning#sql-databases
from which:

It is highly recommended to ensure that no gaps exist because of over eagerly increasing the sequence number.

Unfortunately I still don’t understand.
Is this log output an indication there is an error in our implementation?

Thanks for any assistance!

2020-05-08 14:23:56.518 INFO 38827 — [agaProcessor]-0] o.a.e.TrackingEventProcessor : Fetched token: GapAwareTrackingToken{index=6257, gaps=[1808, 1809, 1819, 1907, 1908, 1925, 2019, 2020, 2021, 2022, 2023, 2024, 2025, 2026, 2027, 2028, 2029, 2058, 2157, 2158, 2172, 2173, 2183, 2196, 2318, 2319, 2331, 2466, 2467, 2480, 2730, 2731, 2746, 2814, 2815, 2816, 2817, 2818, 2819, 2820, 2821, 2822, 2823, 2824, 2825, 2874, 2875, 2892, 2907, 2909, 2926, 2927, 3003, 3004, 3005, 3006, 3007, 3008, 3009, 3010, 3011, 3012, 3013, 3035, 3049, 3061, 3089, 3090, 3110, 3134, 3135, 3136, 3150, 3164, 3240, 3241, 3242, 3260, 3261, 3275, 3288, 3654, 3655, 3669, 3777, 3778, 3779, 3780, 3781, 3782, 3783, 3784, 3785, 3786, 3787, 3788, 3815, 3816, 3835, 3836, 3837, 3854, 3869, 3882, 3967, 3968, 3969, 3983, 4051, 4052, 4053, 4063, 4138, 4139, 4140, 4141, 4142, 4143, 4144, 4145, 4146, 4147, 4148, 4149, 4179, 4591, 4592, 4607, 4940, 4941, 4942, 4959, 5602, 5603, 5616, 6020, 6021, 6022, 6029, 6129, 6130, 6131, 6139, 6200, 6201, 6202, 6207]} for segment: Segment[0/0]
2020-05-08 14:23:56.524 INFO 38827 — [agaProcessor]-0] o.a.e.TrackingEventProcessor : Fetched token: GapAwareTrackingToken{index=6257, gaps=[1808, 1809, 1819, 1907, 1908, 1925, 2019, 2020, 2021, 2022, 2023, 2024, 2025, 2026, 2027, 2028, 2029, 2058, 2157, 2158, 2172, 2173, 2183, 2196, 2318, 2319, 2331, 2466, 2467, 2480, 2730, 2731, 2746, 2814, 2815, 2816, 2817, 2818, 2819, 2820, 2821, 2822, 2823, 2824, 2825, 2874, 2875, 2892, 2907, 2909, 2926, 2927, 3003, 3004, 3005, 3006, 3007, 3008, 3009, 3010, 3011, 3012, 3013, 3035, 3049, 3061, 3089, 3090, 3110, 3134, 3135, 3136, 3150, 3164, 3240, 3241, 3242, 3260, 3261, 3275, 3288, 3654, 3655, 3669, 3777, 3778, 3779, 3780, 3781, 3782, 3783, 3784, 3785, 3786, 3787, 3788, 3815, 3816, 3835, 3836, 3837, 3854, 3869, 3882, 3967, 3968, 3969, 3983, 4051, 4052, 4053, 4063, 4138, 4139, 4140, 4141, 4142, 4143, 4144, 4145, 4146, 4147, 4148, 4149, 4179, 4591, 4592, 4607, 4940, 4941, 4942, 4959, 5602, 5603, 5616, 6020, 6021, 6022, 6029, 6129, 6130, 6131, 6139, 6200, 6201, 6202, 6207]} for segment: Segment[0/0]
2020-05-08 14:23:56.529 INFO 38827 — [agaProcessor]-0] o.a.e.TrackingEventProcessor : Fetched token: GapAwareTrackingToken{index=6257, gaps=[1808, 1809, 1819, 1907, 1908, 1925, 2019, 2020, 2021, 2022, 2023, 2024, 2025, 2026, 2027, 2028, 2029, 2058, 2157, 2158, 2172, 2173, 2183, 2196, 2318, 2319, 2331, 2466, 2467, 2480, 2730, 2731, 2746, 2814, 2815, 2816, 2817, 2818, 2819, 2820, 2821, 2822, 2823, 2824, 2825, 2874, 2875, 2892, 2907, 2909, 2926, 2927, 3003, 3004, 3005, 3006, 3007, 3008, 3009, 3010, 3011, 3012, 3013, 3035, 3049, 3061, 3089, 3090, 3110, 3134, 3135, 3136, 3150, 3164, 3240, 3241, 3242, 3260, 3261, 3275, 3288, 3654, 3655, 3669, 3777, 3778, 3779, 3780, 3781, 3782, 3783, 3784, 3785, 3786, 3787, 3788, 3815, 3816, 3835, 3836, 3837, 3854, 3869, 3882, 3967, 3968, 3969, 3983, 4051, 4052, 4053, 4063, 4138, 4139, 4140, 4141, 4142, 4143, 4144, 4145, 4146, 4147, 4148, 4149, 4179, 4591, 4592, 4607, 4940, 4941, 4942, 4959, 5602, 5603, 5616, 6020, 6021, 6022, 6029, 6129, 6130, 6131, 6139, 6200, 6201, 6202, 6207]} for segment: Segment[0/0]
2020-05-08 14:23:56.537 INFO 38827 — [n.app.domain]-0] o.a.e.TrackingEventProcessor : Fetched token: GapAwareTrackingToken{index=6257, gaps=[1808, 1809, 1819, 1907, 1908, 1925, 2019, 2020, 2021, 2022, 2023, 2024, 2025, 2026, 2027, 2028, 2029, 2058, 2157, 2158, 2172, 2173, 2183, 2196, 2318, 2319, 2331, 2466, 2467, 2480, 2730, 2731, 2746, 2814, 2815, 2816, 2817, 2818, 2819, 2820, 2821, 2822, 2823, 2824, 2825, 2874, 2875, 2892, 2907, 2909, 2926, 2927, 3003, 3004, 3005, 3006, 3007, 3008, 3009, 3010, 3011, 3012, 3013, 3035, 3049, 3061, 3089, 3090, 3110, 3134, 3135, 3136, 3150, 3164, 3240, 3241, 3242, 3260, 3261, 3275, 3288, 3654, 3655, 3669, 3777, 3778, 3779, 3780, 3781, 3782, 3783, 3784, 3785, 3786, 3787, 3788, 3815, 3816, 3835, 3836, 3837, 3854, 3869, 3882, 3967, 3968, 3969, 3983, 4051, 4052, 4053, 4063, 4138, 4139, 4140, 4141, 4142, 4143, 4144, 4145, 4146, 4147, 4148, 4149, 4179, 4591, 4592, 4607, 4940, 4941, 4942, 4959, 5602, 5603, 5616, 6020, 6021, 6022, 6029, 6129, 6130, 6131, 6139, 6200, 6201, 6202, 6207]} for segment: Segment[0/0]
2020-05-08 14:23:56.537 INFO 38827 — [agaProcessor]-0] o.a.e.TrackingEventProcessor : Fetched token: GapAwareTrackingToken{index=6257, gaps=[1808, 1809, 1819, 1907, 1908, 1925, 2019, 2020, 2021, 2022, 2023, 2024, 2025, 2026, 2027, 2028, 2029, 2058, 2157, 2158, 2172, 2173, 2183, 2196, 2318, 2319, 2331, 2466, 2467, 2480, 2730, 2731, 2746, 2814, 2815, 2816, 2817, 2818, 2819, 2820, 2821, 2822, 2823, 2824, 2825, 2874, 2875, 2892, 2907, 2909, 2926, 2927, 3003, 3004, 3005, 3006, 3007, 3008, 3009, 3010, 3011, 3012, 3013, 3035, 3049, 3061, 3089, 3090, 3110, 3134, 3135, 3136, 3150, 3164, 3240, 3241, 3242, 3260, 3261, 3275, 3288, 3654, 3655, 3669, 3777, 3778, 3779, 3780, 3781, 3782, 3783, 3784, 3785, 3786, 3787, 3788, 3815, 3816, 3835, 3836, 3837, 3854, 3869, 3882, 3967, 3968, 3969, 3983, 4051, 4052, 4053, 4063, 4138, 4139, 4140, 4141, 4142, 4143, 4144, 4145, 4146, 4147, 4148, 4149, 4179, 4591, 4592, 4607, 4940, 4941, 4942, 4959, 5602, 5603, 5616, 6020, 6021, 6022, 6029, 6129, 6130, 6131, 6139, 6200, 6201, 6202, 6207]} for segment: Segment[0/0]
2020-05-08 14:23:56.528 INFO 38827 — [agaProcessor]-0] o.a.e.TrackingEventProcessor : Using current Thread for last segment worker: TrackingSegmentWorker{processor=EditPackageSagaProcessor, segment=Segment[0/0]}
2020-05-08 14:23:56.529 INFO 38827 — [agaProcessor]-0] o.a.e.TrackingEventProcessor : Fetched token: GapAwareTrackingToken{index=6257, gaps=[1808, 1809, 1819, 1907, 1908, 1925, 2019, 2020, 2021, 2022, 2023, 2024, 2025, 2026, 2027, 2028, 2029, 2058, 2157, 2158, 2172, 2173, 2183, 2196, 2318, 2319, 2331, 2466, 2467, 2480, 2730, 2731, 2746, 2814, 2815, 2816, 2817, 2818, 2819, 2820, 2821, 2822, 2823, 2824, 2825, 2874, 2875, 2892, 2907, 2909, 2926, 2927, 3003, 3004, 3005, 3006, 3007, 3008, 3009, 3010, 3011, 3012, 3013, 3035, 3049, 3061, 3089, 3090, 3110, 3134, 3135, 3136, 3150, 3164, 3240, 3241, 3242, 3260, 3261, 3275, 3288, 3654, 3655, 3669, 3777, 3778, 3779, 3780, 3781, 3782, 3783, 3784, 3785, 3786, 3787, 3788, 3815, 3816, 3835, 3836, 3837, 3854, 3869, 3882, 3967, 3968, 3969, 3983, 4051, 4052, 4053, 4063, 4138, 4139, 4140, 4141, 4142, 4143, 4144, 4145, 4146, 4147, 4148, 4149, 4179, 4591, 4592, 4607, 4940, 4941, 4942, 4959, 5602, 5603, 5616, 6020, 6021, 6022, 6029, 6129, 6130, 6131, 6139, 6200, 6201, 6202, 6207]} for segment: Segment[0/0]
2020-05-08 14:23:56.544 INFO 38827 — [agaProcessor]-0] o.a.e.TrackingEventProcessor : Fetched token: GapAwareTrackingToken{index=6257, gaps=[1808, 1809, 1819, 1907, 1908, 1925, 2019, 2020, 2021, 2022, 2023, 2024, 2025, 2026, 2027, 2028, 2029, 2058, 2157, 2158, 2172, 2173, 2183, 2196, 2318, 2319, 2331, 2466, 2467, 2480, 2730, 2731, 2746, 2814, 2815, 2816, 2817, 2818, 2819, 2820, 2821, 2822, 2823, 2824, 2825, 2874, 2875, 2892, 2907, 2909, 2926, 2927, 3003, 3004, 3005, 3006, 3007, 3008, 3009, 3010, 3011, 3012, 3013, 3035, 3049, 3061, 3089, 3090, 3110, 3134, 3135, 3136, 3150, 3164, 3240, 3241, 3242, 3260, 3261, 3275, 3288, 3654, 3655, 3669, 3777, 3778, 3779, 3780, 3781, 3782, 3783, 3784, 3785, 3786, 3787, 3788, 3815, 3816, 3835, 3836, 3837, 3854, 3869, 3882, 3967, 3968, 3969, 3983, 4051, 4052, 4053, 4063, 4138, 4139, 4140, 4141, 4142, 4143, 4144, 4145, 4146, 4147, 4148, 4149, 4179, 4591, 4592, 4607, 4940, 4941, 4942, 4959, 5602, 5603, 5616, 6020, 6021, 6022, 6029, 6129, 6130, 6131, 6139, 6200, 6201, 6202, 6207]} for segment: Segment[0/0]
2020-05-08 14:23:56.551 INFO 38827 — [agaProcessor]-0] o.a.e.TrackingEventProcessor : Fetched token: GapAwareTrackingToken{index=6257, gaps=[1808, 1809, 1819, 1907, 1908, 1925, 2019, 2020, 2021, 2022, 2023, 2024, 2025, 2026, 2027, 2028, 2029, 2058, 2157, 2158, 2172, 2173, 2183, 2196, 2318, 2319, 2331, 2466, 2467, 2480, 2730, 2731, 2746, 2814, 2815, 2816, 2817, 2818, 2819, 2820, 2821, 2822, 2823, 2824, 2825, 2874, 2875, 2892, 2907, 2909, 2926, 2927, 3003, 3004, 3005, 3006, 3007, 3008, 3009, 3010, 3011, 3012, 3013, 3035, 3049, 3061, 3089, 3090, 3110, 3134, 3135, 3136, 3150, 3164, 3240, 3241, 3242, 3260, 3261, 3275, 3288, 3654, 3655, 3669, 3777, 3778, 3779, 3780, 3781, 3782, 3783, 3784, 3785, 3786, 3787, 3788, 3815, 3816, 3835, 3836, 3837, 3854, 3869, 3882, 3967, 3968, 3969, 3983, 4051, 4052, 4053, 4063, 4138, 4139, 4140, 4141, 4142, 4143, 4144, 4145, 4146, 4147, 4148, 4149, 4179, 4591, 4592, 4607, 4940, 4941, 4942, 4959, 5602, 5603, 5616, 6020, 6021, 6022, 6029, 6129, 6130, 6131, 6139, 6200, 6201, 6202, 6207]} for segment: Segment[0/0]
2020-05-08 14:23:56.562 INFO 38827 — [agaProcessor]-0] o.a.e.TrackingEventProcessor : Fetched token: GapAwareTrackingToken{index=6257, gaps=[1808, 1809, 1819, 1907, 1908, 1925, 2019, 2020, 2021, 2022, 2023, 2024, 2025, 2026, 2027, 2028, 2029, 2058, 2157, 2158, 2172, 2173, 2183, 2196, 2318, 2319, 2331, 2466, 2467, 2480, 2730, 2731, 2746, 2814, 2815, 2816, 2817, 2818, 2819, 2820, 2821, 2822, 2823, 2824, 2825, 2874, 2875, 2892, 2907, 2909, 2926, 2927, 3003, 3004, 3005, 3006, 3007, 3008, 3009, 3010, 3011, 3012, 3013, 3035, 3049, 3061, 3089, 3090, 3110, 3134, 3135, 3136, 3150, 3164, 3240, 3241, 3242, 3260, 3261, 3275, 3288, 3654, 3655, 3669, 3777, 3778, 3779, 3780, 3781, 3782, 3783, 3784, 3785, 3786, 3787, 3788, 3815, 3816, 3835, 3836, 3837, 3854, 3869, 3882, 3967, 3968, 3969, 3983, 4051, 4052, 4053, 4063, 4138, 4139, 4140, 4141, 4142, 4143, 4144, 4145, 4146, 4147, 4148, 4149, 4179, 4591, 4592, 4607, 4940, 4941, 4942, 4959, 5602, 5603, 5616, 6020, 6021, 6022, 6029, 6129, 6130, 6131, 6139, 6200, 6201, 6202, 6207]} for segment: Segment[0/0]
2020-05-08 14:23:56.564 INFO 38827 — [.app.storage]-0] o.a.e.TrackingEventProcessor : Fetched token: GapAwareTrackingToken{index=6257, gaps=[1808, 1809, 1819, 1907, 1908, 1925, 2019, 2020, 2021, 2022, 2023, 2024, 2025, 2026, 2027, 2028, 2029, 2058, 2157, 2158, 2172, 2173, 2183, 2196, 2318, 2319, 2331, 2466, 2467, 2480, 2730, 2731, 2746, 2814, 2815, 2816, 2817, 2818, 2819, 2820, 2821, 2822, 2823, 2824, 2825, 2874, 2875, 2892, 2907, 2909, 2926, 2927, 3003, 3004, 3005, 3006, 3007, 3008, 3009, 3010, 3011, 3012, 3013, 3035, 3049, 3061, 3089, 3090, 3110, 3134, 3135, 3136, 3150, 3164, 3240, 3241, 3242, 3260, 3261, 3275, 3288, 3654, 3655, 3669, 3777, 3778, 3779, 3780, 3781, 3782, 3783, 3784, 3785, 3786, 3787, 3788, 3815, 3816, 3835, 3836, 3837, 3854, 3869, 3882, 3967, 3968, 3969, 3983, 4051, 4052, 4053, 4063, 4138, 4139, 4140, 4141, 4142, 4143, 4144, 4145, 4146, 4147, 4148, 4149, 4179, 4591, 4592, 4607, 4940, 4941, 4942, 4959, 5602, 5603, 5616, 6020, 6021, 6022, 6029, 6129, 6130, 6131, 6139, 6200, 6201, 6202, 6207]} for segment: Segment[0/0]
2020-05-08 14:23:56.566 INFO 38827 — [agaProcessor]-0] o.a.e.TrackingEventProcessor : Fetched token: GapAwareTrackingToken{index=6257, gaps=[1808, 1809, 1819, 1907, 1908, 1925, 2019, 2020, 2021, 2022, 2023, 2024, 2025, 2026, 2027, 2028, 2029, 2058, 2157, 2158, 2172, 2173, 2183, 2196, 2318, 2319, 2331, 2466, 2467, 2480, 2730, 2731, 2746, 2814, 2815, 2816, 2817, 2818, 2819, 2820, 2821, 2822, 2823, 2824, 2825, 2874, 2875, 2892, 2907, 2909, 2926, 2927, 3003, 3004, 3005, 3006, 3007, 3008, 3009, 3010, 3011, 3012, 3013, 3035, 3049, 3061, 3089, 3090, 3110, 3134, 3135, 3136, 3150, 3164, 3240, 3241, 3242, 3260, 3261, 3275, 3288, 3654, 3655, 3669, 3777, 3778, 3779, 3780, 3781, 3782, 3783, 3784, 3785, 3786, 3787, 3788, 3815, 3816, 3835, 3836, 3837, 3854, 3869, 3882, 3967, 3968, 3969, 3983, 4051, 4052, 4053, 4063, 4138, 4139, 4140, 4141, 4142, 4143, 4144, 4145, 4146, 4147, 4148, 4149, 4179, 4591, 4592, 4607, 4940, 4941, 4942, 4959, 5602, 5603, 5616, 6020, 6021, 6022, 6029, 6129, 6130, 6131, 6139, 6200, 6201, 6202, 6207]} for segment: Segment[0/0]
2020-05-08 14:23:56.611 INFO 38827 — [agaProcessor]-0] o.a.e.TrackingEventProcessor : Fetched token: GapAwareTrackingToken{index=6257, gaps=[1808, 1809, 1819, 1907, 1908, 1925, 2019, 2020, 2021, 2022, 2023, 2024, 2025, 2026, 2027, 2028, 2029, 2058, 2157, 2158, 2172, 2173, 2183, 2196, 2318, 2319, 2331, 2466, 2467, 2480, 2730, 2731, 2746, 2814, 2815, 2816, 2817, 2818, 2819, 2820, 2821, 2822, 2823, 2824, 2825, 2874, 2875, 2892, 2907, 2909, 2926, 2927, 3003, 3004, 3005, 3006, 3007, 3008, 3009, 3010, 3011, 3012, 3013, 3035, 3049, 3061, 3089, 3090, 3110, 3134, 3135, 3136, 3150, 3164, 3240, 3241, 3242, 3260, 3261, 3275, 3288, 3654, 3655, 3669, 3777, 3778, 3779, 3780, 3781, 3782, 3783, 3784, 3785, 3786, 3787, 3788, 3815, 3816, 3835, 3836, 3837, 3854, 3869, 3882, 3967, 3968, 3969, 3983, 4051, 4052, 4053, 4063, 4138, 4139, 4140, 4141, 4142, 4143, 4144, 4145, 4146, 4147, 4148, 4149, 4179, 4591, 4592, 4607, 4940, 4941, 4942, 4959, 5602, 5603, 5616, 6020, 6021, 6022, 6029, 6129, 6130, 6131, 6139, 6200, 6201, 6202, 6207]} for segment: Segment[0/0]

Hi Steven,

this is nothing to worry about. Axon will at some point automatically check if the gaps are so old that they can be safely cleaned up. If I recall correctly, this happens when there are 250 gaps.

Gaps are caused because of 3 reasons:

  • transactions may have been rolled back. In that case the sequence has been increased, but the record wasn’t inserted. Typically, these are gaps that will stick around and eventually get cleaned from the token.
  • insert and commit order are different. This means that the transaction with the lowest sequence may be committed after a transaction that claimed a higher sequence. This causes the higher sequence to be visible first, and the lower sequence appears as a gap. Once that transaction also completes, the gap is detected to be committed, and the event is processed after all.
  • the sequence might be used for other tables as well. This causes gaps that don’t represent any activity in the table. These are the types of gaps that are easily avoided. It doesn’t harm if there are only a few, but the remedy is quite simple to implement.

Hope this clarifies it.
Cheers,