log_sink_perfschema.cc File Reference

This file contains. More...

#include "log_sink_perfschema.h"
#include <mysql/components/services/log_shared.h>
#include <string.h>
#include "log_builtins_internal.h"
#include "log_sink_perfschema_imp.h"
#include "log_sink_trad.h"
#include "my_dir.h"
#include "my_systime.h"
#include "mysql/components/services/log_builtins.h"
#include "mysql/my_loglevel.h"
#include "mysqld_error.h"
#include "mysys_err.h"
#include "sql/log.h"

Macros
#define	LOG_ERR_READ_LINE_SIZE   (LOG_BUFF_MAX * 2)

Functions
static size_t	log_sink_pfs_event_size (log_sink_pfs_event *e)
	Calculate the size of the given event (header + blob + '\0' + alignment). More...
static bool	log_sink_pfs_event_header_fits (char *p)
	Test whether we're so close to the end of the ring-buffer that another event header would not fit. More...
void	log_sink_pfs_read_start ()
	Acquire a read-lock on the ring-buffer. More...
void	log_sink_pfs_read_end ()
	Release read-lock on ring-buffer. More...
size_t	log_sink_pfs_event_count ()
	Get number of events currently in ring-buffer. More...
log_sink_pfs_event *	log_sink_pfs_event_first ()
	Get oldest event still in ring-buffer. More...
log_sink_pfs_event *	log_sink_pfs_event_next (log_sink_pfs_event *e)
	Get event following the supplied one. More...
log_sink_pfs_event *	log_sink_pfs_event_valid (log_sink_pfs_event *e, ulonglong logged)
	Use timestamp to check whether a given event-pointer still points to a valid event in the ring-buffer. More...
static void	log_sink_pfs_event_expire (void)
static int	log_sink_pfs_write_wrap (size_t s)
	If the current event can fit in the ring-buffer, but the write position is so close to the physical end of the ring-buffer that the event won't fit there, wrap to the beginning of the ring-buffer. More...
static void	log_sink_pfs_sanitize_timestamp (log_sink_pfs_event *e)
log_service_error	log_sink_pfs_event_add (log_sink_pfs_event *e, const char *blob_src)
	Add a log-event to the ring buffer. More...
static log_service_error	log_error_read_loop (const char *log_file, size_t size)
	Add all rows from a log file to the error-log ring-buffer. More...
log_service_error	log_error_read_log (const char *log_name)
	Restore error log messages from previous shutdown. More...
int	log_error_read_log_exit ()
	Release error log ring-buffer. More...
int	log_error_read_log_init ()
	Set up ring-buffer for error-log. More...
int	log_sink_perfschema (void *instance, log_line *ll)
	services: log sinks: logging to performance_schema ring-buffer More...

Variables
static const size_t	ring_buffer_size = 5 * 1024 * 1024
	In the interest of not adding more settings to confuse the using, the error-log ring-buffer is of a static size for now. More...
static char *	ring_buffer_start = nullptr
	buffer start More...
static char *	ring_buffer_end = nullptr
	buffer end (for convenience) More...
static char *	ring_buffer_write = nullptr
	write position ("head") More...
static char *	ring_buffer_read = nullptr
	read pos (oldest entry, "tail") More...
ulong	log_sink_pfs_buffered_bytes = 0
	bytes in use (now) More...
ulong	log_sink_pfs_buffered_events = 0
	events in buffer (now) More...
ulong	log_sink_pfs_expired_events = 0
	number of expired entries (ever) More...
ulong	log_sink_pfs_longest_event = 0
	longest event seen (ever) More...
ulonglong	log_sink_pfs_latest_timestamp
	timestamp of most recent write More...
PSI_memory_key	key_memory_log_sink_pfs
	memory instrumentation More...
static mysql_rwlock_t	THR_LOCK_log_perfschema
	ring-buffer rwlock Local to the sink that feeds the table performance_schema.error_log. More...

Detailed Description

