From 88c233f9119ae70ae93b5cbfdb8dc3f2a5722c30 Mon Sep 17 00:00:00 2001 From: Ulf Wiger Date: Fri, 30 Nov 2018 10:30:50 +0100 Subject: [PATCH 1/3] dynamically check log_level --- src/leveled_log.erl | 25 +++++++++++++++++++------ 1 file changed, 19 insertions(+), 6 deletions(-) diff --git a/src/leveled_log.erl b/src/leveled_log.erl index d48c597..9647c9b 100644 --- a/src/leveled_log.erl +++ b/src/leveled_log.erl @@ -11,7 +11,9 @@ log_timer/3, log_randomtimer/4]). --define(LOG_LEVEL, [info, warn, error, critical]). +-define(LOG_LEVEL, [debug, info, warn, error, critical]). + +-define(DEFAULT_LOG_LEVEL, error). -define(LOGBASE, [ @@ -377,12 +379,12 @@ log(LogReference, Subs) -> log(LogRef, Subs, SupportedLogLevels) -> case lists:keyfind(LogRef, 1, ?LOGBASE) of {LogRef, {LogLevel, LogText}} -> - case lists:member(LogLevel, SupportedLogLevels) of + case should_i_log(LogLevel, SupportedLogLevels) of true -> io:format(format_time() - ++ " " ++ LogRef ++ " ~w " - ++ LogText ++ "~n", - [self()|Subs]); + ++ " " ++ LogRef ++ " ~w " + ++ LogText ++ "~n", + [self()|Subs]); false -> ok end; @@ -390,6 +392,17 @@ log(LogRef, Subs, SupportedLogLevels) -> ok end. +should_i_log(LogLevel, Levels) -> + case application:get_env(leveled, log_level, ?DEFAULT_LOG_LEVEL) of + LogLevel -> true; + CurLevel -> + is_active_level(Levels, CurLevel, LogLevel) + end. + +is_active_level([L|_], L, _) -> true; +is_active_level([L|_], _, L) -> false; +is_active_level([_|T], C, L) -> is_active_level(T, C, L); +is_active_level([] , _, _) -> false. log_timer(LogReference, Subs, StartTime) -> log_timer(LogReference, Subs, StartTime, ?LOG_LEVEL). @@ -397,7 +410,7 @@ log_timer(LogReference, Subs, StartTime) -> log_timer(LogRef, Subs, StartTime, SupportedLogLevels) -> case lists:keyfind(LogRef, 1, ?LOGBASE) of {LogRef, {LogLevel, LogText}} -> - case lists:member(LogLevel, SupportedLogLevels) of + case should_i_log(LogLevel, SupportedLogLevels) of true -> MicroS = timer:now_diff(os:timestamp(), StartTime), {Unit, Time} = case MicroS of From 578a9f88e0264237817fe6072b70a1f423a09104 Mon Sep 17 00:00:00 2001 From: Martin Sumner Date: Wed, 5 Dec 2018 00:17:39 +0000 Subject: [PATCH 2/3] Support for log settings at startup Both log level and forced_logs. Allows for log_level to be changed at startup ad runtime. Also allow for a list of forced logs, so if log_level is set > info, individual info logs can be forced to be seen (such as to see stats logs). --- docs/STARTUP_OPTIONS.md | 12 ++++++++- src/leveled_bookie.erl | 33 ++++++++++++++++++++++-- src/leveled_log.erl | 45 +++++++++++++++++++++++++-------- test/end_to_end/basic_SUITE.erl | 17 +++++++++++-- 4 files changed, 92 insertions(+), 15 deletions(-) diff --git a/docs/STARTUP_OPTIONS.md b/docs/STARTUP_OPTIONS.md index 6214c88..a8d7998 100644 --- a/docs/STARTUP_OPTIONS.md +++ b/docs/STARTUP_OPTIONS.md @@ -12,11 +12,21 @@ This mode was specifically added to support Leveled's use as a dedicated aae_sto There is no current support for running leveled so that it supports both `head` objects which are stored entirely in the Ledger, along side other objects stored as normal split between the Journal and the Ledger. Setting `head_only` fundamentally changes the way the store works. +## Log Level + +The log level can be set to `debug`, `info`, `warn`, `error`, `critical`. The `info` log level will generate a significant amount of logs, and in testing this volume of logs has not currently been shown to be detrimental to performance. The log level has been set to be 'noisy' in this way to suit environments which make use of log indexers which can consume large volumes of logs, and allow operators freedom to build queries and dashboards from those indexes. + +There is no stats facility within leveled, the stats are only available from the logs. In the future, a stats facility may be added to provide access to this information without having to run at `info` log levels. [Forced Logs](#Forced Logs) may be used to add stats or other info logs selectively. + +## Forced logs + +The `forced_logs` option will force a particular log reference to be logged regardless of the log level that has been set. This can be used to log at a higher level than `info`, whilst allowing for specific logs to still be logged out, such as logs providing sample performance statistics. + ## Max Journal Size The maximum size of an individual Journal file can be set using `{max_journalsize, integer()}`, which sets the size in bytes. The default value is 1,000,000,000 (~1GB). The maximum size, which cannot be exceed is `2^32`. It is not expected that the Journal Size should normally set to lower than 100 MB, it should be sized to hold many thousands of objects at least. -If there are smaller objects then lookups within a Journal may get faster if each individual journal file is smaller. Generally there should be o(100K) objects per journal. Signs that the journal size is too high may include: +If there are smaller objects, then lookups within a Journal may get faster if each individual journal file is smaller. Generally there should be o(100K) objects per journal, to control the maximum size of the hash table within each file. Signs that the journal size is too high may include: - excessive CPU use and related performance impacts during rolling of CDB files, see log `CDB07`; - excessive load caused during journal compaction despite tuning down `max_run_length`. diff --git a/src/leveled_bookie.erl b/src/leveled_bookie.erl index 0875a56..18f1095 100644 --- a/src/leveled_bookie.erl +++ b/src/leveled_bookie.erl @@ -107,6 +107,7 @@ -define(LONG_RUNNING, 80000). -define(COMPRESSION_METHOD, lz4). -define(COMPRESSION_POINT, on_receipt). +-define(LOG_LEVEL, info). -define(TIMING_SAMPLESIZE, 100). -define(TIMING_SAMPLECOUNTDOWN, 10000). -define(DUMMY, dummy). % Dummy key used for mput operations @@ -127,7 +128,9 @@ {reload_strategy, []}, {max_pencillercachesize, ?MAX_PCL_CACHE_SIZE}, {compression_method, ?COMPRESSION_METHOD}, - {compression_point, ?COMPRESSION_POINT}]). + {compression_point, ?COMPRESSION_POINT}, + {log_level, ?LOG_LEVEL}, + {forced_logs, []}]). -record(ledger_cache, {mem :: ets:tab(), loader = leveled_tree:empty(?CACHE_TYPE) @@ -293,12 +296,33 @@ % using bif based compression (zlib) to using nif based compression % (lz4). % Defaults to ?COMPRESSION_METHOD - {compression_point, on_compact|on_receipt} + {compression_point, on_compact|on_receipt} | % The =compression point can be changed between on_receipt (all % values are compressed as they are received), to on_compact where % values are originally stored uncompressed (speeding PUT times), % and are only compressed when they are first subject to compaction % Defaults to ?COMPRESSION_POINT + {log_level, debug|info|warn|error|critical} | + % Set the log level. The default log_level of info is noisy - the + % current implementation was targetted at environments that have + % facilities to index large proportions of logs and allow for + % dynamic querying of those indexes to output relevant stats. + % + % As an alternative a higher log_level can be used to reduce this + % 'noise', however, there is currently no separate stats facility + % to gather relevant information outside of info level logs. So + % moving to higher log levels will at present make the opertaor + % blind to sample performance statistics of leveled sub-components + % etc + {forced_logs, list(string())} + % Forced logs allow for specific info level logs, such as those + % logging stats to be logged even when the defualt log level has + % been set to a higher log level. Using: + % {forced_logs, + % ["B0015", "B0016", "B0017", "B0018", + % "P0032", "SST12", "CDB19", "SST13", "I0019"]} + % Will log all timing points even when log_level is not set to + % support info ]. @@ -1027,6 +1051,11 @@ init([Opts]) -> % Start from file not snapshot {InkerOpts, PencillerOpts} = set_options(Opts), + LogLevel = proplists:get_value(log_level, Opts), + ok = application:set_env(leveled, log_level, LogLevel), + ForcedLogs = proplists:get_value(forced_logs, Opts), + ok = application:set_env(leveled, forced_logs, ForcedLogs), + ConfiguredCacheSize = max(proplists:get_value(cache_size, Opts), ?MIN_CACHE_SIZE), CacheJitter = diff --git a/src/leveled_log.erl b/src/leveled_log.erl index 9647c9b..59d5202 100644 --- a/src/leveled_log.erl +++ b/src/leveled_log.erl @@ -11,7 +11,7 @@ log_timer/3, log_randomtimer/4]). --define(LOG_LEVEL, [debug, info, warn, error, critical]). +-define(LOG_LEVELS, [debug, info, warn, error, critical]). -define(DEFAULT_LOG_LEVEL, error). @@ -374,12 +374,12 @@ log(LogReference, Subs) -> - log(LogReference, Subs, ?LOG_LEVEL). + log(LogReference, Subs, ?LOG_LEVELS). log(LogRef, Subs, SupportedLogLevels) -> case lists:keyfind(LogRef, 1, ?LOGBASE) of {LogRef, {LogLevel, LogText}} -> - case should_i_log(LogLevel, SupportedLogLevels) of + case should_i_log(LogLevel, SupportedLogLevels, LogRef) of true -> io:format(format_time() ++ " " ++ LogRef ++ " ~w " @@ -392,11 +392,18 @@ log(LogRef, Subs, SupportedLogLevels) -> ok end. -should_i_log(LogLevel, Levels) -> - case application:get_env(leveled, log_level, ?DEFAULT_LOG_LEVEL) of - LogLevel -> true; - CurLevel -> - is_active_level(Levels, CurLevel, LogLevel) +should_i_log(LogLevel, Levels, LogRef) -> + ForcedLogs = application:get_env(leveled, forced_logs, []), + case lists:member(LogRef, ForcedLogs) of + true -> + true; + false -> + case application:get_env(leveled, log_level, ?DEFAULT_LOG_LEVEL) of + LogLevel -> + true; + CurLevel -> + is_active_level(Levels, CurLevel, LogLevel) + end end. is_active_level([L|_], L, _) -> true; @@ -405,12 +412,12 @@ is_active_level([_|T], C, L) -> is_active_level(T, C, L); is_active_level([] , _, _) -> false. log_timer(LogReference, Subs, StartTime) -> - log_timer(LogReference, Subs, StartTime, ?LOG_LEVEL). + log_timer(LogReference, Subs, StartTime, ?LOG_LEVELS). log_timer(LogRef, Subs, StartTime, SupportedLogLevels) -> case lists:keyfind(LogRef, 1, ?LOGBASE) of {LogRef, {LogLevel, LogText}} -> - case should_i_log(LogLevel, SupportedLogLevels) of + case should_i_log(LogLevel, SupportedLogLevels, LogRef) of true -> MicroS = timer:now_diff(os:timestamp(), StartTime), {Unit, Time} = case MicroS of @@ -471,4 +478,22 @@ log_warn_test() -> ok = log_timer("G0001", [], os:timestamp(), [warn, error]), ok = log_timer("G8888", [], os:timestamp(), [info, warn, error]). +shouldilog_test() -> + % What if an unsupported option is set for the log level + % don't log + ok = application:set_env(leveled, log_level, unsupported), + ?assertMatch(false, should_i_log(info, ?LOG_LEVELS, "G0001")), + ?assertMatch(false, should_i_log(inform, ?LOG_LEVELS, "G0001")), + ok = application:set_env(leveled, log_level, debug), + ?assertMatch(true, should_i_log(info, ?LOG_LEVELS, "G0001")), + ok = application:set_env(leveled, log_level, info), + ?assertMatch(true, should_i_log(info, ?LOG_LEVELS, "G0001")), + ok = application:set_env(leveled, forced_logs, ["G0001"]), + ok = application:set_env(leveled, log_level, error), + ?assertMatch(true, should_i_log(info, ?LOG_LEVELS, "G0001")), + ?assertMatch(false, should_i_log(info, ?LOG_LEVELS, "G0002")), + ok = application:set_env(leveled, forced_logs, []), + ok = application:set_env(leveled, log_level, info), + ?assertMatch(false, should_i_log(debug, ?LOG_LEVELS, "D0001")). + -endif. diff --git a/test/end_to_end/basic_SUITE.erl b/test/end_to_end/basic_SUITE.erl index cd29e60..2317510 100644 --- a/test/end_to_end/basic_SUITE.erl +++ b/test/end_to_end/basic_SUITE.erl @@ -33,9 +33,20 @@ all() -> [ simple_put_fetch_head_delete(_Config) -> + io:format("simple test with info and no forced logs~n"), + simple_test_withlog(info, []), + io:format("simple test with error and no forced logs~n"), + simple_test_withlog(error, []), + io:format("simple test with error and stats logs~n"), + simple_test_withlog(error, ["B0015", "B0016", "B0017", "B0018", + "P0032", "SST12", "CDB19", "SST13", "I0019"]). + +simple_test_withlog(LogLevel, ForcedLogs) -> RootPath = testutil:reset_filestructure(), StartOpts1 = [{root_path, RootPath}, - {sync_strategy, testutil:sync_strategy()}], + {sync_strategy, testutil:sync_strategy()}, + {log_level, LogLevel}, + {forced_logs, ForcedLogs}], {ok, Bookie1} = leveled_bookie:book_start(StartOpts1), {TestObject, TestSpec} = testutil:generate_testobject(), ok = testutil:book_riakput(Bookie1, TestObject, TestSpec), @@ -44,7 +55,9 @@ simple_put_fetch_head_delete(_Config) -> ok = leveled_bookie:book_close(Bookie1), StartOpts2 = [{root_path, RootPath}, {max_journalsize, 3000000}, - {sync_strategy, testutil:sync_strategy()}], + {sync_strategy, testutil:sync_strategy()}, + {log_level, LogLevel}, + {forced_logs, ForcedLogs}], {ok, Bookie2} = leveled_bookie:book_start(StartOpts2), testutil:check_forobject(Bookie2, TestObject), ObjList1 = testutil:generate_objects(5000, 2), From 9735661d987234032efe1ca85471d5ca68025457 Mon Sep 17 00:00:00 2001 From: Martin Sumner Date: Wed, 5 Dec 2018 09:31:03 +0000 Subject: [PATCH 3/3] Typos as per PR comments --- src/leveled_bookie.erl | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/leveled_bookie.erl b/src/leveled_bookie.erl index 18f1095..14d0090 100644 --- a/src/leveled_bookie.erl +++ b/src/leveled_bookie.erl @@ -311,12 +311,12 @@ % As an alternative a higher log_level can be used to reduce this % 'noise', however, there is currently no separate stats facility % to gather relevant information outside of info level logs. So - % moving to higher log levels will at present make the opertaor + % moving to higher log levels will at present make the operator % blind to sample performance statistics of leveled sub-components % etc {forced_logs, list(string())} % Forced logs allow for specific info level logs, such as those - % logging stats to be logged even when the defualt log level has + % logging stats to be logged even when the default log level has % been set to a higher log level. Using: % {forced_logs, % ["B0015", "B0016", "B0017", "B0018",