From 130fb36ddd428ccc33c3ad21796f5660427a4bde Mon Sep 17 00:00:00 2001 From: martinsumner Date: Thu, 22 Dec 2016 14:03:31 +0000 Subject: [PATCH] Add head timings Include log breaking down timings of HEAD requests by result and level --- src/leveled_bookie.erl | 19 ++++-------- src/leveled_cdb.erl | 13 ++------ src/leveled_inker.erl | 15 +++------ src/leveled_log.erl | 65 +++++++++++++++++++++++++++++++++++++-- src/leveled_penciller.erl | 48 +++++++++++++++++++---------- 5 files changed, 108 insertions(+), 52 deletions(-) diff --git a/src/leveled_bookie.erl b/src/leveled_bookie.erl index e058c5b..cdc39ff 100644 --- a/src/leveled_bookie.erl +++ b/src/leveled_bookie.erl @@ -150,7 +150,7 @@ -define(CHECKJOURNAL_PROB, 0.2). -define(CACHE_SIZE_JITTER, 25). -define(JOURNAL_SIZE_JITTER, 20). --define(PUT_TIMING_LOGPOINT, 10000). +-define(LONG_RUNNING, 80000). -record(ledger_cache, {skiplist = leveled_skiplist:empty(true) :: tuple(), min_sqn = infinity :: integer()|infinity, @@ -278,7 +278,7 @@ handle_call({put, Bucket, Key, Object, IndexSpecs, Tag, TTL}, From, State) -> {IndexSpecs, TTL}), Cache0 = addto_ledgercache(Changes, State#state.ledger_cache), T1 = timer:now_diff(os:timestamp(), SW) - T0, - PutTimings = update_put_timings(State#state.put_timing, T0, T1), + PutTimes = leveled_log:put_timings(bookie, State#state.put_timing, T0, T1), % If the previous push to memory was returned then punish this PUT with a % delay. If the back-pressure in the Penciller continues, these delays % will beocme more frequent @@ -294,11 +294,11 @@ handle_call({put, Bucket, Key, Object, IndexSpecs, Tag, TTL}, From, State) -> State#state.penciller) of {ok, NewCache} -> {noreply, State#state{ledger_cache=NewCache, - put_timing=PutTimings, + put_timing=PutTimes, slow_offer=false}}; {returned, NewCache} -> {noreply, State#state{ledger_cache=NewCache, - put_timing=PutTimings, + put_timing=PutTimes, slow_offer=true}} end; handle_call({get, Bucket, Key, Tag}, _From, State) -> @@ -465,23 +465,16 @@ push_ledgercache(Penciller, Cache) -> %%% Internal functions %%%============================================================================ -update_put_timings({?PUT_TIMING_LOGPOINT, {Total0, Total1}, {Max0, Max1}}, - T0, T1) -> - leveled_log:log("B0012", - [?PUT_TIMING_LOGPOINT, Total0, Total1, Max0, Max1]), - {1, {T0, T1}, {T0, T1}}; -update_put_timings({N, {Total0, Total1}, {Max0, Max1}}, T0, T1) -> - {N + 1, {Total0 + T0, Total1 + T1}, {max(Max0, T0), max(Max1, T1)}}. + maybe_longrunning(SW, Aspect) -> case timer:now_diff(os:timestamp(), SW) of - N when N > 80000 -> + N when N > ?LONG_RUNNING -> leveled_log:log("B0013", [N, Aspect]); _ -> ok end. - cache_size(LedgerCache) -> leveled_skiplist:size(LedgerCache#ledger_cache.skiplist). diff --git a/src/leveled_cdb.erl b/src/leveled_cdb.erl index 2501098..66c528c 100644 --- a/src/leveled_cdb.erl +++ b/src/leveled_cdb.erl @@ -95,7 +95,6 @@ -define(WRITE_OPS, [binary, raw, read, write]). -define(PENDING_ROLL_WAIT, 30). -define(DELETE_TIMEOUT, 10000). --define(PUT_TIMING_LOGPOINT, 10000). -record(state, {hashtree, last_position :: integer(), @@ -279,7 +278,9 @@ writer({put_kv, Key, Value}, _From, State) -> ok end, T1 = timer:now_diff(os:timestamp(), SW) - T0, - Timings = update_put_timings(State#state.put_timing, T0, T1), + Timings = leveled_log:put_timings(journal, + State#state.put_timing, + T0, T1), {reply, ok, writer, State#state{handle=UpdHandle, last_position=NewPosition, last_key=Key, @@ -779,14 +780,6 @@ hashtable_calc(HashTree, StartPos) -> %% Internal functions %%%%%%%%%%%%%%%%%%%% -update_put_timings({?PUT_TIMING_LOGPOINT, {Total0, Total1}, {Max0, Max1}}, - T0, T1) -> - leveled_log:log("CDB17", - [?PUT_TIMING_LOGPOINT, Total0, Total1, Max0, Max1]), - {1, {T0, T1}, {T0, T1}}; -update_put_timings({N, {Total0, Total1}, {Max0, Max1}}, T0, T1) -> - {N + 1, {Total0 + T0, Total1 + T1}, {max(Max0, T0), max(Max1, T1)}}. - determine_new_filename(Filename) -> filename:rootname(Filename, ".pnd") ++ ".cdb". diff --git a/src/leveled_inker.erl b/src/leveled_inker.erl index 4908351..df3c33a 100644 --- a/src/leveled_inker.erl +++ b/src/leveled_inker.erl @@ -126,7 +126,6 @@ -define(PENDING_FILEX, "pnd"). -define(LOADING_PAUSE, 1000). -define(LOADING_BATCH, 1000). --define(PUT_TIMING_LOGPOINT, 10000). -record(state, {manifest = [] :: list(), manifest_sqn = 0 :: integer(), @@ -427,9 +426,11 @@ put_object(LedgerKey, Object, KeyChanges, State) -> JournalBin) of ok -> T1 = timer:now_diff(os:timestamp(), SW) - T0, - UpdPutTimings = update_put_timings(State#state.put_timing, T0, T1), + UpdPutTimes = leveled_log:put_timings(inker, + State#state.put_timing, + T0, T1), {ok, - State#state{journal_sqn=NewSQN, put_timing=UpdPutTimings}, + State#state{journal_sqn=NewSQN, put_timing=UpdPutTimes}, byte_size(JournalBin)}; roll -> SWroll = os:timestamp(), @@ -750,14 +751,6 @@ initiate_penciller_snapshot(Bookie) -> MaxSQN = leveled_penciller:pcl_getstartupsequencenumber(LedgerSnap), {LedgerSnap, MaxSQN}. -update_put_timings({?PUT_TIMING_LOGPOINT, {Total0, Total1}, {Max0, Max1}}, - T0, T1) -> - leveled_log:log("I0019", - [?PUT_TIMING_LOGPOINT, Total0, Total1, Max0, Max1]), - {1, {T0, T1}, {T0, T1}}; -update_put_timings({N, {Total0, Total1}, {Max0, Max1}}, T0, T1) -> - {N + 1, {Total0 + T0, Total1 + T1}, {max(Max0, T0), max(Max1, T1)}}. - %%%============================================================================ %%% Test diff --git a/src/leveled_log.erl b/src/leveled_log.erl index 225c113..1c6d5ad 100644 --- a/src/leveled_log.erl +++ b/src/leveled_log.erl @@ -8,9 +8,14 @@ -include_lib("eunit/include/eunit.hrl"). -export([log/2, - log_timer/3]). + log_timer/3, + put_timings/4, + head_timings/4]). +-define(PUT_TIMING_LOGPOINT, 10000). +-define(HEAD_TIMING_LOGPOINT, 10000). -define(LOG_LEVEL, [info, warn, error, critical]). + -define(LOGBASE, dict:from_list([ {"G0001", @@ -111,6 +116,8 @@ {warn, "We're doomed - intention recorded to destroy all files"}}, {"P0031", {info, "Completion of update to levelzero"}}, + {"P0032", + {info, "Head timing for result ~w is count ~w total ~w and max ~w"}}, {"PC001", {info, "Penciller's clerk ~w started with owner ~w"}}, @@ -226,7 +233,7 @@ {"SFT03", {info, "File creation of L0 file ~s"}}, {"SFT04", - {info, "File ~s prompting for delete status check"}}, + {debug, "File ~s prompting for delete status check"}}, {"SFT05", {info, "Exit called for reason ~w on filename ~s"}}, {"SFT06", @@ -318,9 +325,63 @@ log_timer(LogReference, Subs, StartTime) -> ok end. +%% Make a log of put timings split out by actor - one log for every +%% PUT_TIMING_LOGPOINT puts +put_timings(Actor, {?PUT_TIMING_LOGPOINT, {Total0, Total1}, {Max0, Max1}}, T0, T1) -> + LogRef = + case Actor of + bookie -> "B0012"; + inker -> "I0019"; + journal -> "CDB17" + end, + log(LogRef, [?PUT_TIMING_LOGPOINT, Total0, Total1, Max0, Max1]), + {1, {T0, T1}, {T0, T1}}; +put_timings(_Actor, {N, {Total0, Total1}, {Max0, Max1}}, T0, T1) -> + {N + 1, {Total0 + T0, Total1 + T1}, {max(Max0, T0), max(Max1, T1)}}. +%% Make a log of penciller head timings split out by level and result - one +%% log for every HEAD_TIMING_LOGPOINT puts +%% Returns a tuple of {Count, TimingDict} to be stored on the process state +head_timings(HeadTimer, SW, Level, R) -> + T0 = timer:now_diff(os:timestamp(), SW), + head_timings_int(HeadTimer, T0, Level, R). + +head_timings_int(undefined, T0, Level, R) -> + Key = head_key(R, Level), + NewDFun = fun(K, Acc) -> + case K of + Key -> + dict:store(K, [1, T0, T0], Acc); + _ -> + dict:store(K, [0, 0, 0], Acc) + end end, + {1, lists:foldl(NewDFun, dict:new(), head_keylist())}; +head_timings_int({?HEAD_TIMING_LOGPOINT, HeadTimingD}, T0, Level, R) -> + LogFun = fun(K) -> log("P0032", [K|dict:fetch(K, HeadTimingD)]) end, + lists:foreach(LogFun, head_keylist()), + head_timings_int(undefined, T0, Level, R); +head_timings_int({N, HeadTimingD}, T0, Level, R) -> + Key = head_key(R, Level), + [Count0, Total0, Max0] = dict:fetch(Key, HeadTimingD), + {N + 1, + dict:store(Key, [Count0 + 1, Total0 + T0, max(Max0, T0)], + HeadTimingD)}. + +head_key(not_present, _Level) -> + not_present; +head_key(found, 0) -> + found_0; +head_key(found, 1) -> + found_1; +head_key(found, 2) -> + found_2; +head_key(found, Level) when Level > 2 -> + found_lower. + +head_keylist() -> + [not_present, found_lower, found_0, found_1, found_2]. %%%============================================================================ %%% Test diff --git a/src/leveled_penciller.erl b/src/leveled_penciller.erl index ad13bfc..689a701 100644 --- a/src/leveled_penciller.erl +++ b/src/leveled_penciller.erl @@ -228,7 +228,9 @@ levelzero_astree :: list(), ongoing_work = [] :: list(), - work_backlog = false :: boolean()}). + work_backlog = false :: boolean(), + + head_timing :: tuple()}). %%%============================================================================ @@ -367,20 +369,20 @@ handle_call({push_mem, {PushedTree, MinSQN, MaxSQN}}, State)} end; handle_call({fetch, Key, Hash}, _From, State) -> - {reply, - fetch_mem(Key, - Hash, - State#state.manifest, - State#state.levelzero_cache, - State#state.levelzero_index), - State}; + {R, HeadTimer} = timed_fetch_mem(Key, + Hash, + State#state.manifest, + State#state.levelzero_cache, + State#state.levelzero_index, + State#state.head_timing), + {reply, R, State#state{head_timing=HeadTimer}}; handle_call({check_sqn, Key, Hash, SQN}, _From, State) -> {reply, - compare_to_sqn(fetch_mem(Key, - Hash, - State#state.manifest, - State#state.levelzero_cache, - State#state.levelzero_index), + compare_to_sqn(plain_fetch_mem(Key, + Hash, + State#state.manifest, + State#state.levelzero_cache, + State#state.levelzero_index), SQN), State}; handle_call({fetch_keys, StartKey, EndKey, AccFun, InitAcc, MaxKeys}, @@ -731,7 +733,21 @@ levelzero_filename(State) -> ++ integer_to_list(MSN) ++ "_0_0", FileName. +timed_fetch_mem(Key, Hash, Manifest, L0Cache, L0Index, HeadTimer) -> + SW = os:timestamp(), + {R, Level} = fetch_mem(Key, Hash, Manifest, L0Cache, L0Index), + UpdHeadTimer = + case R of + not_present -> + leveled_log:head_timings(HeadTimer, SW, Level, not_present); + _ -> + leveled_log:head_timings(HeadTimer, SW, Level, found) + end, + {R, UpdHeadTimer}. +plain_fetch_mem(Key, Hash, Manifest, L0Cache, L0Index) -> + R = fetch_mem(Key, Hash, Manifest, L0Cache, L0Index), + element(1, R). fetch_mem(Key, Hash, Manifest, L0Cache, none) -> L0Check = leveled_pmem:check_levelzero(Key, Hash, L0Cache), @@ -739,7 +755,7 @@ fetch_mem(Key, Hash, Manifest, L0Cache, none) -> {false, not_found} -> fetch(Key, Hash, Manifest, 0, fun timed_sft_get/3); {true, KV} -> - KV + {KV, 0} end; fetch_mem(Key, Hash, Manifest, L0Cache, L0Index) -> case leveled_pmem:check_index(Hash, L0Index) of @@ -750,7 +766,7 @@ fetch_mem(Key, Hash, Manifest, L0Cache, L0Index) -> end. fetch(_Key, _Hash, _Manifest, ?MAX_LEVELS + 1, _FetchFun) -> - not_present; + {not_present, basement}; fetch(Key, Hash, Manifest, Level, FetchFun) -> LevelManifest = get_item(Level, Manifest, []), case lists:foldl(fun(File, Acc) -> @@ -771,7 +787,7 @@ fetch(Key, Hash, Manifest, Level, FetchFun) -> not_present -> fetch(Key, Hash, Manifest, Level + 1, FetchFun); ObjectFound -> - ObjectFound + {ObjectFound, Level} end end.