This file contains.

a) the ring-buffer that stores a backlog of error-messages so they can be exposed to the SQL layer via performance_schema.error_log;

b) the log-sink that adds errors logged at run-time to the ring-buffer.

c) the error log reader that reads error log file at start-up (These functions will in turn use a parse-function defined in a log-sink. Whichever log-sink that has a parse-function is listed first in @global.log_error_services will be used; that service will decide what log-file to read (i.e. its name) and how to parse it. We initially support the reading of JSON- formatted error log files and of the traditional MySQL error log files.) This lets us restore error log information from previous runs when the server starts. These functions are called from mysqld.cc at start-up.

Macro Definition Documentation

LOG_ERR_READ_LINE_SIZE

#define LOG_ERR_READ_LINE_SIZE   (LOG_BUFF_MAX * 2)

Function Documentation

log_error_read_log()

log_service_error log_error_read_log

(

const char *

log_name

)

Restore error log messages from previous shutdown.

We try restoring from the first (leftmost) of those services listed in @global.log_error_services that have the LOG_SERVICE_LOG_PARSER characteristic.

It is assumed that the last run's log file name is the same as the current one's. That is to say, we check whether the file supplied to –log-error already exists.

Once we have determined what file to read from, we'll call

See also

log_error_read_loop() to do the actual reading and parsing.

It should be noted that at the point this function is normally called, buffered error logging will not have flushed yet.

a) If we are using the built-in "trad" sink/reader, the start-up messages are usually not buffered, and have already been written to the error log. In this case, they will be restored from the log (and flushing won't add another event to the ring-buffer).

b) If we are using a reader in a loadable log-service,

Parameters

log_name

The log file to read (log_error_dest).

Return values

LOG_SERVICE_SUCCESS	Success (log read and parsed)
LOG_SERVICE_UNABLE_TO_READ	Could not read/access() file
LOG_SERVICE_INVALID_ARGUMENT	Invalid file-name (no '.')
LOG_SERVICE_NOT_AVAILABLE	No log_component active that can parse log-files
LOG_SERVICE_ARGUMENT_TOO_LONG	File-name too long
LOG_SERVICE_COULD_NOT_MAKE_LOG_NAME	Could not determine file extension
otherwise	Return value from reader

log_error_read_log_exit()

int log_error_read_log_exit

(

)

Release error log ring-buffer.

Return values

0	Success - buffer was released, or did not exist in the first place.

log_error_read_log_init()

int log_error_read_log_init

(

)

Set up ring-buffer for error-log.

Return values

0	Success - buffer was allocated.
!=0	Failure - buffer was not allocated.

log_error_read_loop()

static log_service_error log_error_read_loop ( const char *  log_file, size_t  size  )

static

Add all rows from a log file to the error-log ring-buffer.

We have to guesstimate where to start reading in the log:

• The error_log table is kept in a ring-buffer. Reading more items than we have space for is therefore harmless; we should however try to keep the waste down for performance reasons.
• In the traditional log, the part of the row before the message is 63 characters long. This gets converted into an event header. The header's size is platform-dependent, but usually shorter than 63 bytes. Thus, the size of each record in the input will be more or less the size of its corresponding record in the output. As a consequence, reading the ring-buffer's size from the input should be about right.
• When reading the JSON log, we'll fill in the event header from the parsed values, but we will also attach the entire JSON record to the event. Each record in the ring-buffer is therefore the size of the original JSON record, plus the size of a record header. As a consequence reading the ring-buffer's size from the input will give us more events than we need (because we "lose" about 50 bytes to the header for each event). However, the input is of variable length and we can not tell whether it's a few long rows or a lot of short ones. Therefore, we assume the worst (rather than the average) case and try to read input the size of the ring-buffer. This will mean that we read some more rows than we have space for, but since it's a ring-buffer, that means that the oldest entries will be discarded to make room for the younger ones, and we'll end up with the correct result.

Parameters

