Logging

Examining log files may not sound like your idea of fun on a Friday evening, but it can be an invaluable aid in not only identifying problems that have already occurred, but spotting situations that, if left untouched, may soon cause you to lose more than a Friday night. MySQL has a number of different log files:

The error log This is the place to look for problems with starting, running, or stopping MySQL.

The query log All connections and executed queries are logged here.

The binary update log All SQL statements that change data are stored.

The slow query log All queries that took more than long_query_time to execute, or that didn't make use of any indexes, are logged here.

The update log This has been deprecated and should be replaced by the binary update log in all instances. It stores SQL statements that change data.

The ISAM log Logs all changes to the ISAM tables. Used only for debugging the ISAM code.

The Error Log

On Windows, the MySQL error log is called mysql.err, and on Unix it is called hostname.err (for example, test.mysqlhost.co.za.err). It is located in the data directory (usually C:\MySQL\data on Windows, /usr/local/mysql/data for binary Unix installations, /usr/local/var for source Unix installations, or /var/lib/mysql on Red Hat Linux flavors).

It contains startup and shutdown information and any critical errors that occur while running. It will log if the server died and was automatically restarted or if MySQL notices that a table needs to be automatically checked or repaired. The log may also contain a stack trace when MySQL dies. A sample error log follows:

010710 19:52:43  mysqld started 010710 19:52:43  Can't start server: Bind on TCP/IP port: Address already in use 010710 19:52:43  Do you already have another mysqld server running on port: 3306 ? 010710 19:52:43  Aborting 010710 19:52:43  /usr/local/mysql-3.23.39-pc-linux-gnu-i686/bin/mysqld:  Shutdown Complete 010710 19:52:43  mysqld ended 010710 19:55:23  mysqld started /usr/local/mysql-3.23.39-pc-linux-gnu-i686/bin/mysqld: ready for connections 010907 17:50:38  /usr/local/mysql-3.23.39-pc-linux-gnu-i686/bin/mysqld:  Normal shutdown 010907 17:50:38  /usr/local/mysql-3.23.39-pc-linux-gnu-i686/bin/mysqld:  Shutdown Complete 010907 17:50:38  mysqld ended 

This logs a situation you were warned about at the beginning of the chapter, where MySQL has been improperly started. Then, when you attempted to start MySQL properly, you could not because another process had already started. To solve the problem, you had to end the rogue process (such as by running kill s 9 PID or kill -9 PID on Unix, or using the Task Manager on Windows).

The Query Log

You can start the query log with the following option:

log =[query_log_filename]

in my.cnf. If you don't specify query_log_filename, the query log will be given the hostname.

It will log all connections and executed queries. It can be useful to see who is connecting (and when) for security purposes, as well as for debugging to see if the server is receiving queries correctly.

This kind of log has performance implications, so you should deactivate it if performance is a concern. The binary update log (which logs only update queries) can be useful in its place.

A sample query log follows:

/usr/local/mysql-max-4.0.1-alpha-pc-linux-gnu-i686/bin/mysqld, Version:  4.0.1-alpha-max-log, started with: Tcp port: 3306  Unix socket: /tmp/mysql.sock Time                 Id Command     Argument 020707  1:01:29       1 Connect     root@localhost on 020707  1:01:35       1 Init DB     firstdb 020707  1:01:38       1 Query       show tables 020707  1:01:51       1 Query       select * from innotest 020707  1:01:54       1 Quit

The Binary Update Log

Binary logging is activated when the log-bin option is used in the my.cnf or my.ini configuration file, as follows:

--log-bin[=binlog_filename]

Any extension will be dropped, as MySQL adds its own extension to the binary log. If no filename is specified, the binary log is named as the host machine, with -bin appended. MySQL also creates a binary index file, with the same name and an extension of .index. The index can be given a different name (and location) with the following option:

--log-bin-index=binlog_index_filename 

The binary update logs contain all the SQL statements that update the database, as well as how long the query took to execute and a timestamp of when the query was processed. Statements are logged in the same order as they are executed (after the query is complete but before transactions are completed or locks removed). Updates that have not yet been committed are placed in a cache first.

The binary update log is also useful for restoring backups (see Chapter 11, "Database Backups") and for when you are replicating a slave database from a master (see Chapter 12, "Database Replication").

Binary update logs start with an extension 001. A new one is created, with the number incremented by one, each time the server is restarted or one of mysqladmin refresh, mysqladmin flush-logs, or FLUSH LOGS is run. A new binary log is also created (and incremented) when the binary log reaches max_bin_log_size.

The max_bin_log_size value is set in the my.cnf or my.ini file as follows:

set-variable    = max_binlog_size = 1000M

You can see what size it has defaulted to, in bytes, by examining the variables:

 % mysqladmin -u root -pg00r002b variables | grep 'max_binlog_size' max_binlog_size                 | 1073741824

The binary update index file contains a list of all the binary logs used to date. A sample could be as follows:

./test-bin.001 ./test-bin.002 ./test-bin.003 ./test-bin.004

