%%% @copyright (C) 2016, AdRoll %%% @doc %%% %%% Generic record processor with support for batching and checkpointing. %%% %%% We use an underlying 'erlmld_flusher' module to maintain the current %%% batch. When the current batch is full (according to the flusher's %%% definition of fullness), or when 'flush_interval_ms' milliseconds have %%% elapsed, we ask the flusher to flush the current batch and start a new %%% one. %%% %%% We checkpoint every 'checkpoint_interval_ms' milliseconds. After %%% 'watchdog_timeout_ms' milliseconds with no activity (after any initial %%% activity), the current process is killed. Checkpointing works by %%% keeping track of the latest record for which itself and all %%% predecessors have been flushed. For example, suppose 'process_record' %%% has been called with the following records, and the flusher has already %%% flushed the ones marked with '*': %%% %%% R1 R2 R3 R4 R5 R6 R7 R8 R9 R10 %%% * * * * * * %%% %%% Then the stream will be checkpointed at (the sequence number of) R3. %%% For the internal mechanics, see the comment in 'note_success'. %%% %%% @end %%% Created : 19 Dec 2016 by Constantin Berzan %%% based on original code by Mike Watters -module(erlmld_batch_processor). -behaviour(erlmld_worker). -export([initialize/3, ready/1, process_record/2, checkpointed/3, shutdown/2]). -include("erlmld.hrl"). -record(state, {%% Handler module implementing the flusher behavior. flusher_mod :: atom(), %% Flusher state (opaque to this module) passed to flusher_mod callbacks. flusher_state :: flusher_state(), %% Optional callback to call each time process_record returns a checkpoint. on_checkpoint :: fun((term(), shard_id()) -> term()), %% Optional, false by default. Tells whether to log or not every successful %% checkpoint from the KCL worker. log_checkpoints :: boolean(), description :: term(), shard_id :: shard_id(), count = 0, % non-ignored records seen checkpoints = 0, % checkpoints requested next_counter_checkpoint = 0, % counter value at which we can next checkpoint last_flush_time = os:timestamp(), last_checkpoint_time = os:timestamp(), checkpointable = gb_trees:empty(), % {Count, SequenceNo} flush_interval_ms, checkpoint_interval_ms, watchdog_timeout_ms, watchdog, enable_subsequence_checkpoints = false :: boolean()}). %%%=================================================================== %%% API %%%=================================================================== initialize(Opts, ShardId, ISN) -> Defaults = #{on_checkpoint => fun(_, _) -> ok end, log_checkpoints => false, description => undefined, enable_subsequence_checkpoints => false}, #{description := Description, flusher_mod := FlusherMod, flusher_mod_data := FlusherModData, on_checkpoint := OnCheckpoint, log_checkpoints := LogCheckpoints, flush_interval_ms := FlushIntervalMs, checkpoint_interval_ms := CheckpointIntervalMs, watchdog_timeout_ms := WatchdogTimeoutMs, enable_subsequence_checkpoints := EnableSubCP} = maps:merge(Defaults, Opts), State = #state{flusher_mod = FlusherMod, flusher_state = erlmld_flusher:init(FlusherMod, ShardId, FlusherModData), on_checkpoint = OnCheckpoint, log_checkpoints = LogCheckpoints, description = Description, shard_id = ShardId, flush_interval_ms = FlushIntervalMs, checkpoint_interval_ms = CheckpointIntervalMs, watchdog_timeout_ms = WatchdogTimeoutMs, enable_subsequence_checkpoints = EnableSubCP}, error_logger:info_msg("~p initialized for shard {~p,~p} at ~p~n", [self(), Description, ShardId, ISN]), {ok, update_watchdog(State)}. ready(#state{flusher_mod = FMod, flusher_state = FState} = State) -> {ok, NFState, Tokens} = erlmld_flusher:heartbeat(FMod, FState), NState = flusher_state(State, NFState), NNState = case Tokens of [] -> NState; _ -> note_success(note_flush(NState), Tokens) end, maybe_checkpoint(update_watchdog(NNState)). process_record(#state{last_flush_time = LastFlush, flush_interval_ms = FlushInterval} = State, Record) -> {ok, NState} = case {add_record(State, Record), elapsed_ms(LastFlush)} of {{ok, State1}, E} when E >= FlushInterval -> {ok, flush(State1)}; {{ok, State1}, _} -> {ok, State1}; {{error, full}, _} -> add_record(flush(State), Record) end, maybe_checkpoint(update_watchdog(NState)). checkpointed(#state{log_checkpoints = LogCheckpoints} = State, SequenceNumber, Checkpoint) -> case LogCheckpoints of true -> error_logger:info_msg("~p checkpointed at ~p (~p)~n", [State, Checkpoint, SequenceNumber]); false -> ok end, {ok, State}. shutdown(#state{description = Description, shard_id = ShardId, count = Count} = State, Reason) -> error_logger:info_msg("{~p,~p} (~p) shutting down, reason: ~p~n", [Description, ShardId, Count, Reason]), case Reason of zombie -> %% we lost our lease, nothing else to do now. ok; terminate -> %% the shard is closing (e.g., as a result of a merge or split). we should %% flush all outstanding data and checkpoint. NState = flush_full(State), case next_checkpoint(NState) of %% we flushed all items and are able to checkpoint. there shouldn't be %% any more items left to checkpoint: {CPState, CPSN} -> error_logger:info_msg("{~p,~p} will checkpoint at ~p~n", [Description, ShardId, CPSN]), Remaining = checkpointable(CPState), Remaining = gb_trees:empty(), {ok, #checkpoint{sequence_number = CPSN}}; %% nothing was checkpointable. there shouldn't be any items left to %% checkpoint: undefined -> error_logger:info_msg("{~p,~p} has nothing to checkpoint, will use latest~n", [Description, ShardId]), Remaining = checkpointable(NState), Remaining = gb_trees:empty(), %% we checkpoint with an empty sequence number. this will cause the %% KCL to checkpoint at the most recent record it has seen on the %% shard: {ok, #checkpoint{}} end end. %%%=================================================================== %%% Internal functions %%%=================================================================== incr_count(#state{count = Count} = State) -> State#state{count = Count + 1}. incr_checkpoints(#state{checkpoints = Count} = State) -> State#state{checkpoints = Count + 1}. checkpointable(#state{checkpointable = CPT}) -> CPT. checkpointable(State, CPT) -> State#state{checkpointable = CPT}. next_counter_checkpoint(State, N) -> State#state{next_counter_checkpoint = N}. flusher_state(State, FState) -> State#state{flusher_state = FState}. add_record(#state{count = Count, flusher_mod = FMod, flusher_state = FState} = State, #stream_record{sequence_number = SN} = Record) -> case erlmld_flusher:add_record(FMod, FState, Record, {Count, SN}) of {ok, NFState} -> {ok, incr_count(flusher_state(State, NFState))}; {ignored, NFState} -> {ok, flusher_state(State, NFState)}; {error, full} -> {error, full} end. flush(State) -> flush(State, partial). flush_full(State) -> flush(State, full). flush(#state{flusher_mod = FMod, flusher_state = FState} = State, Kind) -> {ok, NFState, Tokens} = erlmld_flusher:flush(FMod, FState, Kind), NState = flusher_state(State, NFState), note_success(note_flush(NState), Tokens). note_success(#state{checkpointable = CPT} = State, Tokens) -> %% The items with the given Tokens have been successfully processed. %% Update the 'checkpointable' gb_tree, which we are using as a priority %% queue. When the time comes to checkpoint, we pop items until the next %% smallest item has a discontiguous id, then checkpoint at the sequence %% number corresponding to the most recently-popped item. This way, we can %% do time-based checkpointing without forcing a flush of the current %% pending batch. %% %% fixme; when adding a new element, also pop all smaller elements which have %% contiguous keys with the new element (only need to track gaps). NCPT = lists:foldl(fun({Counter, SeqNum}, Acc) -> gb_trees:insert(Counter, SeqNum, Acc) end, CPT, Tokens), checkpointable(State, NCPT). maybe_checkpoint(#state{last_checkpoint_time = LastCheckpoint, checkpoint_interval_ms = CheckpointInterval} = State) -> case elapsed_ms(LastCheckpoint) of N when N >= CheckpointInterval -> case next_checkpoint(State) of {NState, SequenceNumber} -> {ok, note_checkpoint(NState), #checkpoint{sequence_number = SequenceNumber}}; undefined -> {ok, State} end; _ -> {ok, State} end. %% given a state, return undefined if nothing is ready to be checkpointed. otherwise, %% return {NState, SeqNo}, where SeqNo is a #sequence_number{} at which we can checkpoint %% (i.e., all items below that SN have been successfully processed), and NState represents %% the state after checkpointing. next_checkpoint(State) -> CPT = checkpointable(State), case gb_trees:is_empty(CPT) of true -> undefined; false -> next_checkpoint(State, gb_trees:take_smallest(CPT), undefined) end. next_checkpoint(State, {SmallestCount, _, _} = SmallestItem, LatestFinished) -> next_checkpoint(State, SmallestCount, SmallestItem, LatestFinished). %% in order to checkpoint, the smallest tree element must have a key whose value is equal %% to the `next_counter_checkpoint` field; otherwise, we can't checkpoint yet (we have an %% initial gap). next_checkpoint(#state{next_counter_checkpoint = N}, FirstSmallestCount, _, _) when FirstSmallestCount > N -> undefined; %% if subsequence checkpointing is disabled, we can only checkpoint at a record which has %% been fully processed. while advancing through contiguous items, we keep track of the %% highest-numbered item corresponding to a completely-processed record (which may be %% undefined). next_checkpoint(#state{enable_subsequence_checkpoints = EnableSubCP} = State, FirstSmallestCount, {SmallestCount, SmallestSN, CPT}, LatestFinished) -> %% can checkpoint at SmallestSN if subsequence checkpointing is enabled, or if it %% corresponds to the last subrecord in an aggregate record, or if it corresponds to a %% non-aggregate record: CanCheckpoint = EnableSubCP orelse not is_sub_record(SmallestSN), %% if we can checkpoint at the current SN, use it as the latest 'finished' value: NLatestFinished = case CanCheckpoint of true -> {next_counter_checkpoint(checkpointable(State, CPT), SmallestCount + 1), SmallestSN}; false -> LatestFinished end, case gb_trees:is_empty(CPT) of true -> NLatestFinished; false -> NextContiguous = SmallestCount + 1, case gb_trees:take_smallest(CPT) of {NextContiguous, _, _} = Next -> next_checkpoint(State, FirstSmallestCount, Next, NLatestFinished); _ -> NLatestFinished end end. note_checkpoint(#state{description = Description, shard_id = ShardId, on_checkpoint = OnCheckpoint} = State) -> OnCheckpoint(Description, ShardId), incr_checkpoints(State#state{last_checkpoint_time = os:timestamp()}). note_flush(State) -> State#state{last_flush_time = os:timestamp()}. %% given an erlang timestamp, return the elapsed duration in milliseconds. elapsed_ms(When) -> timer:now_diff( os:timestamp(), When) div 1000. %% start a watchdog timer, cancelling any which is outstanding. if the timer fires, it %% will result in the current process exiting with a reason of 'watchdog_timeout' update_watchdog(#state{watchdog_timeout_ms = undefined} = State) -> State; update_watchdog(#state{watchdog_timeout_ms = WatchdogTimeout, watchdog = Watchdog} = State) -> case Watchdog of undefined -> ok; _ -> timer:cancel(Watchdog) end, {ok, Ref} = timer:exit_after(WatchdogTimeout, watchdog_timeout), State#state{watchdog = Ref}. %% We use user_sub here instead of sub: for KPL records, those values will be %% the same. For our own KPL-like protocol user_sub will be filled in, and %% in other use cases it will be undefined. In both of these last cases sub %% will be the original KCL sent (0, possible) so it can't be really used to %% know if this is a subrecord or not. is_sub_record(#sequence_number{user_sub = Sub, user_total = Total}) when is_integer(Sub) andalso is_integer(Total) andalso Sub < Total - 1 -> true; is_sub_record(_) -> false. %%%=================================================================== %%% TESTS %%%=================================================================== -ifdef(TEST). -include_lib("eunit/include/eunit.hrl"). equal_cpt(A, B) -> maps:from_list( gb_trees:to_list(checkpointable(A))) == maps:from_list( gb_trees:to_list(checkpointable(B))). checkpointing_test() -> State = #state{}, ?assertEqual(undefined, next_checkpoint(State)), %% items 0, 1, and 3 completed and checkpointable: CPT0 = gb_trees:insert(0, 0, gb_trees:insert(1, 1, gb_trees:insert(3, 3, gb_trees:empty()))), Expected1 = checkpointable(State, CPT0), State1 = note_success(State, [{0, 0}, {1, 1}, {3, 3}]), ?assert(equal_cpt(Expected1, State1)), %% the initial checkpoint should only cover items 0-1 due to the gap (2 not %% checkpointable yet), so item 3 should still be 'checkpointable': CPT1 = gb_trees:delete(0, gb_trees:delete(1, CPT0)), AfterCheckpoint1 = next_counter_checkpoint(checkpointable(State, CPT1), 2), ?assertEqual({AfterCheckpoint1, 1}, next_checkpoint(State1)), %% after completing item 2, the next checkpoint should be at sequence number 3, %% because the gap between successfully-processed items has been closed: CPT2 = gb_trees:insert(2, 2, CPT1), Expected2 = checkpointable(AfterCheckpoint1, CPT2), State2 = note_success(AfterCheckpoint1, [{2, 2}]), ?assert(equal_cpt(Expected2, State2)), AfterCheckpoint2 = next_counter_checkpoint(checkpointable(AfterCheckpoint1, gb_trees:empty()), 4), ?assertEqual({AfterCheckpoint2, 3}, next_checkpoint(State2)). checkpointing_subrecord_test() -> State = #state{enable_subsequence_checkpoints = false}, ?assertEqual(undefined, next_checkpoint(State)), SN0 = #sequence_number{user_sub = 0, user_total = 3}, SN1 = #sequence_number{user_sub = 1, user_total = 3}, SN2 = #sequence_number{user_sub = 2, user_total = 3}, SN3 = #sequence_number{}, %% items 0 and 2 completed and checkpointable, but not all subrecords have completed, %% so we can't checkpoint yet: State1 = note_success(State, [{0, SN0}, {2, SN2}]), ?assertEqual(undefined, next_checkpoint(State1)), %% item 1 is the last pending subrecord in an aggregate record, and so item 2 should %% be the next checkpoint: State2 = note_success(State1, [{1, SN1}]), {State3, SN2} = next_checkpoint(State2), %% item 3 is not a subrecord, so is checkpointable: State4 = note_success(State3, [{3, SN3}]), {_State5, SN3} = next_checkpoint(State4), %% if subsequence checkpointing is enabled, we can checkpoint at subrecords: State6 = State#state{enable_subsequence_checkpoints = true}, State7 = note_success(State6, [{0, SN0}, {2, SN2}]), {State8, SN0} = next_checkpoint(State7), State9 = note_success(State8, [{1, SN1}]), {_State10, SN2} = next_checkpoint(State9). watchdog_test() -> process_flag(trap_exit, true), State = update_watchdog(#state{watchdog_timeout_ms = 200}), receive {'EXIT', _, watchdog_timeout} -> error("unexpected watchdog trigger") after 100 -> ok end, update_watchdog(State), receive {'EXIT', _, watchdog_timeout} -> ok after 400 -> error("watchdog failed to trigger") end. is_sub_record_test() -> ?assertEqual(true, is_sub_record(#sequence_number{user_sub = 0, user_total = 2})), ?assertEqual(false, is_sub_record(#sequence_number{user_sub = 1, user_total = 2})), ?assertEqual(false, is_sub_record(#sequence_number{user_sub = undefined, user_total = undefined})). -endif.