From ee44197422710dabe43f2f4b80d1034aae9c916f Mon Sep 17 00:00:00 2001 From: Peter Andersson Date: Wed, 25 Apr 2018 21:18:08 +0200 Subject: Add documentation of the built-in logger handlers --- lib/kernel/doc/src/Makefile | 1 + lib/kernel/doc/src/logger_chapter.xml | 178 ++++++++++++++++++++++++++++++- lib/kernel/doc/src/logger_disk_log_h.xml | 146 +++++++++++++++++++++++++ lib/kernel/doc/src/logger_std_h.xml | 110 ++++++++++++++----- lib/kernel/doc/src/ref_man.xml | 1 + lib/kernel/doc/src/specs.xml | 1 + lib/kernel/src/logger_h_common.erl | 4 - 7 files changed, 406 insertions(+), 35 deletions(-) create mode 100644 lib/kernel/doc/src/logger_disk_log_h.xml diff --git a/lib/kernel/doc/src/Makefile b/lib/kernel/doc/src/Makefile index 10bdf46119..82869d7b15 100644 --- a/lib/kernel/doc/src/Makefile +++ b/lib/kernel/doc/src/Makefile @@ -58,6 +58,7 @@ XML_REF3_FILES = application.xml \ init_stub.xml \ logger.xml \ logger_std_h.xml \ + logger_disk_log_h.xml \ logger_filters.xml \ logger_formatter.xml \ net_adm.xml \ diff --git a/lib/kernel/doc/src/logger_chapter.xml b/lib/kernel/doc/src/logger_chapter.xml index 2a325453da..0bc3b37476 100644 --- a/lib/kernel/doc/src/logger_chapter.xml +++ b/lib/kernel/doc/src/logger_chapter.xml @@ -296,6 +296,7 @@
+ Handler configuration level @@ -577,8 +578,8 @@ log(#{msg:={F,A}},#{myhandler_fd:=Fd}) ->

For examples of overload protection, please refer to the implementation of logger_std_h - and logger_disk_log_h - .

+ and logger_disk_log_h + .

Below is a simpler example of a handler which logs through one single process, and uses the default formatter to gain a common @@ -632,6 +633,179 @@ my_report_cb(R) ->

+
+ + Protecting the handler from overload +

In order for the built-in handlers to survive, and stay responsive, + during periods of high load (i.e. when huge numbers of incoming + log requests must be handled), a mechanism for overload protection + has been implemented in the + logger_std_h + and logger_disk_log_h + handler. The mechanism, used by both handlers, works + as follows:

+ +
+ Message queue length +

The handler process keeps track of the length of its message + queue and reacts in different ways depending on the current status. + The purpose is to keep the handler in, or (as quickly as possible), + get the handler into, a state where it can keep up with the pace + of incoming log requests. The memory usage of the handler must never + keep growing larger and larger, since that would eventually cause the + handler to crash. Three thresholds with associated actions have been + defined:

+ + + toggle_sync_qlen + +

The default value of this level is 10 messages, + and as long as the length of the message queue is lower, all log + requests are handled asynchronously. This simply means that the + process sending the log request (by calling a log function in the + logger API) does not wait for a response from the handler but + continues executing immediately after the request (i.e. it will not + be affected by the time it takes the handler to print to the log + device). If the message queue grows larger than this value, however, + the handler starts handling the log requests synchronously instead, + meaning the process sending the request will have to wait for a + response. When the handler manages to reduce the message queue to a + level below the toggle_sync_qlen threshold, asynchronous + operation is resumed. The switch from asynchronous to synchronous + mode will force the logging tempo of few busy senders to slow down, + but can not protect the handler sufficiently in situations of many + concurrent senders.

+ + drop_new_reqs_qlen + +

When the message queue has grown larger than this threshold, which + defaults to 200 messages, the handler switches to a mode in + which it drops any new requests being made. Dropping a message in + this state means that the log function never actually sends a message + to the handler. The log call simply returns without an action. When + the length of the message queue has been reduced to a level below this + threshold, synchronous or asynchronous request handling mode is + resumed.

+ + flush_reqs_qlen + +

Above this threshold, which defaults to 1000 messages, a + flush operation takes place, in which all messages buffered in the + process mailbox get deleted without any logging actually taking + place. (Processes waiting for a response from a synchronous log request + will receive a reply indicating that the request has been dropped).

+ + + +

For the overload protection algorithm to work properly, it is a + requirement that:

+ +

toggle_sync_qlen < drop_new_reqs_qlen < flush_reqs_qlen

+ +

During high load scenarios, the length of the handler message queue + rarely grows in a linear and predictable way. Instead, whenever the + handler process gets scheduled in, it can have an almost arbitrary number + of messages waiting in the mailbox. It's for this reason that the overload + protection mechanism is focused on acting quickly and quite drastically + (such as immediately dropping or flushing messages) as soon as a large + queue length is detected.

+ +

The thresholds listed above may be modified by the user if, e.g, a handler + shouldn't drop or flush messages unless the message queue length grows + extremely large. (The handler must be allowed to use large amounts of memory + under such circumstances however). Another example of when the user might want + to change the settings is if, for performance reasons, the logging processes must + never get blocked by synchronous log requests, while dropping or flushing requests + is perfectly acceptable (since it doesn't affect the performance of the + loggers).