If you now flushed the logs, the binary update index would be appended with the new binary log:

% mysqladmin -u root -pg00r002b flush-logs 

The sample now contains the following:

./test-bin.001 ./test-bin.002 ./test-bin.003 ./test-bin.004 ./test-bin.005

You can delete all the unused binary update logs with RESET MASTER:

mysql> RESET MASTER; Query OK, 0 rows affected (0.00 sec)

The binary update index now reflects that there is only one binary update log:

./test-bin.006 
Warning 

Do not remove binary update logs until you are sure they are not going to be needed. If you use replication, be especially careful (see Chapter 12 for more on this). If you use the binary logs to restore backups, make sure you don't remove any that are more recent than your most recent backup.

Not all updates to all databases need to be logged; in many cases, you may only want to store updates to certain databases. The binlog-do-db and binlog-ignore-db options in the my.cnf and my.ini configuration files allow you to control this. The first specifically sets which database updates are to be logged. For example, the following:

binlog-do-db = firstdb

will log updates only to the firstdb database, but the following:

binlog-ignore-db = test

will log updates to all databases except test. You can add multiple lines if you want to log multiple databases:

binlog-do-db = test binlog-do-db = firstdb

When updates that are part of a transaction are to be logged, MySQL creates a buffer of the size specified by binlog-cache-size in your configuration file (the default is 32KB, or 32,768 bytes). Each thread can create one of these buffers. To avoid too many buffers being used at the same time, the variable max-binlog-cache-size is also set. The default maximum for this is 4GB, or 4,294,967,295 bytes.

Because the binary update log is a binary file, the data is stored more efficiently than in the old text update log. It also means that you cannot view the data with a text editor. The mysqlbinlog utility allows you to view the data:

C:\Program Files\MySQL\data>..\bin\mysqlbinlog test-bin.002 # at 4 #020602 18:40:02 server id  1   Start: binlog v 2, server v 4.0.1-alpha-max-log created 020602 18:40:02 # at 79 #020602 18:41:27 server id  1   Query   thread_id=3     exec_time=0  error_code=0 use firstdb; SET TIMESTAMP=1023036087; CREATE TABLE customer(id INT); # at 146 #020602 18:41:40 server id  1   Query   thread_id=3     exec_time=0      error_code=0 SET TIMESTAMP=1023036100; INSERT INTO customer(id) VALUES(1); # at 218 #020602 18:43:12 server id  1   Query   thread_id=5     exec_time=0      error_code=0 SET TIMESTAMP=1023036192; INSERT INTO customer VALUES(12); # at 287 #020602 18:45:00 server id  1   Stop 

To use a binary update log to update the contents of a MySQL server, simply pipe the results to the required server, for example:

 % mysqlbinlog ..\data\test-bin.022 | mysql 
Note 

One of the consequences of using the binary update log is that concurrent inserts will not work with CREATE…INSERT or INSERT…SELECT. Concurrent inserts are where MySQL allows reads and writes to happen at the same time in MyISAM tables, but enabling them with these two kinds of statement would mean that the binary update log could not be reliably used for restoring backups or for replication.

The Slow Query Log

You start the slow query log with the following option:

log-slow-queries[=slow_query_log_filename]

in the configuration file. If slow_query_log_filename is not supplied, the slow query log will be given the name of the host machine, with -slow.log appended (for example, test.mysqlhost.co.za-slow.log).

All SQL statements that take longer to execute than long_query_time are logged.

This is set in the my.cnf or my.ini config file as follows:

set-variable    = long_query_time = 20

It is measured in seconds (though MySQL is planning to change soon to measure in microseconds, so check the latest documentation).

If the option log-long-format is set, then all queries that do not make use of an index are also logged. Place the following line:

log-long-format

in your my.cnf or my.ini file to do this.

This is a useful log to have in place; the performance impact is not high (assuming most of your queries are not slow!), and it highlights the queries that most need attention (where indexes are missing or not optimally used).

A sample slow query log follows:

/usr/local/mysql-max-4.0.1-alpha-pc-linux-gnu-i686/bin/mysqld, Version:  4.0.1-alpha-max-log, started with: Tcp port: 3306  Unix socket: /tmp/mysql.sock Time                 Id Command    Argument # Time: 020707 13:57:57 # User@Host: root[root] @ localhost [] # Query_time: 0  Lock_time: 0  Rows_sent: 8  Rows_examined: 8 use firstdb; select id from sales; # Time: 020707 13:58:47 # User@Host: root[root] @ localhost [] # Query_time: 0  Lock_time: 0  Rows_sent: 6  Rows_examined: 8 

In this log, the select id from sales query is there because it did not make use of an index. The query could have made use of an index on the id field. See Chapter 4, "Indexes and Query Optimization," for a discussion on where to use indexes.

You can also use the mysqldumpslow utility to display the results of the slow query log:

% mysqldumpslow test-slow.log  Reading mysql slow query log from test-slow.log Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost   # Query_time: N  Lock_time: N  Rows_sent: N  Rows_examined: N   use firstdb;   select id from sales Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost   # Query_time: N  Lock_time: N  Rows_sent: N  Rows_examined: N   DELETE FROM sales WHERE id>N Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost   # Query_time: N  Lock_time: N  Rows_sent: N  Rows_examined: N   select id from sales where id<N

Rotating Logs

Log files, although extremely useful, have a cancerous nature in that they continue to grow until there is no space left for anything else. Eventually you'll need to remove the excess logs, and there is no better way of doing this than having some scripts that automatically perform this task for you.

For the noncritical logs, doing the following will suffice (assuming you start in the directory containing the log files). The following is on a Unix system:

mv logfile backup_directory/logfile.old mysqladmin flush-logs

And the following is on a Windows system:

move logfile backup_directory\logfile.old mysqladmin flush-logs

Flushing the logs (which you can also do while connected the server with the SQL statement FLUSH LOGS) closes and reopens log files that do not increment in sequence (such as the slow query log). Or, in the case of logs that are incremented (the binary update log), flushing the logs creates a new log file with an extension incremented by one from the previous one and forces MySQL to use this new file.

The old log file can be either removed to backup or just deleted if it will be of no further use. Any queries that are processed between the two statements are not logged, as the query log for that moment in time does not exist. Logging is only re-created when the logs are flushed. For example, assuming that the query log is called querylog, the following set of commands shows one way to rotate logs. You need to have two windows open, Window1 connected to your shell or command line, and Window2 connected to MySQL.

First, from Window1:

% mv querylog querylog.old 

Now run a query fromWindow2 (connected to MySQL):

mysql> SELECT * FROM sales;   

See if the query has been logged, from Window1:

% tail querylog tail: querylog: No such file or directory

Until you flush the logs, no log file exists and no queries will be logged:

% mysqladmin -uroot -pg00r002b flush-logs 

Run another query from Window2:

mysql> SELECT * FROM customer; 

This time it's been added to the query log, as you can see from Window1:

% tail querylog /usr/local/mysql-max-4.0.1-alpha-pc-linux-gnu-i686/bin/mysqld, Version:  4.0.1-alpha-max-log, started with: Tcp port: 3306  Unix socket: /tmp/mysql.sock Time                 Id Command    Argument 020707 20:45:23       5 Quit        020707 20:45:26       4 Query       select * from customer

This technique cannot be used with the critical log files (such as the binary update log) because if they are to be useful for replication or for restoration of backups, there cannot be the possibility of any queries being missed. For this reason, a new binary update log, with an extension that increments by one each time, is created whenever the logs are flushed. Records will only be added to the latest log, meaning you can move older ones without worrying about queries going missing. Assuming the binary update log is called gmbinlog and starting with one binary update log, try the following:

C:\Program Files\MySQL\data>dir *-bin*  Volume in drive C has no label  Volume Serial Number is 2D20-1303  Directory of C:\Program Files\MySQL\data GMBINLOG 001           272  07-07-02  8:50p gmbinlog.001 GMBINL~1 IND             0  07-07-02  8:48p gmbinlog.index          2 file(s)            398 bytes          0 dir(s)       33,868.09 MB free C:\Program Files\MySQL\data>..\bin\mysqladmin flush-logs C:\Program Files\MySQL\data>dir *-bin*  Volume in drive C has no label  Volume Serial Number is 2D20-1303  Directory of C:\Program Files\MySQL\data GMBINLOG 001           272  07-07-02  8:50p gmbinlog.001 GMBINL~1 IND             0  07-07-02  8:48p gmbinlog.index GMBINLOG 002             0  07-07-02  8:50p gmbinlog.001          3 file(s)            398 bytes          0 dir(s)       33,868.09 MB free C:\Program Files\MySQL\data> move gmbinlog.001 D:\backup_directory\gmbinlog001.old 

Warning 

If you're using replication, do not remove old binary log files until you are sure no slave servers will still need them. See Chapter 12 for more details.

MySQL for Red Hat Linux comes with a log rotation script. If the distribution you're using does not, you can use this one as the basis to create your own:

# This logname is set in mysql.server.sh that ends up in /etc/rc.d/init.d/mysql # # If the root user has a password you have to create a # /root/.my.cnf configuration file with the following # content: # # [mysqladmin] # password = <secret> # user= root # # where "<secret>" is the password. # # ATTENTION: This /root/.my.cnf should be readable ONLY # for root ! /usr/local/var/mysqld.log {         # create 600 mysql mysql         notifempty         daily         rotate 3         missingok         compress     postrotate         # just if mysqld is really running         if test -n "`ps acx|grep mysqld`"; then                 /usr/local/bin/mysqladmin flush-logs         fi     endscript }



Mastering MySQL 4
Mastering MySQL 4
ISBN: 0782141625
EAN: 2147483647
Year: 2003
Pages: 230
Authors: Ian Gilfillan

flylib.com © 2008-2017.
If you may any questions please contact us: flylib@qtcs.net