log_file	The file's name
size	length of the input file (in bytes)

Return values

LOG_SERVICE_SUCCESS	success
LOG_SERVICE_OPEN_FAILED	failed to open file
LOG_SERVICE_SEEK_FAILED	seek failed
LOG_SERVICE_UNABLE_TO_READ	read failed
LOG_SERVICE_PARSE_ERROR	could not find delimiter (' ')

log_sink_perfschema()

int log_sink_perfschema	(	void *	instance,
		log_line *	ll
	)

services: log sinks: logging to performance_schema ring-buffer

Will write timestamp, label, thread-ID, and message to stderr/file. If you should not be able to specify a label, one will be generated for you from the line's priority field.

Parameters

instance	instance handle
ll	the log line to write

Return values

int	number of added fields, if any

log_sink_pfs_event_add()

log_service_error log_sink_pfs_event_add	(	log_sink_pfs_event *	e,
		const char *	blob_src
	)

Add a log-event to the ring buffer.

In the ring-buffer, each event exists as a header and a blob. The header is a log_sink_pfs_event struct containing the traditional error-log columns. It is followed by a variable-length blob that contains just the message string in traditional log mode, and the complete event as JSON in JSON log format. The length of the event will be align to the correct boundary.

If writing the event would go past the end of the ring-buffer, we wrap around to the beginning of the buffer.

After the function success, ring_buffer_read will be set to a valid, non-zero value.

Parameters

e	filled-in event struct to copy into the ring-buffer
blob_src	variable-length part of the event to add to the ring-buffer

Return values

LOG_SERVICE_SUCCESS	event was added
LOG_SERVICE_NOT_AVAILABLE	ring-buffer not available
LOG_SERVICE_INVALID_ARGUMENT	event has no message
LOG_SERVICE_ARGUMENT_TOO_LONG	event is larger than buffer(!)

log_sink_pfs_event_count()

size_t log_sink_pfs_event_count

(

)

Get number of events currently in ring-buffer.

Caller should hold THR_LOCK_log_perschema when reading this.

Returns

number of events current in ring-buffer (0..)

log_sink_pfs_event_expire()

static void log_sink_pfs_event_expire ( void  )

inlinestatic

log_sink_pfs_event_first()

log_sink_pfs_event * log_sink_pfs_event_first

(

)

Get oldest event still in ring-buffer.

Caller should hold read-lock on THR_LOCK_log_perfschema when calling this.

Return values

nullptr	No events in buffer
otherwise	Address of oldest event in ring-buffer

log_sink_pfs_event_header_fits()

static bool log_sink_pfs_event_header_fits ( char *  p )

inlinestatic

Test whether we're so close to the end of the ring-buffer that another event header would not fit.

Parameters

p	The address where we'd like to write (e.g. ring_buffer_write)

Return values

true	There is enough space to write a header.
false	Insufficient space, must wrap around to buffer-start to write.

log_sink_pfs_event_next()

log_sink_pfs_event * log_sink_pfs_event_next

(

log_sink_pfs_event *

e

)

Get event following the supplied one.

Caller should hold read-lock on THR_LOCK_log_perfschema when calling this.

