Logging is a very important diagnostic tool for understanding the behavior of the application as well as troubleshooting any issue with the application. Since MySQL Enterprise Backup (MEB) is a command line application, there is little interaction with the myriad of operations going on behind the scenes. Thus, logging messages are very important for knowing the progress of current operation as well as learning more about errors should they occur. The messages logged by MEB are written to the con
Mysql 09-Mar-2017

Improved Logging Messages

Introduction

Logging is a very important diagnostic tool for understanding the behavior of the application as well as troubleshooting any issue with the application. Since MySQL Enterprise Backup (MEB) is a command line application, there is little interaction with the myriad of operations going on behind the scenes. Thus, logging messages are very important for knowing the progress of current operation as well as learning more about errors should they occur. The messages logged by MEB are written to the console and the log file as depicted in the following diagram, which looks similar to the Tee command in UNIX.

By default, MEB creates the log file in the default ‘<backup_dir>/meta’ directory with a name like MEB_<Date.time>_<operation_name>.log. For example – MEB created a log file with the name, ‘MEB_2017-02-24.07-47-09_backup.log’, for the backup operation executed to save the log messages. User may specify any other existing directory to create the log file using the --messages-logdir= <directory_ path> option. Users may also skip the log file creation using the --skip-messages-logdir option, but it is not recommended.

 

Background

 

Prior to 4.1 release, the log messages are printed as shown below.

Notice how the messages seem to interlace, making it harder to read a logical flow from the output. There were several reasons for this.

 

  • MEB is a multithreaded application. From the output, there was no way to determine which thread printed the message. This is very crucial information to know when diagnosing problems or performance.
  • The log messages contained trace levels starting with the string, ‘mysqlbackup:’. But this did not convey any useful information. Furthermore, some of these log messages are printed without any timestamp prefixes.

 

The trace levels of the log messages, in the order of increasing fineness, are:

 

  • 0 - INFO (information, warnings, errors)
  • 1 - FINE (more information given than at trace level 0)
  • 2 - FINER (finer level of information given than at trace level 1)
  • 3 - FINEST (finest level of information that can be given)

 

The improvements

 

Logging has been greatly improved In the 4.1 release. They are now printed as shown below. 

The improvements are small but have a profound effect on readability and usability. These improvements include the following.

 

  • MEB now prints each thread name that it creates. The thread name is an abbreviation derived from the thread description. They will also be helpful in analyzing the work performed by each thread. The following table shows several examples

 

Thread Name  Thread Description
 RDR1  ReaDeR thread #1
 PCR1  ProCessoR thread #1
 WTR1  WriTeR thread #1
 CLD1  CLouD thread #1
 RLR1  Redo Log Reader thread #1
 RLP1  Redo Log Processor thread #1
 RLW1  Redo Log Writer thread #1
 ALW1  Apply Log Worker thread #1

 

  • Every message that includes a trace level is now prefixed with the timestamp. 
  • The logger module has been improved for better performance.