+ +

A configuration example:

+ +logger:add_handler(my_standard_h, logger_std_h, + #{logger_std_h => + #{type => {file,"./system_info.log"}, + toggle_sync_qlen => 100, + drop_new_reqs_qlen => 1000, + flush_reqs_qlen => 2000}}). + +
+ +
+ Controlling bursts of log requests +

A potential problem with large bursts of log requests, is that log files + may get full or wrapped too quickly (in the latter case overwriting + previously logged data that could be of great importance). For this reason, + both built-in handlers offer the possibility to set a maximum level of how + many requests to process with a certain time frame. With this burst control + feature enabled, the handler will take care of bursts of log requests + without choking log files, or the console, with massive amounts of + printouts. These are the configuration parameters:

+ + + enable_burst_limit + +

This is set to true by default. The value false + disables the burst control feature.

+ + burst_limit_size + +

This is how many requests should be processed within the + burst_window_time time frame. After this maximum has been + reached, successive requests will be dropped until the end of the + time frame. The default value is 500 messages.

+ + burst_window_time + +

The default window is 1000 milliseconds long.

+ + + +

A configuration example:

+ +logger:add_handler(my_disk_log_h, logger_disk_log_h, + #{disk_log_opts => + #{file => "./my_disk_log"}, + logger_disk_log_h => + #{burst_limit_size => 10, + burst_window_time => 500}}). + +
+ +
+ Terminating a large handler +

A handler process may grow large even if it can manage peaks of high load + without crashing. The overload protection mechanism includes user configurable + levels for a maximum allowed message queue length and maximum allowed memory + usage. This feature is disabled by default, but can be switched on by means + of the following configuration parameters:

+ + + enable_kill_overloaded + +

This is set to false by default. The value true + enables the feature.

+ + handler_overloaded_qlen + +

This is the maximum allowed queue length. If the mailbox grows larger + than this, the handler process gets terminated.

+ + handler_overloaded_mem + +

This is the maximum allowed memory usage of the handler process. If + the handler grows any larger, the process gets terminated.

+ + handler_restart_after + +

If the handler gets terminated because of its queue length or + memory usage, it can get automatically restarted again after a + configurable delay time. The time is specified in milliseconds + and 5000 is the default value. The value never can + also be set, which prevents a restart.

+ + +
+
See Also diff --git a/lib/kernel/doc/src/logger_disk_log_h.xml b/lib/kernel/doc/src/logger_disk_log_h.xml new file mode 100644 index 0000000000..90cc4fec30 --- /dev/null +++ b/lib/kernel/doc/src/logger_disk_log_h.xml @@ -0,0 +1,146 @@ + + + + +
+ + 2017 + Ericsson AB. All Rights Reserved. + + + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. + + + + logger_disk_log_h + + + + + + + A + logger_disk_log_h.xml +
+ logger_disk_log_h + A disk_log based handler for the Logger + application. + + +

This is a handler for the Logger application that offers circular + (wrapped) logs by using the disk_log application. Multiple instances + of this handler can be added to logger, and each instance will print to + its own disk_log file, created with the name and settings specified in + the handler configuration.

+

The default standard handler, + logger_std_h, can be + replaced by a disk_log handler at startup of the kernel application. + See an example of this below.

+

The handler has an overload protection mechanism that will keep the handler + process and the kernel application alive during a high load of log + requests. How this feature works, and how to modify the configuration, + is described in the + User's Guide + .

+

To add a new instance of the disk_log handler, use + logger:add_handler/3 + . The handler configuration argument is a map which may contain + general configuration parameters, as documented in the + User's Guide + , as well as handler specific parameters.

+

The settings for the disk_log log file should be specified with the + key disk_log_opts. These settings are a subset of the disk_log + datatype + dlog_option().

+

Parameters in the disk_log_opts map:

+ + file + This is the full name of the disk_log log file. + type + This is the disk_log type, wrap or halt. The + default value is wrap. + max_no_files + This is the maximum number of files that disk_log will use + for its circular logging. The default value is 10. (The setting + has no effect on a halt log). + max_no_bytes + This is the maximum number of bytes that will be written to + a log file before disk_log proceeds with the next file in order (or + generates an error in case of a full halt log). The default value for + a wrap log is 1048576 bytes, and infinity for a halt + log. + +

Specific configuration for the handler (represented as a sub map) + is specified with the key logger_disk_log_h. It may contain the + following parameter:

+ + filesync_repeat_interval + +

This value (in milliseconds) specifies how often the handler will + do a disk_log sync operation in order to make sure that buffered data + gets written to disk. The handler will repeatedly attempt this + operation, but only perform it if something has actually been logged + since the last sync. The default value is 5000 milliseconds. + If no_repeat is set as value, the repeated sync operation is + disabled. The user can also call the + disk_log_sync/1 + function to perform a disk_log sync.

 + +

There are a number of other configuration parameters available, that are + to be used for customizing the overload protection behaviour. The same + parameters are used both in the standard handler and the disk_log handler, + and are documented in the + User's Guide + .

+

Note that when changing the configuration of the handler in runtime, by + calling + logger:set_handler_config/2 + or logger:set_handler_config/3, the disk_log_opts + settings may not be modified.

+

Example of adding a disk_log handler:

+ +logger:add_handler(my_disk_log_h, logger_disk_log_h, + #{level => error, + filter_default => log, + disk_log_opts => + #{file => "./my_disk_log", + type => wrap, + max_no_files => 4, + max_no_bytes => 10000}, + logger_disk_log_h => + #{filesync_repeat_interval => 1000}}). + +

In order to use the disk_log handler instead of the default standard + handler when starting en Erlang node, use the kernel configuration parameter + logger_dest with + value {disk_log,FileName}. Example:

+ +erl -kernel logger_dest '{disk_log,"./system_disk_log"}' + + + + + + + + Writes buffered data to disk. + +

Write buffered data to disk.

+ + + + + + + + diff --git a/lib/kernel/doc/src/logger_std_h.xml b/lib/kernel/doc/src/logger_std_h.xml index 2a368b16eb..fe9b9ca5a9 100644 --- a/lib/kernel/doc/src/logger_std_h.xml +++ b/lib/kernel/doc/src/logger_std_h.xml @@ -39,42 +39,94 @@

This is the default handler for the Logger application. Multiple instances of this handler can be added to logger, and each instance will print logs to standard_io, - standard_error or to a file.

- -

To add a new instance, - use logger:add_handler/3 + standard_error or to file. The default instance that starts + with kernel is named logger_std_h - which is the name to be used + for reconfiguration.

+

The handler has an overload protection mechanism that will keep the handler + process and the kernel application alive during a high load of log + requests. How this feature works, and how to modify the configuration, + is described in the + User's Guide .

- -

The handler configuration may contain the following keys, - associated with values as described:

+

To add a new instance of the standard handler, use + logger:add_handler/3 + . The handler configuration argument is a map which may contain + general configuration parameters, as documented in the + User's Guide + , as well as handler specific parameters. The specific parameters + are stored in a sub map with the key logger_std_h. The following + keys and values may be specified:

- filters - -

A list of {Id,{Fun,Args}}, each representing a filter - that may selct or modify log events to forward to this - handler.

 - filter_default - -

The atom log or stop, specifying what to - do with a log event if all filters - return ignore.

 - formatter + type -

{Module,Extra}, - where Module:format(Log,Extra) will be called by - the handler to produce the string that will be printed to - the handler's destination.

 - level +

This will have the value standard_io, standard_error, + {file,LogFileName}, or {file,LogFileName,LogFileOpts}, + where standard_io is the default value for type. It's recommended + to not specify LogFileOpts if not absolutely necessary. The + default options used by the handler to open a file for logging are: + raw, append and delayed_write. The standard + handler does not have support for circular logging. Use the + logger_disk_log_h + handler for this.

+ filesync_repeat_interval -

The level of log events that logger shall forward to - this handler. Log events of the specified, or more severe - levels, are forwarded.

 +

This value (in milliseconds) specifies how often the handler will + do a file sync operation in order to make sure that buffered data gets + written to disk. The handler will repeatedly attempt this + operation, but only perform it if something has actually been logged + since the last sync. The default value is 5000 milliseconds. + If no_repeat is set as value, the repeated file sync operation + is disabled, and it will be the operating system settings that determine + how quickly or slowly data gets written to disk. The user can also call + the filesync/1 + function to perform a file sync.

 - +

There are a number of other configuration parameters available, that are + to be used for customizing the overload protection behaviour. The same + parameters are used both in the standard handler and the disk_log handler, + and are documented in the + User's Guide + .

+

Note that when changing the configuration of the handler in runtime, by + calling + logger:set_handler_config/2 + , or + logger:set_handler_config/3 + , + the type parameter may not be modified.

+

Example of adding a standard handler:

+ +logger:add_handler(my_standard_h, logger_std_h, + #{level => info, + filter_default => log, + logger_std_h => + #{type => {file,"./system_info.log"}, + filesync_repeat_interval => 1000}}). + +

In order to configure the default handler (that starts initially with + the kernel application) to log to file instead of standard_io, + use the kernel configuration parameter + logger_dest with + value {file,FileName}. Example:

+ +erl -kernel logger_dest '{file,"./erl.log"}' + +

An example of how to replace the standard handler with a disk_log handler + at startup can be found in the manual of + logger_disk_log_h.

- + + + + + Writes buffered data to disk. + +

Write buffered data to disk.

+ + + + diff --git a/lib/kernel/doc/src/ref_man.xml b/lib/kernel/doc/src/ref_man.xml index 7f4d5b384f..c06914d23d 100644 --- a/lib/kernel/doc/src/ref_man.xml +++ b/lib/kernel/doc/src/ref_man.xml @@ -56,6 +56,7 @@ + diff --git a/lib/kernel/doc/src/specs.xml b/lib/kernel/doc/src/specs.xml index a67e26ef16..bcc422930e 100644 --- a/lib/kernel/doc/src/specs.xml +++ b/lib/kernel/doc/src/specs.xml @@ -24,6 +24,7 @@ + diff --git a/lib/kernel/src/logger_h_common.erl b/lib/kernel/src/logger_h_common.erl index 7a5082fb84..7caad366ae 100644 --- a/lib/kernel/src/logger_h_common.erl +++ b/lib/kernel/src/logger_h_common.erl @@ -133,10 +133,6 @@ call_cast_or_drop(Name, Bin) -> dropped -> ok catch _:{timeout,_} -> - %%! --- Tue Mar 6 23:10:48 2018 --- peppe was here! - erlang:display('CLIENT_TIMEOUT'), - %% exit('CLIENT_TIMEOUT'), - ?observe(Name,{dropped,1}) end; drop -> ?observe(Name,{dropped,1}) -- cgit v1.2.3