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),