If advancing the read position puts the read-pointer beyond the highest-address event in the ring-buffer (which isn't necessarily the latest event, which is defined as the last event before catching up with the write-pointer), i.e. at a position where either a wrap- around marker exists, or there is not enough space for a header, we wrap around to the start of the ring-buffer.

Parameters

e	Last event the caller was processing. This event should be valid, non-NULL, and should not be a wrap-around marker (m_messages_length == 0).

Return values

nullptr	No more events in ring-buffer (caught up with writer)
otherwise	Address of the next event in the ring-buffer

log_sink_pfs_event_size()

static size_t log_sink_pfs_event_size ( log_sink_pfs_event *  e )

inlinestatic

Calculate the size of the given event (header + blob + '\0' + alignment).

The header is followed by a blob (error message or JSON representation of the complete event) and a '\0' terminator (for safety); it is then aligned to the correct address boundary if needed.

Parameters

e	The event we're interested in. Must be non-NULL.

Return values

The	total size (header + message + '\0' + padding) in bytes.

log_sink_pfs_event_valid()

log_sink_pfs_event * log_sink_pfs_event_valid	(	log_sink_pfs_event *	e,
		ulonglong	logged
	)

Use timestamp to check whether a given event-pointer still points to a valid event in the ring-buffer.

Caller should hold read-lock on THR_LOCK_log_perfschema when calling this.

Parameters

e	Address of event
logged	unique timestamp of event

Return values

nullptr	Event no longer exists in ring-buffer
otherwise	Address of the event in the ring-buffer

log_sink_pfs_read_end()

void log_sink_pfs_read_end

(

)

Release read-lock on ring-buffer.

log_sink_pfs_read_start()

void log_sink_pfs_read_start

(

)

Acquire a read-lock on the ring-buffer.

log_sink_pfs_sanitize_timestamp()

static void log_sink_pfs_sanitize_timestamp ( log_sink_pfs_event *  e )

inlinestatic

log_sink_pfs_write_wrap()

static int log_sink_pfs_write_wrap ( size_t  s )

inlinestatic

If the current event can fit in the ring-buffer, but the write position is so close to the physical end of the ring-buffer that the event won't fit there, wrap to the beginning of the ring-buffer.

Write a wrap-marker if possible. Adjust the pointers as needed:

If there isn't enough space to write the current event (of size s): a) if the read-pointer > write-pointer (which should always be the case after the first wrap), we wrap the read-pointer to the physical start of the ring-buffer b) write a wrap-marker if space permits c) wrap the write-pointer to the (physical) start of the ring-buffer

Caller must guarantee that event size <= ring-buffer-size.

Return values

0	didn't need to wrap
1	write-pointer wrapped
2	write-pointer and read-pointer wrapped

Variable Documentation

key_memory_log_sink_pfs

PSI_memory_key key_memory_log_sink_pfs

memory instrumentation

log_sink_pfs_buffered_bytes

ulong log_sink_pfs_buffered_bytes = 0

bytes in use (now)

log_sink_pfs_buffered_events

ulong log_sink_pfs_buffered_events = 0

events in buffer (now)

log_sink_pfs_expired_events

ulong log_sink_pfs_expired_events = 0

number of expired entries (ever)

log_sink_pfs_latest_timestamp

ulonglong log_sink_pfs_latest_timestamp

Initial value:

=
    0

timestamp of most recent write

log_sink_pfs_longest_event

ulong log_sink_pfs_longest_event = 0

longest event seen (ever)

ring_buffer_end

char* ring_buffer_end = nullptr

static

buffer end (for convenience)

ring_buffer_read

char* ring_buffer_read = nullptr

static

read pos (oldest entry, "tail")

ring_buffer_size

const size_t ring_buffer_size = 5 * 1024 * 1024

static

In the interest of not adding more settings to confuse the using, the error-log ring-buffer is of a static size for now.

This will be easy enough to change later if needs or policy change.

While a log-event can currently be up to 8 KB in size (and with minor changes be of practically arbitrary size), a majority of common events seem to be in the 150 - 200 bytes range (in trad mode, perhaps 100 more each in JSON mode) at the time of this writing. That lead us to expect a yield of 4-6 events per KB, and thus about 25,000 for a buffer of 5 MB.

ring_buffer_start

char* ring_buffer_start = nullptr

static

buffer start

ring_buffer_write

char* ring_buffer_write = nullptr

static

write position ("head")

THR_LOCK_log_perfschema

mysql_rwlock_t THR_LOCK_log_perfschema

static

ring-buffer rwlock Local to the sink that feeds the table performance_schema.error_log.

Code outside of the sink can acquire / release this lock using log_sink_pfs_read_start() / log_sink_pfs_read_start().