diff options
| -rw-r--r-- | lib/kernel/doc/src/Makefile | 1 | ||||
| -rw-r--r-- | lib/kernel/doc/src/logger_chapter.xml | 178 | ||||
| -rw-r--r-- | lib/kernel/doc/src/logger_disk_log_h.xml | 146 | ||||
| -rw-r--r-- | lib/kernel/doc/src/logger_std_h.xml | 110 | ||||
| -rw-r--r-- | lib/kernel/doc/src/ref_man.xml | 1 | ||||
| -rw-r--r-- | lib/kernel/doc/src/specs.xml | 1 | ||||
| -rw-r--r-- | lib/kernel/src/logger_h_common.erl | 4 |
7 files changed, 406 insertions, 35 deletions
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 @@ </section> <section> + <marker id="handler_configuration"/> <title>Handler configuration</title> <taglist> <tag><c>level</c></tag> @@ -577,8 +578,8 @@ log(#{msg:={F,A}},#{myhandler_fd:=Fd}) -> <p>For examples of overload protection, please refer to the implementation of <seealso marker="logger_std_h"><c>logger_std_h</c></seealso> - and <!--<seealso marker="logger_disk_log_h"--><c>logger_disk_log_h</c> - <!--/seealso-->.</p> + and <seealso marker="logger_disk_log_h"><c>logger_disk_log_h</c> + </seealso>.</p> <p>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) -> </code> </section> + <section> + <marker id="overload_protection"/> + <title>Protecting the handler from overload</title> + <p>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 + <seealso marker="logger_std_h"><c>logger_std_h</c></seealso> + and <seealso marker="logger_disk_log_h"><c>logger_disk_log_h</c> + </seealso> handler. The mechanism, used by both handlers, works + as follows:</p> + + <section> + <title>Message queue length</title> + <p>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:</p> + + <taglist> + <tag><c>toggle_sync_qlen</c></tag> + <item> + <p>The default value of this level is <c>10</c> 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 <c>toggle_sync_qlen</c> 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.</p> + </item> + <tag><c>drop_new_reqs_qlen</c></tag> + <item> + <p>When the message queue has grown larger than this threshold, which + defaults to <c>200</c> 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.</p> + </item> + <tag><c>flush_reqs_qlen</c></tag> + <item> + <p>Above this threshold, which defaults to <c>1000</c> 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).</p> + </item> + </taglist> + + <p>For the overload protection algorithm to work properly, it is a + requirement that:</p> + + <p><c>toggle_sync_qlen < drop_new_reqs_qlen < flush_reqs_qlen</c></p> + + <p>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. </p> + + <p>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).</p> + + <p>A configuration example:</p> + <code type="none"> +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}}). + </code> + </section> + + <section> + <title>Controlling bursts of log requests</title> + <p>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:</p> + + <taglist> + <tag><c>enable_burst_limit</c></tag> + <item> + <p>This is set to <c>true</c> by default. The value <c>false</c> + disables the burst control feature.</p> + </item> + <tag><c>burst_limit_size</c></tag> + <item> + <p>This is how many requests should be processed within the + <c>burst_window_time</c> time frame. After this maximum has been + reached, successive requests will be dropped until the end of the + time frame. The default value is <c>500</c> messages.</p> + </item> + <tag><c>burst_window_time</c></tag> + <item> + <p>The default window is <c>1000</c> milliseconds long.</p> + </item> + </taglist> + + <p>A configuration example:</p> + <code type="none"> +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}}). + </code> + </section> + + <section> + <title>Terminating a large handler</title> + <p>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:</p> + + <taglist> + <tag><c>enable_kill_overloaded</c></tag> + <item> + <p>This is set to <c>false</c> by default. The value <c>true</c> + enables the feature.</p> + </item> + <tag><c>handler_overloaded_qlen</c></tag> + <item> + <p>This is the maximum allowed queue length. If the mailbox grows larger + than this, the handler process gets terminated.</p> + </item> + <tag><c>handler_overloaded_mem</c></tag> + <item> + <p>This is the maximum allowed memory usage of the handler process. If + the handler grows any larger, the process gets terminated.</p> + </item> + <tag><c>handler_restart_after</c></tag> + <item> + <p>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 <c>5000</c> is the default value. The value <c>never</c> can + also be set, which prevents a restart.</p> + </item> + </taglist> + </section> + </section> <section> <title>See Also</title> 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 @@ +<?xml version="1.0" encoding="utf-8" ?> +<!DOCTYPE erlref SYSTEM "erlref.dtd"> + +<erlref> + <header> + <copyright> + <year>2017</year> + <holder>Ericsson AB. All Rights Reserved.</holder> + </copyright> + <legalnotice> + 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. + + </legalnotice> + + <title>logger_disk_log_h</title> + <prepared></prepared> + <responsible></responsible> + <docno></docno> + <approved></approved> + <checked></checked> + <date></date> + <rev>A</rev> + <file>logger_disk_log_h.xml</file> + </header> + <module>logger_disk_log_h</module> + <modulesummary>A disk_log based handler for the Logger + application.</modulesummary> + + <description> + <p>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.</p> + <p>The default standard handler, + <seealso marker="logger_std_h"><c>logger_std_h</c></seealso>, can be + replaced by a disk_log handler at startup of the kernel application. + See an example of this below.</p> + <p>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 + <seealso marker="logger_chapter#overload_protection"><c>User's Guide</c> + </seealso>.</p> + <p>To add a new instance of the disk_log handler, use + <seealso marker="logger#add_handler-3"><c>logger:add_handler/3</c> + </seealso>. The handler configuration argument is a map which may contain + general configuration parameters, as documented in the + <seealso marker="logger_chapter#handler_configuration"><c>User's Guide</c> + </seealso>, as well as handler specific parameters.</p> + <p>The settings for the disk_log log file should be specified with the + key <c>disk_log_opts</c>. These settings are a subset of the disk_log + datatype + <seealso marker="disk_log#open-1"><c>dlog_option()</c></seealso>.</p> + <p>Parameters in the <c>disk_log_opts</c> map:</p> + <taglist> + <tag><c>file</c></tag> + <item>This is the full name of the disk_log log file.</item> + <tag><c>type</c></tag> + <item>This is the disk_log type, <c>wrap</c> or <c>halt</c>. The + default value is <c>wrap</c>.</item> + <tag><c>max_no_files</c></tag> + <item>This is the maximum number of files that disk_log will use + for its circular logging. The default value is <c>10</c>. (The setting + has no effect on a halt log).</item> + <tag><c>max_no_bytes</c></tag> + <item>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 <c>1048576</c> bytes, and <c>infinity</c> for a halt + log.</item> + </taglist> + <p>Specific configuration for the handler (represented as a sub map) + is specified with the key <c>logger_disk_log_h</c>. It may contain the + following parameter:</p> + <taglist> + <tag><c>filesync_repeat_interval</c></tag> + <item> + <p>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 <c>5000</c> milliseconds. + If <c>no_repeat</c> is set as value, the repeated sync operation is + disabled. The user can also call the + <seealso marker="logger_disk_log_h#disk_log_sync-1"><c>disk_log_sync/1</c> + </seealso> function to perform a disk_log sync.</p></item> + </taglist> + <p>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 + <seealso marker="logger_chapter#overload_protection"><c>User's Guide</c> + </seealso>.</p> + <p>Note that when changing the configuration of the handler in runtime, by + calling + <seealso marker="logger#set_handler_config-2"><c>logger:set_handler_config/2 + or logger:set_handler_config/3</c></seealso>, the <c>disk_log_opts</c> + settings may not be modified.</p> + <p>Example of adding a disk_log handler:</p> + <code type="none"> +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}}). + </code> + <p>In order to use the disk_log handler instead of the default standard + handler when starting en Erlang node, use the kernel configuration parameter + <seealso marker="kernel_app#configuration"><c>logger_dest</c></seealso> with + value <c>{disk_log,FileName}</c>. Example:</p> + <code type="none"> +erl -kernel logger_dest '{disk_log,"./system_disk_log"}' + </code> + </description> + + <funcs> + + <func> + <name name="disk_log_sync" arity="1" clause_i="1"/> + <fsummary>Writes buffered data to disk.</fsummary> + <desc> + <p>Write buffered data to disk.</p> + </desc> + </func> + + </funcs> + +</erlref> + + 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 @@ <p>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 <c>standard_io</c>, - <c>standard_error</c> or to a file.</p> - - <p>To add a new instance, - use <seealso marker="logger#add_handler-3"><c>logger:add_handler/3</c> + <c>standard_error</c> or to file. The default instance that starts + with kernel is named <c>logger_std_h</c> - which is the name to be used + for reconfiguration.</p> + <p>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 + <seealso marker="logger_chapter#overload_protection"><c>User's Guide</c> </seealso>.</p> - - <p>The handler configuration may contain the following keys, - associated with values as described:</p> + <p>To add a new instance of the standard handler, use + <seealso marker="logger#add_handler-3"><c>logger:add_handler/3</c> + </seealso>. The handler configuration argument is a map which may contain + general configuration parameters, as documented in the + <seealso marker="logger_chapter#handler_configuration"><c>User's Guide</c> + </seealso>, as well as handler specific parameters. The specific parameters + are stored in a sub map with the key <c>logger_std_h</c>. The following + keys and values may be specified:</p> <taglist> - <tag><c>filters</c></tag> - <item> - <p>A list of <c>{Id,{Fun,Args}}</c>, each representing a filter - that may selct or modify log events to forward to this - handler.</p></item> - <tag><c>filter_default</c></tag> - <item> - <p>The atom <c>log</c> or <c>stop</c>, specifying what to - do with a log event if all filters - return <c>ignore</c>.</p></item> - <tag><c>formatter</c></tag> + <tag><c>type</c></tag> <item> - <p><c>{Module,Extra}</c>, - where <c>Module:format(Log,Extra)</c> will be called by - the handler to produce the string that will be printed to - the handler's destination.</p></item> - <tag><c>level</c></tag> + <p>This will have the value <c>standard_io</c>, <c>standard_error</c>, + <c>{file,LogFileName}</c>, or <c>{file,LogFileName,LogFileOpts}</c>, + where <c>standard_io</c> is the default value for type. It's recommended + to not specify <c>LogFileOpts</c> if not absolutely necessary. The + default options used by the handler to open a file for logging are: + <c>raw</c>, <c>append</c> and <c>delayed_write</c>. The standard + handler does not have support for circular logging. Use the + <seealso marker="logger_disk_log_h"><c>logger_disk_log_h</c> + </seealso> handler for this.</p></item> + <tag><c>filesync_repeat_interval</c></tag> <item> - <p>The level of log events that <c>logger</c> shall forward to - this handler. Log events of the specified, or more severe - levels, are forwarded.</p></item> + <p>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 <c>5000</c> milliseconds. + If <c>no_repeat</c> 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 <seealso marker="logger_std_h#filesync-1"><c>filesync/1</c></seealso> + function to perform a file sync.</p></item> </taglist> - + <p>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 + <seealso marker="logger_chapter#overload_protection"><c>User's Guide</c> + </seealso>.</p> + <p>Note that when changing the configuration of the handler in runtime, by + calling + <seealso marker="logger#set_handler_config-2"><c>logger:set_handler_config/2</c> + </seealso>, or + <seealso marker="logger#set_handler_config-3"><c>logger:set_handler_config/3</c> + </seealso>, + the <c>type</c> parameter may not be modified.</p> + <p>Example of adding a standard handler:</p> + <code type="none"> +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}}). + </code> + <p>In order to configure the default handler (that starts initially with + the kernel application) to log to file instead of <c>standard_io</c>, + use the kernel configuration parameter + <seealso marker="kernel_app#configuration"><c>logger_dest</c></seealso> with + value <c>{file,FileName}</c>. Example:</p> + <code type="none"> +erl -kernel logger_dest '{file,"./erl.log"}' + </code> + <p>An example of how to replace the standard handler with a disk_log handler + at startup can be found in the manual of + <seealso marker="logger_disk_log_h"><c>logger_disk_log_h</c></seealso>.</p> </description> -<!-- <funcs> - </funcs> --> + <funcs> + + <func> + <name name="filesync" arity="1" clause_i="1"/> + <fsummary>Writes buffered data to disk.</fsummary> + <desc> + <p>Write buffered data to disk.</p> + </desc> + </func> + + </funcs> </erlref> 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 @@ <xi:include href="logger_filters.xml"/> <xi:include href="logger_formatter.xml"/> <xi:include href="logger_std_h.xml"/> + <xi:include href="logger_disk_log_h.xml"/> <xi:include href="net_adm.xml"/> <xi:include href="net_kernel.xml"/> <xi:include href="os.xml"/> 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 @@ <xi:include href="../specs/specs_logger_filters.xml"/> <xi:include href="../specs/specs_logger_formatter.xml"/> <xi:include href="../specs/specs_logger_std_h.xml"/> + <xi:include href="../specs/specs_logger_disk_log_h.xml"/> <xi:include href="../specs/specs_net_adm.xml"/> <xi:include href="../specs/specs_net_kernel.xml"/> <xi:include href="../specs/specs_os.xml"/> 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}) |