From 676e8fa4949b294d55d14ee5261a6de1c2e91763 Mon Sep 17 00:00:00 2001 From: Martin Sumner Date: Thu, 22 Dec 2016 15:45:38 +0000 Subject: [PATCH] Add Get Timing --- src/leveled_bookie.erl | 26 +++++++++++----- src/leveled_cdb.erl | 2 +- src/leveled_inker.erl | 2 +- src/leveled_log.erl | 65 +++++++++++++++++++++++++++++---------- src/leveled_penciller.erl | 4 +-- 5 files changed, 71 insertions(+), 28 deletions(-) diff --git a/src/leveled_bookie.erl b/src/leveled_bookie.erl index af0f102..90a0b2a 100644 --- a/src/leveled_bookie.erl +++ b/src/leveled_bookie.erl @@ -162,7 +162,8 @@ ledger_cache = #ledger_cache{}, is_snapshot :: boolean(), slow_offer = false :: boolean(), - put_timing :: tuple()}). + put_timing :: tuple(), + get_timing :: tuple()}). %%%============================================================================ @@ -278,7 +279,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, - PutTimes = leveled_log:put_timings(bookie, State#state.put_timing, T0, T1), + PutTimes = leveled_log:put_timing(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 @@ -303,26 +304,35 @@ handle_call({put, Bucket, Key, Object, IndexSpecs, Tag, TTL}, From, State) -> end; handle_call({get, Bucket, Key, Tag}, _From, State) -> LedgerKey = leveled_codec:to_ledgerkey(Bucket, Key, Tag), + SWh = os:timestamp(), case fetch_head(LedgerKey, State#state.penciller, State#state.ledger_cache) of not_present -> - {reply, not_found, State}; + GT0 = leveled_log:get_timing(State#state.get_timing, + SWh, + head_not_present), + {reply, not_found, State#state{get_timing=GT0}}; Head -> + GT0 = leveled_log:get_timing(State#state.get_timing, + SWh, + head_found), + SWg = os:timestamp(), {Seqn, Status, _MH, _MD} = leveled_codec:striphead_to_details(Head), case Status of tomb -> {reply, not_found, State}; {active, TS} -> Active = TS >= leveled_codec:integer_now(), - case {Active, - fetch_value(LedgerKey, Seqn, State#state.inker)} of + Object = fetch_value(LedgerKey, Seqn, State#state.inker), + GT1 = leveled_log:get_timing(GT0, SWg, fetch), + case {Active, Object} of {_, not_present} -> - {reply, not_found, State}; + {reply, not_found, State#state{get_timing=GT1}}; {true, Object} -> - {reply, {ok, Object}, State}; + {reply, {ok, Object}, State#state{get_timing=GT1}}; _ -> - {reply, not_found, State} + {reply, not_found, State#state{get_timing=GT1}} end end end; diff --git a/src/leveled_cdb.erl b/src/leveled_cdb.erl index 816e43c..0c0f745 100644 --- a/src/leveled_cdb.erl +++ b/src/leveled_cdb.erl @@ -278,7 +278,7 @@ writer({put_kv, Key, Value}, _From, State) -> ok end, T1 = timer:now_diff(os:timestamp(), SW) - T0, - Timings = leveled_log:put_timings(journal, + Timings = leveled_log:put_timing(journal, State#state.put_timing, T0, T1), {reply, ok, writer, State#state{handle=UpdHandle, diff --git a/src/leveled_inker.erl b/src/leveled_inker.erl index 7fa7a25..f56ea20 100644 --- a/src/leveled_inker.erl +++ b/src/leveled_inker.erl @@ -426,7 +426,7 @@ put_object(LedgerKey, Object, KeyChanges, State) -> JournalBin) of ok -> T1 = timer:now_diff(os:timestamp(), SW) - T0, - UpdPutTimes = leveled_log:put_timings(inker, + UpdPutTimes = leveled_log:put_timing(inker, State#state.put_timing, T0, T1), {ok, diff --git a/src/leveled_log.erl b/src/leveled_log.erl index 67151cc..4b87108 100644 --- a/src/leveled_log.erl +++ b/src/leveled_log.erl @@ -9,11 +9,13 @@ -export([log/2, log_timer/3, - put_timings/4, - head_timings/4]). + put_timing/4, + head_timing/4, + get_timing/3]). --define(PUT_TIMING_LOGPOINT, 10000). +-define(PUT_TIMING_LOGPOINT, 20000). -define(HEAD_TIMING_LOGPOINT, 100000). +-define(GET_TIMING_LOGPOINT, 50000). -define(LOG_LEVEL, [info, warn, error, critical]). -define(LOGBASE, dict:from_list([ @@ -50,6 +52,8 @@ ++ "and max inker time is ~w and max ledger time is ~w"}}, {"B0013", {warn, "Long running task took ~w microseconds with task of type ~w"}}, + {"B0014", + {info, "Get timing for result ~w is count ~w total ~w and max ~w"}}, {"P0001", {info, "Ledger snapshot ~w registered"}}, @@ -328,9 +332,9 @@ log_timer(LogReference, Subs, StartTime) -> %% Make a log of put timings split out by actor - one log for every %% PUT_TIMING_LOGPOINT puts -put_timings(_Actor, undefined, T0, T1) -> +put_timing(_Actor, undefined, T0, T1) -> {1, {T0, T1}, {T0, T1}}; -put_timings(Actor, {?PUT_TIMING_LOGPOINT, {Total0, Total1}, {Max0, Max1}}, T0, T1) -> +put_timing(Actor, {?PUT_TIMING_LOGPOINT, {Total0, Total1}, {Max0, Max1}}, T0, T1) -> LogRef = case Actor of bookie -> "B0012"; @@ -338,19 +342,19 @@ put_timings(Actor, {?PUT_TIMING_LOGPOINT, {Total0, Total1}, {Max0, Max1}}, T0, T journal -> "CDB17" end, log(LogRef, [?PUT_TIMING_LOGPOINT, Total0, Total1, Max0, Max1]), - put_timings(Actor, undefined, T0, T1); -put_timings(_Actor, {N, {Total0, Total1}, {Max0, Max1}}, T0, T1) -> + put_timing(Actor, undefined, T0, T1); +put_timing(_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) -> +head_timing(HeadTimer, SW, Level, R) -> T0 = timer:now_diff(os:timestamp(), SW), - head_timings_int(HeadTimer, T0, Level, R). + head_timing_int(HeadTimer, T0, Level, R). -head_timings_int(undefined, T0, Level, R) -> +head_timing_int(undefined, T0, Level, R) -> Key = head_key(R, Level), NewDFun = fun(K, Acc) -> case K of @@ -360,11 +364,11 @@ head_timings_int(undefined, T0, Level, R) -> 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) -> +head_timing_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) -> + head_timing_int(undefined, T0, Level, R); +head_timing_int({N, HeadTimingD}, T0, Level, R) -> Key = head_key(R, Level), [Count0, Total0, Max0] = dict:fetch(Key, HeadTimingD), {N + 1, @@ -385,6 +389,35 @@ head_key(found, Level) when Level > 2 -> head_keylist() -> [not_present, found_lower, found_0, found_1, found_2]. +get_timing(GetTimer, SW, TimerType) -> + T0 = timer:now_diff(os:timestamp(), SW), + get_timing_int(GetTimer, T0, TimerType). + +get_timing_int(undefined, T0, TimerType) -> + NewDFun = fun(K, Acc) -> + case K of + TimerType -> + dict:store(K, [1, T0, T0], Acc); + _ -> + dict:store(K, [0, 0, 0], Acc) + end end, + {1, lists:foldl(NewDFun, dict:new(), get_keylist())}; +get_timing_int({?GET_TIMING_LOGPOINT, GetTimerD}, T0, TimerType) -> + LogFun = fun(K) -> log("B0014", [K|dict:fetch(K, GetTimerD)]) end, + lists:foreach(LogFun, get_keylist()), + get_timing_int(undefined, T0, TimerType); +get_timing_int({N, GetTimerD}, T0, TimerType) -> + [Count0, Total0, Max0] = dict:fetch(TimerType, GetTimerD), + {N + 1, + dict:store(TimerType, + [Count0 + 1, Total0 + T0, max(Max0, T0)], + GetTimerD)}. + + + +get_keylist() -> + [head_not_present, head_found, fetch]. + %%%============================================================================ %%% Test %%%============================================================================ @@ -399,9 +432,9 @@ log_test() -> head_timing_test() -> SW = os:timestamp(), - HeadTimer0 = head_timings(undefined, SW, 2, found), - HeadTimer1 = head_timings(HeadTimer0, SW, 2, found), - HeadTimer2 = head_timings(HeadTimer1, SW, 3, found), + HeadTimer0 = head_timing(undefined, SW, 2, found), + HeadTimer1 = head_timing(HeadTimer0, SW, 2, found), + HeadTimer2 = head_timing(HeadTimer1, SW, 3, found), {N, D} = HeadTimer2, ?assertMatch(3, N), ?assertMatch(2, lists:nth(1, dict:fetch(found_2, D))), diff --git a/src/leveled_penciller.erl b/src/leveled_penciller.erl index 689a701..0de9b2b 100644 --- a/src/leveled_penciller.erl +++ b/src/leveled_penciller.erl @@ -739,9 +739,9 @@ timed_fetch_mem(Key, Hash, Manifest, L0Cache, L0Index, HeadTimer) -> UpdHeadTimer = case R of not_present -> - leveled_log:head_timings(HeadTimer, SW, Level, not_present); + leveled_log:head_timing(HeadTimer, SW, Level, not_present); _ -> - leveled_log:head_timings(HeadTimer, SW, Level, found) + leveled_log:head_timing(HeadTimer, SW, Level, found) end, {R, UpdHeadTimer}.