Agrégateur de flux

Recently I switched on the MariaDB slow query logging flag log_queries_not_using_indexes just for curiosity on one of our customers systems:

mariadb> SHOW GLOBAL VARIABLES LIKE 'log_quer%'; +-------------------------------+-------+ | Variable_name | Value | +-------------------------------+-------+ | log_queries_not_using_indexes | OFF | +-------------------------------+-------+ mariadb> SET GLOBAL log_queries_not_using_indexes = ON;

A tail -f on the MariaDB Slow Query Log caused a huge flickering on my screen.
I got to see about 5 times per second the following statement sequence in the Slow Query Log:

# User@Host: app_admin[app_admin] @ [192.168.1.42] Id: 580195 # Query_time: 0.091731 Lock_time: 0.000028 Rows_sent: 273185 Rows_examined: 273185 SELECT LAST_INSERT_ID() FROM `placeholder`; # Query_time: 0.002858 Lock_time: 0.000043 Rows_sent: 6856 Rows_examined: 6856 SELECT LAST_INSERT_ID() FROM `data`;

So at least 5 times 95 ms (5 x (92 + 3) = 475 ms) per 1000 ms (48%) where spent in these 2 statements which are running quite fast but do not use an index (long_query_time was set to 2 seconds).

So I estimate, that this load job can be speed up at least by factor 2 when using the LAST_INSERT_ID() function correctly not considering the possible reduction of network traffic (throughput and response time).

To show the problem I made a little test case:

mariadb> INSERT INTO test VALUES (NULL, 'Some data', NULL); mariadb> SELECT LAST_INSERT_ID() from test; +------------------+ | LAST_INSERT_ID() | +------------------+ | 1376221 | ... | 1376221 | +------------------+ 1048577 rows in set (0.27 sec)

The response time of this query will linearly grow with the amount of data as long as they fit into memory and the response time will explode as soon as the table does not fit into memory any more. In addition the network traffic would be reduced by about 8 Mbyte (1 Mio rows x BIGINT UNSIGNED (64-bit) + some header per row?) per second (6-8% of the network bandwidth of a 1 Gbit network link).

shell> ifconfig lo | grep bytes RX bytes:2001930826 (2.0 GB) TX bytes:2001930826 (2.0 GB) shell> ifconfig lo | grep bytes RX bytes:2027289745 (2.0 GB) TX bytes:2027289745 (2.0 GB)

The correct way of doing the query would be:

mariadb> SELECT LAST_INSERT_ID(); +------------------+ | last_insert_id() | +------------------+ | 1376221 | +------------------+ 1 row in set (0.00 sec)

The response time is below 10 ms.

So why is the first query taking so long an consuming so many resources? To get an answer to this question the MariaDB Optimizer can tell us more with the Query Execution Plan (QEP):

mariadb> EXPLAIN SELECT LAST_INSERT_ID() FROM test; +------+-------------+-------+-------+---------------+---------+---------+------+---------+-------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | +------+-------------+-------+-------+---------------+---------+---------+------+---------+-------------+ | 1 | SIMPLE | test | index | NULL | PRIMARY | 4 | NULL | 1048577 | Using index | +------+-------------+-------+-------+---------------+---------+---------+------+---------+-------------+ mariadb> EXPLAIN FORMAT=JSON SELECT LAST_INSERT_ID() FROM test; { "query_block": { "select_id": 1, "table": { "table_name": "test", "access_type": "index", "key": "PRIMARY", "key_length": "4", "used_key_parts": ["id"], "rows": 1048577, "filtered": 100, "using_index": true } } }

The database does a Full Index Scan (FIS, other call it a Index Fast Full Scan (IFFS)) on the Primary Key (column id).

The Query Execution Plan of the second query looks as follows:

mariadb> EXPLAIN SELECT LAST_INSERT_ID(); +------+-------------+-------+------+---------------+------+---------+------+------+----------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | +------+-------------+-------+------+---------------+------+---------+------+------+----------------+ | 1 | SIMPLE | NULL | NULL | NULL | NULL | NULL | NULL | NULL | No tables used | +------+-------------+-------+------+---------------+------+---------+------+------+----------------+ mariadb> EXPLAIN FORMAT=JSON SELECT LAST_INSERT_ID(); { "query_block": { "select_id": 1, "table": { "message": "No tables used" } } }
Taxonomy upgrade extras: query tuningOptimizerindexindex scanlast_insert_idexplainslowlog

Recently I switched on the MariaDB slow query logging flag log_queries_not_using_indexes just for curiosity on one of our customers systems:

mariadb> SHOW GLOBAL VARIABLES LIKE 'log_quer%'; +-------------------------------+-------+ | Variable_name | Value | +-------------------------------+-------+ | log_queries_not_using_indexes | OFF | +-------------------------------+-------+ mariadb> SET GLOBAL log_queries_not_using_indexes = ON;

A tail -f on the MariaDB Slow Query Log caused a huge flickering on my screen.
I got to see about 5 times per second the following statement sequence in the Slow Query Log:

# User@Host: app_admin[app_admin] @ [192.168.1.42] Id: 580195 # Query_time: 0.091731 Lock_time: 0.000028 Rows_sent: 273185 Rows_examined: 273185 SELECT LAST_INSERT_ID() FROM `placeholder`; # Query_time: 0.002858 Lock_time: 0.000043 Rows_sent: 6856 Rows_examined: 6856 SELECT LAST_INSERT_ID() FROM `data`;

So at least 5 times 95 ms (5 x (92 + 3) = 475 ms) per 1000 ms (48%) where spent in these 2 statements which are running quite fast but do not use an index (long_query_time was set to 2 seconds).

So I estimate, that this load job can be speed up at least by factor 2 when using the LAST_INSERT_ID() function correctly not considering the possible reduction of network traffic (throughput and response time).

To show the problem I made a little test case:

mariadb> INSERT INTO test VALUES (NULL, 'Some data', NULL); mariadb> SELECT LAST_INSERT_ID() from test; +------------------+ | LAST_INSERT_ID() | +------------------+ | 1376221 | ... | 1376221 | +------------------+ 1048577 rows in set (0.27 sec)

The response time of this query will linearly grow with the amount of data as long as they fit into memory and the response time will explode as soon as the table does not fit into memory any more. In addition the network traffic would be reduced by about 8 Mbyte (1 Mio rows x BIGINT UNSIGNED (64-bit) + some header per row?) per second (6-8% of the network bandwidth of a 1 Gbit network link).

shell> ifconfig lo | grep bytes RX bytes:2001930826 (2.0 GB) TX bytes:2001930826 (2.0 GB) shell> ifconfig lo | grep bytes RX bytes:2027289745 (2.0 GB) TX bytes:2027289745 (2.0 GB)

The correct way of doing the query would be:

mariadb> SELECT LAST_INSERT_ID(); +------------------+ | last_insert_id() | +------------------+ | 1376221 | +------------------+ 1 row in set (0.00 sec)

The response time is below 10 ms.

So why is the first query taking so long an consuming so many resources? To get an answer to this question the MariaDB Optimizer can tell us more with the Query Execution Plan (QEP):

mariadb> EXPLAIN SELECT LAST_INSERT_ID() FROM test; +------+-------------+-------+-------+---------------+---------+---------+------+---------+-------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | +------+-------------+-------+-------+---------------+---------+---------+------+---------+-------------+ | 1 | SIMPLE | test | index | NULL | PRIMARY | 4 | NULL | 1048577 | Using index | +------+-------------+-------+-------+---------------+---------+---------+------+---------+-------------+ mariadb> EXPLAIN FORMAT=JSON SELECT LAST_INSERT_ID() FROM test; { "query_block": { "select_id": 1, "table": { "table_name": "test", "access_type": "index", "key": "PRIMARY", "key_length": "4", "used_key_parts": ["id"], "rows": 1048577, "filtered": 100, "using_index": true } } }

The database does a Full Index Scan (FIS, other call it a Index Fast Full Scan (IFFS)) on the Primary Key (column id).

The Query Execution Plan of the second query looks as follows:

mariadb> EXPLAIN SELECT LAST_INSERT_ID(); +------+-------------+-------+------+---------------+------+---------+------+------+----------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | +------+-------------+-------+------+---------------+------+---------+------+------+----------------+ | 1 | SIMPLE | NULL | NULL | NULL | NULL | NULL | NULL | NULL | No tables used | +------+-------------+-------+------+---------------+------+---------+------+------+----------------+ mariadb> EXPLAIN FORMAT=JSON SELECT LAST_INSERT_ID(); { "query_block": { "select_id": 1, "table": { "message": "No tables used" } } }
Taxonomy upgrade extras: query tuningOptimizerindexindex scanlast_insert_idexplainslowlog

We have sometimes discussions with our customers whether to store LOBs (Large Objects) in the database or not. To not rephrase the arguments again and again I have summarized them in the following lines.

The following items are more or less valid for all large data types (BLOB, TEXT and theoretically also for JSON and GIS columns) stored in a MySQL or MariaDB (or any other relational) database.

The idea of a relational table based data-store is to store structured data (numbers, data and short character strings) to have a quick write and read access to them.

And yes, you can also store other things like videos, huge texts (PDF, emails) or similar in a RDBMS but they are principally not designed for such a job and thus non optimal for the task. Software vendors implement such features not mainly because it makes sense but because users want it and the vendors want to attract users (or their managers) with such features (USP, Unique Selling Proposition). Here also one of my Mantras: Use the right tool for the right task:

The main topics to discuss related to LOBs are: Operations, performance, economical reasons and technical limitations.

Disadvantages of storing LOBs in the database

• The database will grow fast. Operations will become more costly and complicated.
• Backup and restore will become more costly and complicated for the admin because of the increased size caused by LOBs.
• Backup and restore will take longer because of the same reason.
• Database and table management functions (OPTIMIZE, ALTER, etc.) will take longer on big LOB tables.
• Smaller databases need less RAM/disk space and are thus cheaper.
• Smaller databases fit better into your RAM and are thus potentially faster (RAM vs disk access).
• RDBMS are a relatively slow technology (compared to others). Reading LOBs from the database is significantly slower than reading LOBs from a filer for example.
• LOBs stored in the database will spoil your database cache (InnoDB Buffer Pool) and thus possibly slow down other queries (does not necessarily happen with more sophisticated RBDMS).
• LOB size limitation of 1 Gbyte in reality (max_allowed_packet, theoretically limit is at 4 Gbyte) for MySQL/MariaDB.
• Expensive, fast database store (RAID-10, SSD) is wasted for something which can be stored better on a cheap slow file store (RAID-5, HDD).
• It is programmatically often more complicated to get LOBs from a database than from a filer (depends on your libraries).

Advantages of storing LOBs in the database

• Atomicity between data and LOB is guaranteed by transactions (is it really in MySQL/MariaDB?).
• There are no dangling links (reference from data to LOB) between data and LOB.
• Data and LOB are from the same point in time and can be included in the same backup.
• Data and LOB can be transferred simultaneously to other machines, by database replication or dump/restore.
• Applications can use the same mechanism to get the data and the LOB. Remote access needs no separate file transfer for the LOB.

Conclusion

So basically you have to balance the advantages vs. the disadvantages of storing LOBs in the database and decided what arguments are more important in your case.

If you have some more good arguments pro or contra storing LOBs in the database please let me know.

Literature

Check also various articles on Google.

• Nim: Repeat after me: MySQL is not a filesystem

Taxonomy upgrade extras: blobtextlobdesign

We have sometimes discussions with our customers whether to store LOBs (Large Objects) in the database or not. To not rephrase the arguments again and again I have summarized them in the following lines.

The following items are more or less valid for all large data types (BLOB, TEXT and theoretically also for JSON and GIS columns) stored in a MySQL or MariaDB (or any other relational) database.

The idea of a relational table based data-store is to store structured data (numbers, data and short character strings) to have a quick write and read access to them.

And yes, you can also store other things like videos, huge texts (PDF, emails) or similar in a RDBMS but they are principally not designed for such a job and thus non optimal for the task. Software vendors implement such features not mainly because it makes sense but because users want it and the vendors want to attract users (or their managers) with such features (USP, Unique Selling Proposition). Here also one of my Mantras: Use the right tool for the right task:

The main topics to discuss related to LOBs are: Operations, performance, economical reasons and technical limitations.

Disadvantages of storing LOBs in the database

• The database will grow fast. Operations will become more costly and complicated.
• Backup and restore will become more costly and complicated for the admin because of the increased size caused by LOBs.
• Backup and restore will take longer because of the same reason.
• Database and table management functions (OPTIMIZE, ALTER, etc.) will take longer on big LOB tables.
• Smaller databases need less RAM/disk space and are thus cheaper.
• Smaller databases fit better into your RAM and are thus potentially faster (RAM vs disk access).
• RDBMS are a relatively slow technology (compared to others). Reading LOBs from the database is significantly slower than reading LOBs from a filer for example.
• LOBs stored in the database will spoil your database cache (InnoDB Buffer Pool) and thus possibly slow down other queries (does not necessarily happen with more sophisticated RBDMS).
• LOB size limitation of 1 Gbyte in reality (max_allowed_packet, theoretically limit is at 4 Gbyte) for MySQL/MariaDB.
• Expensive, fast database store (RAID-10, SSD) is wasted for something which can be stored better on a cheap slow file store (RAID-5, HDD).
• It is programmatically often more complicated to get LOBs from a database than from a filer (depends on your libraries).

Advantages of storing LOBs in the database

• Atomicity between data and LOB is guaranteed by transactions (is it really in MySQL/MariaDB?).
• There are no dangling links (reference from data to LOB) between data and LOB.
• Data and LOB are from the same point in time and can be included in the same backup.

Conclusion

So basically you have to balance the advantages vs. the disadvantages of storing LOBs in the database and decided what arguments are more important in your case.

If you have some more good arguments pro or contra storing LOBs in the database please let me know.

Literature

Check also various articles on Google.

• Nim: Repeat after me: MySQL is not a filesystem

Taxonomy upgrade extras: blobtextlobdesign

Preparing the MySQL Enterprise Administrator Training I found that the MySQL Enterprise Backup Incremental Backup is not described very well. Thus I tried it out and wrote down this how-to:

Incremental Differential Backup

Full Backup mysqlbackup --user=root --backup-dir=/tape/full backup-and-apply-log grep end_lsn /tape/full/meta/backup_variables.txt end_lsn=2583666
Incremental Backups mysqlbackup --user=root --incremental-backup-dir=/tape/inc1 --start-lsn=2583666 --incremental backup grep end_lsn /tape/inc1/meta/backup_variables.txt end_lsn=2586138 mysqlbackup --user=root --incremental-backup-dir=/tape/inc2 --start-lsn=2586138 --incremental backup grep end_lsn /tape/inc2/meta/backup_variables.txt end_lsn=2589328 mysqlbackup --user=root --incremental-backup-dir=/tape/inc3 --start-lsn=2589328 --incremental backup grep end_lsn /tape/inc3/meta/backup_variables.txt end_lsn=2592519
Binary Log Backups cp /var/lib/binlog/binlog.* /tape/binlog/
Restore

This step will modify the original full backup!

mysqlbackup --incremental-backup-dir=/tape/inc1 --backup-dir=/tape/full apply-incremental-backup mysqlbackup --incremental-backup-dir=/tape/inc2 --backup-dir=/tape/full apply-incremental-backup mysqlbackup --incremental-backup-dir=/tape/inc3 --backup-dir=/tape/full apply-incremental-backup mysqlbackup --user=root --datadir=/var/lib/mysql --backup-dir=/tape/full copy-back
Point-in-Time-Recovery grep binlog_position /tape/inc3/meta/backup_variables.txt /tape/inc3/meta/backup_variables.txt:binlog_position=binlog.000001:7731 cd /tape/binlog mysqlbinlog --disable-log-bin --start-position=7731 binlog.000001 | mysql -uroot
Incremental Cumulative Backup

Full Backup mysqlbackup --user=root --backup-dir=/tape/full backup-and-apply-log grep end_lsn /tape/full/meta/backup_variables.txt end_lsn=2602954 Incremental Backups mysqlbackup --user=root --incremental-backup-dir=/tape/inc1 --start-lsn=2602954 --incremental backup mysqlbackup --user=root --incremental-backup-dir=/tape/inc2 --start-lsn=2602954 --incremental backup mysqlbackup --user=root --incremental-backup-dir=/tape/inc3 --start-lsn=2602954 --incremental backup
Binary Log Backups cp /home/mysql/database/mysql-5.7/binlog/binlog.* /tape/binlog/
Restore

This step will modify the original full backup!

mysqlbackup --incremental-backup-dir=/tape/inc3 --backup-dir=/tape/full apply-incremental-backup mysqlbackup --user=root --datadir=/var/lib/mysql --backup-dir=/tape/full copy-back
Point-in-Time-Recovery grep binlog_position /tape/*/meta/backup_variables.txt /tape/inc3/meta/backup_variables.txt:binlog_position=binlog.000001:7731 cd /tape/binlog mysqlbinlog --disable-log-bin --start-position=7731 binlog.000001 | mysql -uroot

I very much dislike that during my restore the backup is modified. So if I do a mistake during restore my backup is gone and I am doomed.

Taxonomy upgrade extras: BackupRestoreMySQL Enterprise Backupenterpriseincrementalcumulativedifferential

Preparing the MySQL Enterprise Administrator Training I found that the MySQL Enterprise Backup Incremental Backup is not described very well. Thus I tried it out and wrote down this how-to:

Incremental Differential Backup

Full Backup mysqlbackup --user=root --backup-dir=/tape/full backup-and-apply-log grep end_lsn /tape/full/meta/backup_variables.txt end_lsn=2583666
Incremental Backups mysqlbackup --user=root --incremental-backup-dir=/tape/inc1 --start-lsn=2583666 --incremental backup grep end_lsn /tape/inc1/meta/backup_variables.txt end_lsn=2586138 mysqlbackup --user=root --incremental-backup-dir=/tape/inc2 --start-lsn=2586138 --incremental backup grep end_lsn /tape/inc2/meta/backup_variables.txt end_lsn=2589328 mysqlbackup --user=root --incremental-backup-dir=/tape/inc3 --start-lsn=2589328 --incremental backup grep end_lsn /tape/inc3/meta/backup_variables.txt end_lsn=2592519
Binary Log Backups cp /var/lib/binlog/binlog.* /tape/binlog/
Restore

This step will modify the original full backup!

mysqlbackup --incremental-backup-dir=/tape/inc1 --backup-dir=/tape/full apply-incremental-backup mysqlbackup --incremental-backup-dir=/tape/inc2 --backup-dir=/tape/full apply-incremental-backup mysqlbackup --incremental-backup-dir=/tape/inc3 --backup-dir=/tape/full apply-incremental-backup mysqlbackup --user=root --datadir=/var/lib/mysql --backup-dir=/tape/full copy-back
Point-in-Time-Recovery grep binlog_position /tape/inc3/meta/backup_variables.txt /tape/inc3/meta/backup_variables.txt:binlog_position=binlog.000001:7731 cd /tape/binlog mysqlbinlog --disable-log-bin --start-position=7731 binlog.000001 | mysql -uroot
Incremental Cumulative Backup

Full Backup mysqlbackup --user=root --backup-dir=/tape/full backup-and-apply-log grep end_lsn /tape/full/meta/backup_variables.txt end_lsn=2602954 Incremental Backups mysqlbackup --user=root --incremental-backup-dir=/tape/inc1 --start-lsn=2602954 --incremental backup mysqlbackup --user=root --incremental-backup-dir=/tape/inc2 --start-lsn=2602954 --incremental backup mysqlbackup --user=root --incremental-backup-dir=/tape/inc3 --start-lsn=2602954 --incremental backup
Binary Log Backups cp /home/mysql/database/mysql-5.7/binlog/binlog.* /tape/binlog/
Restore

This step will modify the original full backup!

mysqlbackup --incremental-backup-dir=/tape/inc3 --backup-dir=/tape/full apply-incremental-backup mysqlbackup --user=root --datadir=/var/lib/mysql --backup-dir=/tape/full copy-back
Point-in-Time-Recovery grep binlog_position /tape/*/meta/backup_variables.txt /tape/inc3/meta/backup_variables.txt:binlog_position=binlog.000001:7731 cd /tape/binlog mysqlbinlog --disable-log-bin --start-position=7731 binlog.000001 | mysql -uroot

I very much dislike that during my restore the backup is modified. So if I do a mistake during restore my backup is gone and I am doomed.

Taxonomy upgrade extras: BackupRestoreMySQL Enterprise Backupenterpriseincrementalcumulativedifferential

FromDual has the pleasure to announce the release of the new version 1.2.5 of the popular Backup and Recovery Manager for MySQL and MariaDB (fromdual_brman).

You can download the FromDual Backup and Recovery Manager from here.

In the inconceivable case that you find a bug in the FromDual Backup and Recovery Manager please report it to our Bugtracker or just send us an email.

Any feedback, statements and testimonials are welcome as well! Please send them to feedback@fromdual.com.

Upgrade from 1.2.x to 1.2.5 # cd ${HOME}/product # tar xf /download/fromdual_brman-1.2.5.tar.gz # rm -f fromdual_brman # ln -s fromdual_brman-1.2.5 fromdual_brman
Changes in FromDual Backup Manager 1.2.5

This release contains mainly fixes related to the backup catalog and the backup type cleanup.

You can verify your current FromDual Backup Manager version with the following command:

shell> fromdual_bman --version
FromDual Backup Manager

• Docker container is ready.
• Testing infrastructure improved.
• Better option checking to be usage compliant.
• Option handling and checking refactored.
• PHP variable variables_order is included into program. No more php.ini change required any more.
• Connection error made more verbose.
• Downstream myEnv.inc library from rev873.
• Incompatibility change: Default --backupdir location changed from ./bck to $HOME/bck.

FromDual Backup Manager Catalog

• Catalog creation and upgrade messages put into right order.
• Backup catalog should be upgraded directly to newest release when created.
• Only do catalog version check if --upgrade is not specified.
• Incompatibility change: Catalog operation options (--create and --upgrade) made more consistent (--type=catalog). This could lead to different behaviour than earlier!
• Backup cleanup in catalog made nicer.
• Catalog version changed from 010 to 020.

FromDual Backup Manager Cleanup

• Archive cleanup output empty line removed.
• Backup cleanup in catalog made nicer.
• Cleanup should delete only instance backups but not all backups if specified (bug #166).

FromDual Backup Manager Logical Full and Schema backup

• Omit warning for non-transactional tables if option --blocking-backup is set.
• Function getDumpOverview now also includes empty schemata.
• Transactional storage engine selection made ready for MariaDB 10.1/10.2 and MySQL 8.0.

Taxonomy upgrade extras: BackupRestoreRecoverypitrfromdual_brmanbrmanreleasebmanrman

FromDual has the pleasure to announce the release of the new version 1.2.5 of the popular Backup and Recovery Manager for MySQL and MariaDB (fromdual_brman).

You can download the FromDual Backup and Recovery Manager from here.

In the inconceivable case that you find a bug in the FromDual Backup and Recovery Manager please report it to our Bugtracker or just send us an email.

Any feedback, statements and testimonials are welcome as well! Please send them to feedback@fromdual.com.

Upgrade from 1.2.x to 1.2.5 # cd ${HOME}/product # tar xf /download/fromdual_brman-1.2.5.tar.gz # rm -f fromdual_brman # ln -s fromdual_brman-1.2.5 fromdual_brman
Changes in FromDual Backup Manager 1.2.5

This release contains mainly fixes related to the backup catalog and the backup type cleanup.

You can verify your current FromDual Backup Manager version with the following command:

shell> fromdual_bman --version
FromDual Backup Manager

• Docker container is ready.
• Testing infrastructure improved.
• Better option checking to be usage compliant.
• Option handling and checking refactored.
• PHP variable variables_order is included into program. No more php.ini change required any more.
• Connection error made more verbose.
• Downstream myEnv.inc library from rev873.
• Incompatibility change: Default --backupdir location changed from ./bck to $HOME/bck.

FromDual Backup Manager Catalog

• Catalog creation and upgrade messages put into right order.
• Backup catalog should be upgraded directly to newest release when created.
• Only do catalog version check if --upgrade is not specified.
• Incompatibility change: Catalog operation options (--create and --upgrade) made more consistent (--type=catalog). This could lead to different behaviour than earlier!
• Backup cleanup in catalog made nicer.
• Catalog version changed from 010 to 020.

FromDual Backup Manager Cleanup

• Archive cleanup output empty line removed.
• Backup cleanup in catalog made nicer.
• Cleanup should delete only instance backups but not all backups if specified (bug #166).

FromDual Backup Manager Logical Full and Schema backup

• Omit warning for non-transactional tables if option --blocking-backup is set.
• Function getDumpOverview now also includes empty schemata.
• Transactional storage engine selection made ready for MariaDB 10.1/10.2 and MySQL 8.0.

Taxonomy upgrade extras: BackupRestoreRecoverypitrfromdual_brmanbrmanreleasebmanrman

FromDual has the pleasure to announce the release of the new version 1.2.5 of the popular Backup and Recovery Manager for MySQL and MariaDB (fromdual_brman).

You can download the FromDual Backup and Recovery Manager from here.

In the inconceivable case that you find a bug in the FromDual Backup and Recovery Manager please report it to our Bugtracker or just send us an email.

Any feedback, statements and testimonials are welcome as well! Please send them to feedback@fromdual.com.

Upgrade from 1.2.x to 1.2.5 # cd ${HOME}/product # tar xf /download/fromdual_brman-1.2.5.tar.gz # rm -f fromdual_brman # ln -s fromdual_brman-1.2.5 fromdual_brman
Changes in FromDual Backup Manager 1.2.5

This release contains mainly fixes related to the backup catalog and the backup type cleanup.

You can verify your current FromDual Backup Manager version with the following command:

shell> fromdual_bman --version
FromDual Backup Manager

• Docker container is ready.
• Testing infrastructure improved.
• Better option checking to be usage compliant.
• Option handling and checking refactored.
• PHP variable variables_order is included into program. No more php.ini change required any more.
• Connection error made more verbose.
• Downstream myEnv.inc library from rev873.
• Incompatibility change: Default --backupdir location changed from ./bck to $HOME/bck.

FromDual Backup Manager Catalog

• Catalog creation and upgrade messages put into right order.
• Backup catalog should be upgraded directly to newest release when created.
• Only do catalog version check if --upgrade is not specified.
• Incompatibility change: Catalog operation options (--create and --upgrade) made more consistent (--type=catalog). This could lead to different behaviour than earlier!
• Backup cleanup in catalog made nicer.
• Catalog version changed from 010 to 020.

FromDual Backup Manager Cleanup

• Archive cleanup output empty line removed.
• Backup cleanup in catalog made nicer.
• Cleanup should delete only instance backups but not all backups if specified (bug #166).

FromDual Backup Manager Logical Full and Schema backup

• Omit warning for non-transactional tables if option --blocking-backup is set.
• Function getDumpOverview now also includes empty schemata.
• Transactional storage engine selection made ready for MariaDB 10.1/10.2 and MySQL 8.0.

Taxonomy upgrade extras: BackupRestoreRecoverypitrfromdual_brman

Most (relational) DBAs and DB application developers know the concept of a primary key ("PK") and what it is good for. However, much too often one still encounters table definitions without a PK. True, the relational theory based on sets does not need a PK, and all operations (insert, select, update, delete) can also be done on tables for which no PK was defined. If performance doesn't matter (or the data volume is small, a typical situation in tests), the lack of a PK does not immediately cause negative consequences.

But recently, we had several customers who (independent of each other) had big tables without a PK in a replication setup which they wanted to delete, and they all suffered severely from that: Their replication did not progress, the slave lag grew larger and larger, and all this without reporting any error. When I say "larger and larger", I mean it: I'm not talking about minutes or even hours, I'm talking about days!

Observations

In all cases, the situation could be summarized as:

• They were running a traditional, asynchronous replication using the "row" format.
• They had a table without PK with many entries, say a million rows.
• This table wasn't needed any more, and someone issued a "delete from T" statement on the master.
• From this moment, the slave did not show any sign of progress: The output of "show slave status \G"
  - listed both the IO and the SQL slave thread as running,
  - reported the same log positions without any change,
  - did not mention any slave error,
  - but the slave lag grew in sync with the passing time.

Looking at the slave's machine load, say using "vmstat", you could see a certain amount of CPU load in user mode, possibly some "waiting for IO", and some read IO (group "io", column "bi" = "block input"). Checking with "top", you could see that the MySQL server process was the only significant CPU load, and closer inspection would reveal that it used roughly one CPU core.

(A side remark: The numbers of "vmstat" and "top" are not directly comparable: While "vmstat" reports the overall CPU usage as a percentage of the total available CPU power, "top" reports the CPU usage of the individual processes as the percentage of a single CPU core. So if you had a 4-core machine with only one active process running an infinite loop, "top" would show this process as using 100%, while "vmstat" would report the CPU as running 25% in user mode and being 75% idle. If you don't know it, look at "/proc/cpuinfo" to find the number of CPU cores.)

What was the Issue? From "top", we could tell that the MySQL server was using one CPU core at full speed. From "vmstat", we could tell that it might access some data from disk, but didn't write any significant amount. This sure looked like an infinite loop or a close relative of it, executed by only one thread.

Some of you may have heard that (under some conditions) replication may do a full table scan: This is it!

When the slave has to apply a change (for this discussion: a delete or an update) which is provided in row format, and the table has no PK (or other suitable index), the SQL thread does a full table scan searching for the matching row. Note that it doesn't stop on the first match, but rather continues the scan throughout the rest of the table.

To be honest: I don't understand why it doesn't stop after the first match. I also ran a modified test where some master rows had two matches on the slave (I had duplicated them by "insert select"): The "delete" was still replicated as before, and these additional slave rows were still present after the delete.

Until now, you may consider that "full table scan" as a claim without proof, and I agree with all demands for a more thorough check.

The Experiment For tests, I have a setup of two VMs, each running a MySQL server process, and they are configured for a traditional master-slave replication. In fact, I have it for the versions MySQL 5.5.44, 5.6.24, and 5.7.17. (Yes, I might add newer versions.)

So I designed an experiment:

• Start both master and slave, make sure replication is running.
• On the master, create a table without any key / index, neither primary nor secondary: CREATE TABLE for_delete ( inc_num int, # ascending numbers 1 .. 10,000 repeated for larger tables clock timestamp, # now() counted: 129 different values with 200 k rows bubble char(250) # repeat('Abcd', 60) ) DEFAULT CHARACTER SET latin1 ;
• Insert into that table the desired number of rows (I had runs with 10 k, 20 k, 100 k, and 200 k)
• on both master and slave, run "SELECT ... FROM information_schema.global_status WHERE ..." to get status counters,
• Delete all rows of that table
• sleep for a time depending on the row count (you will later see why)
• get new status counters
• compute the status counter differences

This experiment reliably reproduced the symptoms which the customers had reported: When the "delete" had been done on the master, the slave became busy for a long time, depending on the row count, and in this time it did not show any progress indicators. This holds for all three versions I checked.

So what did the slave do? It worked as assumed: For each row, it did a full table scan, continuing even after it had found a matching row. This can be easily seen in the status counters, which you will find in the result tables below.

In this article, I will show the results of tests with 200 k rows only, as they are the most impressive. As described above, the table was created anew for each run. Then, 10,000 rows were inserted, and this was repeated 20 times. Each such group had the value of "inc_num" go up from 1 to 10,000.

In all runs, the status counters "HANDLER_DELETE", "INNODB_ROWS_DELETED", and "INNODB_ROWS_READ" showed the value of 200,000, the table size. So the handler calls did not show any scan, it must be below that interface (= within the handler).

If the server does a table scan, it must access all data pages of the table, so there must be read requests for them to guarantee they are in the buffer pool. And yes, the status counters showed these read requests: Table 1: No Key or Index

200,000 rows, status counters on Master Slave


Version 5.5.44

INNODB_BUFFER_POOL_READ_REQUESTS 2,174,121 380,132,972 Ratio "read_requests" Slave/Master
174.8 "read_requests" per "rows_deleted" 10.9 1,900.7


Version 5.6.24

INNODB_BUFFER_POOL_READ_REQUESTS 2,318,685 379,762,583 Ratio "read_requests" Slave/Master
163.8 "read_requests" per "rows_deleted" 11.6 1,898.8


Version 5.7.17

INNODB_BUFFER_POOL_READ_REQUESTS 1,598,745 379,538,695 Ratio "read_requests" Slave/Master
237.4 "read_requests" per "rows_deleted" 8.0 1,897.7

While master and slave (from a logical point of view) do the same work (delete all rows from a 200 k rows table), the slave accesses many more pages than the master - depending on the version, the factor ranges from 164 to 237. (Note that in version 5.7 the slave didn't do worse than in earlier versions, rather the master did better. This shows clearly in the ratio of "innodb buffer pool read requests" to "rows deleted" on the master: This is about 11 in 5.5 and 5.6, but only 8 in 5.7.)

I won't bother you with the detailed results for 100 k rows. It is enough to say that for half as many rows, the master had half as many read requests, while the slave had a quarter. This means that the effort on the master grows proportional to table size, but on the slave it grows with the square of the table size. Accepting the fact that the slave always scans the full table, this is easy to understand: If the table has twice as many rows, there are twice as many pages to scan, and the number of scans also doubles.

Quadratic growth means that an increase of the table size by a factor ten lets the effort grow by a factor hundred! Now imagine I had tested with a million of rows ...

All this isn't new: In the public MySQL bug database, this is listed as bug #53375. The bug was reported on May 3, 2010, for MySQL 5.1. The bug is closed since December 15, 2011. This does not mean the full table scans were stopped - obviously, they are considered unavoidable, so the bug fix is to write an explaining message into the error log. In my tests, I encountered it only once, here it is:

[Note] The slave is applying a ROW event on behalf of a DELETE statement on table for_delete and is currently taking a considerable amount of time (61 seconds). This is due to the fact that it is scanning an index while looking up records to be processed. Consider adding a primary key (or unique key) to the table to improve performance. Avoiding the Issue

Of course, this problem is the consequence of sloppy table design: If there were a primary key, it would not occur. But this may not help those who currently have tables without a PK and dare not add one, because it would require prior testing and a maintenance window to alter the table on the master.

Luckily, there are remedies, and even more than the log message (quoted above) mentions: In my tests, I found that the slave will use any index on that table if one is available. (It even uses an index with low selectivity, which may increase the page request count.) I did 5 tests:

• Create an index on "clock" (129 different values).
• Create an index on "inc_num" (10,000 different values).
• Create an index on both "clock" and "inc_num" (all combinations are distinct).
• As before, and declare it as "unique".
• Define the combination of "clock" and "inc_num" to be the primary key.

The "alter table" statement for this was always issued on the slave only, after the inserts, but before the delete.

In all three versions, the slave used any index available. The index on "clock" of course had many different rows per value, so it caused many even more page requests than the no-index case: between 2,800 and 3,165 per row deleted. Obviously, thios makes the problem even worse. But all other indexes were huge improvements, the primary key of course was the best choice. Here are the numbers: Table 2: With Added Key or Index

200,000 rows, status counters on Master Slave Slave Slave Slave Slave






"Alter table ..." on slave before "Delete":
Index on "clock" 129 values Index on "inc_num" 10,000 v. Index
on both Unique I.
on both Primary key on both Version 5.5.44





INNODB_BUFFER_POOL_READ_REQUESTS 2,174,121 633,132,032 10,197,554 4,429,243 4,421,357 1,810,734 Ratio "read_requests" Slave/Master
291.2 4.7 2.0 2.0 0.8 "read_requests" per "rows_deleted" 10.9 3,165.7 51.0 22.1 22.1 9.1






Version 5.6.24





INNODB_BUFFER_POOL_READ_REQUESTS 2,318,685 610,482,315 10,327,132 4,375,106 4,073,543 1,794,524 Ratio "read_requests" Slave/Master
342.1 5.0 2.1 2.0 0.9 "read_requests" per "rows_deleted" 11.6 3,052.4 51.6 21.9 20.4 9.0






Version 5.7.17





INNODB_BUFFER_POOL_READ_REQUESTS 1,598,745 559,398,633 9,531,444 3,859,343 3,836,390 1,720,731 Ratio "read_requests" Slave/Master
354.8 6.0 2.3 2.5 1.1 "read_requests" per "rows_deleted" 8.0 2,797.0 47.7 19.3 19.2 8.6

But one very important fact should be mentioned in addition to the numbers: The fact that it worked! By adding an index, I made the slave's schema differ from the master's. The primary key even totally changed the B-tree in which the rows are stored, and it made the slave drop the internal row ID which InnoDB had added on the master. Still, replication using the row format could handle these differences without problems.

The Way Out

So the good message is:

• Even if you have a table without indexes or primary key, you can add these on the slave without breaking the replication.
• If you suffer from slow replication on such a table, adding a good index or (even better) the PK will solve this problem.
• In a replication setup, you can improve the schema on the slave and then do a failover, effectively improving it for all accesses without any maintenance window - just the short failover time.

This might help many DBAs who otherwise don't see a chance to improve a bad schema once it is used in production.

Take care!

Taxonomy upgrade extras: primary key

Most (relational) DBAs and DB application developers know the concept of a primary key ("PK") and what it is good for. However, much too often one still encounters table definitions without a PK. True, the relational theory based on sets does not need a PK, and all operations (insert, select, update, delete) can also be done on tables for which no PK was defined. If performance doesn't matter (or the data volume is small, a typical situation in tests), the lack of a PK does not immediately cause negative consequences.

But recently, we had several customers who (independent of each other) had big tables without a PK in a replication setup which they wanted to delete, and they all suffered severely from that: Their replication did not progress, the slave lag grew larger and larger, and all this without reporting any error. When I say "larger and larger", I mean it: I'm not talking about minutes or even hours, I'm talking about days!

Observations

In all cases, the situation could be summarized as:

• They were running a traditional, asynchronous replication using the "row" format.
• They had a table without PK with many entries, say a million rows.
• This table wasn't needed any more, and someone issued a "delete from T" statement on the master.
• From this moment, the slave did not show any sign of progress: The output of "show slave status \G"
  - listed both the IO and the SQL slave thread as running,
  - reported the same log positions without any change,
  - did not mention any slave error,
  - but the slave lag grew in sync with the passing time.

Looking at the slave's machine load, say using "vmstat", you could see a certain amount of CPU load in user mode, possibly some "waiting for IO", and some read IO (group "io", column "bi" = "block input"). Checking with "top", you could see that the MySQL server process was the only significant CPU load, and closer inspection would reveal that it used roughly one CPU core.

(A side remark: The numbers of "vmstat" and "top" are not directly comparable: While "vmstat" reports the overall CPU usage as a percentage of the total available CPU power, "top" reports the CPU usage of the individual processes as the percentage of a single CPU core. So if you had a 4-core machine with only one active process running an infinite loop, "top" would show this process as using 100%, while "vmstat" would report the CPU as running 25% in user mode and being 75% idle. If you don't know it, look at "/proc/cpuinfo" to find the number of CPU cores.)

What was the Issue? From "top", we could tell that the MySQL server was using one CPU core at full speed. From "vmstat", we could tell that it might access some data from disk, but didn't write any significant amount. This sure looked like an infinite loop or a close relative of it, executed by only one thread.

Some of you may have heard that (under some conditions) replication may do a full table scan: This is it!

When the slave has to apply a change (for this discussion: a delete or an update) which is provided in row format, and the table has no PK (or other suitable index), the SQL thread does a full table scan searching for the matching row. Note that it doesn't stop on the first match, but rather continues the scan throughout the rest of the table.

To be honest: I don't understand why it doesn't stop after the first match. I also ran a modified test where some master rows had two matches on the slave (I had duplicated them by "insert select"): The "delete" was still replicated as before, and these additional slave rows were still present after the delete.

Until now, you may consider that "full table scan" as a claim without proof, and I agree with all demands for a more thorough check.

The Experiment For tests, I have a setup of two VMs, each running a MySQL server process, and they are configured for a traditional master-slave replication. In fact, I have it for the versions MySQL 5.5.44, 5.6.24, and 5.7.17. (Yes, I might add newer versions.)

So I designed an experiment:

• Start both master and slave, make sure replication is running.
• On the master, create a table without any key / index, neither primary nor secondary: CREATE TABLE for_delete ( inc_num int, # ascending numbers 1 .. 10,000 repeated for larger tables clock timestamp, # now() counted: 129 different values with 200 k rows bubble char(250) # repeat('Abcd', 60) ) DEFAULT CHARACTER SET latin1 ;
• Insert into that table the desired number of rows (I had runs with 10 k, 20 k, 100 k, and 200 k)
• on both master and slave, run "SELECT ... FROM information_schema.global_status WHERE ..." to get status counters,
• Delete all rows of that table
• sleep for a time depending on the row count (you will later see why)
• get new status counters
• compute the status counter differences

This experiment reliably reproduced the symptoms which the customers had reported: When the "delete" had been done on the master, the slave became busy for a long time, depending on the row count, and in this time it did not show any progress indicators. This holds for all three versions I checked.

So what did the slave do? It worked as assumed: For each row, it did a full table scan, continuing even after it had found a matching row. This can be easily seen in the status counters, which you will find in the result tables below.

In this article, I will show the results of tests with 200 k rows only, as they are the most impressive. As described above, the table was created anew for each run. Then, 10,000 rows were inserted, and this was repeated 20 times. Each such group had the value of "inc_num" go up from 1 to 10,000.

In all runs, the status counters "HANDLER_DELETE", "INNODB_ROWS_DELETED", and "INNODB_ROWS_READ" showed the value of 200,000, the table size. So the handler calls did not show any scan, it must be below that interface (= within the handler).

If the server does a table scan, it must access all data pages of the table, so there must be read requests for them to guarantee they are in the buffer pool. And yes, the status counters showed these read requests: Table 1: No Key or Index

200,000 rows, status counters on Master Slave


Version 5.5.44

INNODB_BUFFER_POOL_READ_REQUESTS 2,174,121 380,132,972 Ratio "read_requests" Slave/Master
174.8 "read_requests" per "rows_deleted" 10.9 1,900.7


Version 5.6.24

INNODB_BUFFER_POOL_READ_REQUESTS 2,318,685 379,762,583 Ratio "read_requests" Slave/Master
163.8 "read_requests" per "rows_deleted" 11.6 1,898.8


Version 5.7.17

INNODB_BUFFER_POOL_READ_REQUESTS 1,598,745 379,538,695 Ratio "read_requests" Slave/Master
237.4 "read_requests" per "rows_deleted" 8.0 1,897.7

While master and slave (from a logical point of view) do the same work (delete all rows from a 200 k rows table), the slave accesses many more pages than the master - depending on the version, the factor ranges from 164 to 237. (Note that in version 5.7 the slave didn't do worse than in earlier versions, rather the master did better. This shows clearly in the ratio of "innodb buffer pool read requests" to "rows deleted" on the master: This is about 11 in 5.5 and 5.6, but only 8 in 5.7.)

I won't bother you with the detailed results for 100 k rows. It is enough to say that for half as many rows, the master had half as many read requests, while the slave had a quarter. This means that the effort on the master grows proportional to table size, but on the slave it grows with the square of the table size. Accepting the fact that the slave always scans the full table, this is easy to understand: If the table has twice as many rows, there are twice as many pages to scan, and the number of scans also doubles.

Quadratic growth means that an increase of the table size by a factor ten lets the effort grow by a factor hundred! Now imagine I had tested with a million of rows ...

All this isn't new: In the public MySQL bug database, this is listed as bug #53375. The bug was reported on May 3, 2010, for MySQL 5.1. The bug is closed since December 15, 2011. This does not mean the full table scans were stopped - obviously, they are considered unavoidable, so the bug fix is to write an explaining message into the error log. In my tests, I encountered it only once, here it is:

[Note] The slave is applying a ROW event on behalf of a DELETE statement on table for_delete and is currently taking a considerable amount of time (61 seconds). This is due to the fact that it is scanning an index while looking up records to be processed. Consider adding a primary key (or unique key) to the table to improve performance. Avoiding the Issue

Of course, this problem is the consequence of sloppy table design: If there were a primary key, it would not occur. But this may not help those who currently have tables without a PK and dare not add one, because it would require prior testing and a maintenance window to alter the table on the master.

Luckily, there are remedies, and even more than the log message (quoted above) mentions: In my tests, I found that the slave will use any index on that table if one is available. (It even uses an index with low selectivity, which may increase the page request count.) I did 5 tests:

• Create an index on "clock" (129 different values).
• Create an index on "inc_num" (10,000 different values).
• Create an index on both "clock" and "inc_num" (all combinations are distinct).
• As before, and declare it as "unique".
• Define the combination of "clock" and "inc_num" to be the primary key.

The "alter table" statement for this was always issued on the slave only, after the inserts, but before the delete.

In all three versions, the slave used any index available. The index on "clock" of course had many different rows per value, so it caused many even more page requests than the no-index case: between 2,800 and 3,165 per row deleted. Obviously, thios makes the problem even worse. But all other indexes were huge improvements, the primary key of course was the best choice. Here are the numbers: Table 2: With Added Key or Index

200,000 rows, status counters on Master Slave Slave Slave Slave Slave






"Alter table ..." on slave before "Delete":
Index on "clock" 129 values Index on "inc_num" 10,000 v. Index
on both Unique I.
on both Primary key on both Version 5.5.44





INNODB_BUFFER_POOL_READ_REQUESTS 2,174,121 633,132,032 10,197,554 4,429,243 4,421,357 1,810,734 Ratio "read_requests" Slave/Master
291.2 4.7 2.0 2.0 0.8 "read_requests" per "rows_deleted" 10.9 3,165.7 51.0 22.1 22.1 9.1






Version 5.6.24





INNODB_BUFFER_POOL_READ_REQUESTS 2,318,685 610,482,315 10,327,132 4,375,106 4,073,543 1,794,524 Ratio "read_requests" Slave/Master
342.1 5.0 2.1 2.0 0.9 "read_requests" per "rows_deleted" 11.6 3,052.4 51.6 21.9 20.4 9.0






Version 5.7.17





INNODB_BUFFER_POOL_READ_REQUESTS 1,598,745 559,398,633 9,531,444 3,859,343 3,836,390 1,720,731 Ratio "read_requests" Slave/Master
354.8 6.0 2.3 2.5 1.1 "read_requests" per "rows_deleted" 8.0 2,797.0 47.7 19.3 19.2 8.6

But one very important fact should be mentioned in addition to the numbers: The fact that it worked! By adding an index, I made the slave's schema differ from the master's. The primary key even totally changed the B-tree in which the rows are stored, and it made the slave drop the internal row ID which InnoDB had added on the master. Still, replication using the row format could handle these differences without problems.

The Way Out

So the good message is:

• Even if you have a table without indexes or primary key, you can add these on the slave without breaking the replication.
• If you suffer from slow replication on such a table, adding a good index or (even better) the PK will solve this problem.
• In a replication setup, you can improve the schema on the slave and then do a failover, effectively improving it for all accesses without any maintenance window - just the short failover time.

This might help many DBAs who otherwise don't see a chance to improve a bad schema once it is used in production.

Take care!

Taxonomy upgrade extras: primary key

Most (relational) DBAs and DB application developers know the concept of a primary key ("PK") and what it is good for. However, much too often one still encounters table definitions without a PK. True, the relational theory based on sets does not need a PK, and all operations (insert, select, update, delete) can also be done on tables for which no PK was defined. If performance doesn't matter (or the data volume is small, a typical situation in tests), the lack of a PK does not immediately cause negative consequences.

But recently, we had several customers who (independent of each other) had big tables without a PK in a replication setup which they wanted to delete, and they all suffered severely from that: Their replication did not progress, the slave lag grew larger and larger, and all this without reporting any error. When I say "larger and larger", I mean it: I'm not talking about minutes or even hours, I'm talking about days!

Observations

In all cases, the situation could be summarized as:

• They were running a traditional, asynchronous replication using the "row" format.
• They had a table without PK with many entries, say a million rows.
• This table wasn't needed any more, and someone issued a "delete from T" statement on the master.
• From this moment, the slave did not show any sign of progress: The output of "show slave status \G"
  - listed both the IO and the SQL slave thread as running,
  - reported the same log positions without any change,
  - did not mention any slave error,
  - but the slave lag grew in sync with the passing time.

Looking at the slave's machine load, say using "vmstat", you could see a certain amount of CPU load in user mode, possibly some "waiting for IO", and some read IO (group "io", column "bi" = "block input"). Checking with "top", you could see that the MySQL server process was the only significant CPU load, and closer inspection would reveal that it used roughly one CPU core.

(A side remark: The numbers of "vmstat" and "top" are not directly comparable: While "vmstat" reports the overall CPU usage as a percentage of the total available CPU power, "top" reports the CPU usage of the individual processes as the percentage of a single CPU core. So if you had a 4-core machine with only one active process running an infinite loop, "top" would show this process as using 100%, while "vmstat" would report the CPU as running 25% in user mode and being 75% idle. If you don't know it, look at "/proc/cpuinfo" to find the number of CPU cores.)

What was the Issue? From "top", we could tell that the MySQL server was using one CPU core at full speed. From "vmstat", we could tell that it might access some data from disk, but didn't write any significant amount. This sure looked like an infinite loop or a close relative of it, executed by only one thread.

Some of you may have heard that (under some conditions) replication may do a full table scan: This is it!

When the slave has to apply a change (for this discussion: a delete or an update) which is provided in row format, and the table has no PK (or other suitable index), the SQL thread does a full table scan searching for the matching row. Note that it doesn't stop on the first match, but rather continues the scan throughout the rest of the table.

To be honest: I don't understand why it doesn't stop after the first match. I also ran a modified test where some master rows had two matches on the slave (I had duplicated them by "insert select"): The "delete" was still replicated as before, and these additional slave rows were still present after the delete.

Until now, you may consider that "full table scan" as a claim without proof, and I agree with all demands for a more thorough check.

The Experiment For tests, I have a setup of two VMs, each running a MySQL server process, and they are configured for a traditional master-slave replication. In fact, I have it for the versions MySQL 5.5.44, 5.6.24, and 5.7.17. (Yes, I might add newer versions.)

So I designed an experiment:

• Start both master and slave, make sure replication is running.
• On the master, create a table without any key / index, neither primary nor secondary: CREATE TABLE for_delete ( inc_num int, # ascending numbers 1 .. 10,000 repeated for larger tables clock timestamp, # now() counted: 129 different values with 200 k rows bubble char(250) # repeat('Abcd', 60) ) DEFAULT CHARACTER SET latin1 ;
• Insert into that table the desired number of rows (I had runs with 10 k, 20 k, 100 k, and 200 k)
• on both master and slave, run "SELECT ... FROM information_schema.global_status WHERE ..." to get status counters,
• Delete all rows of that table
• sleep for a time depending on the row count (you will later see why)
• get new status counters
• compute the status counter differences

This experiment reliably reproduced the symptoms which the customers had reported: When the "delete" had been done on the master, the slave became busy for a long time, depending on the row count, and in this time it did not show any progress indicators. This holds for all three versions I checked.

So what did the slave do? It worked as assumed: For each row, it did a full table scan, continuing even after it had found a matching row. This can be easily seen in the status counters, which you will find in the result tables below.

In this article, I will show the results of tests with 200 k rows only, as they are the most impressive. As described above, the table was created anew for each run. Then, 10,000 rows were inserted, and this was repeated 20 times. Each such group had the value of "inc_num" go up from 1 to 10,000.

In all runs, the status counters "HANDLER_DELETE", "INNODB_ROWS_DELETED", and "INNODB_ROWS_READ" showed the value of 200,000, the table size. So the handler calls did not show any scan, it must be below that interface (= within the handler).

If the server does a table scan, it must access all data pages of the table, so there must be read requests for them to guarantee they are in the buffer pool. And yes, the status counters showed these read requests: Table 1: No Key or Index

200,000 rows, status counters on Master Slave


Version 5.5.44

INNODB_BUFFER_POOL_READ_REQUESTS 2,174,121 380,132,972 Ratio "read_requests" Slave/Master
174.8 "read_requests" per "rows_deleted" 10.9 1,900.7


Version 5.6.24

INNODB_BUFFER_POOL_READ_REQUESTS 2,318,685 379,762,583 Ratio "read_requests" Slave/Master
163.8 "read_requests" per "rows_deleted" 11.6 1,898.8


Version 5.7.17

INNODB_BUFFER_POOL_READ_REQUESTS 1,598,745 379,538,695 Ratio "read_requests" Slave/Master
237.4 "read_requests" per "rows_deleted" 8.0 1,897.7

While master and slave (from a logical point of view) do the same work (delete all rows from a 200 k rows table), the slave accesses many more pages than the master - depending on the version, the factor ranges from 164 to 237. (Note that in version 5.7 the slave didn't do worse than in earlier versions, rather the master did better. This shows clearly in the ratio of "innodb buffer pool read requests" to "rows deleted" on the master: This is about 11 in 5.5 and 5.6, but only 8 in 5.7.)

I won't bother you with the detailed results for 100 k rows. It is enough to say that for half as many rows, the master had half as many read requests, while the slave had a quarter. This means that the effort on the master grows proportional to table size, but on the slave it grows with the square of the table size. Accepting the fact that the slave always scans the full table, this is easy to understand: If the table has twice as many rows, there are twice as many pages to scan, and the number of scans also doubles.

Quadratic growth means that an increase of the table size by a factor ten lets the effort grow by a factor hundred! Now imagine I had tested with a million of rows ...

All this isn't new: In the public MySQL bug database, this is listed as bug #53375. The bug was reported on May 3, 2010, for MySQL 5.1. The bug is closed since December 15, 2011. This does not mean the full table scans were stopped - obviously, they are considered unavoidable, so the bug fix is to write an explaining message into the error log. In my tests, I encountered it only once, here it is:

[Note] The slave is applying a ROW event on behalf of a DELETE statement on table for_delete and is currently taking a considerable amount of time (61 seconds). This is due to the fact that it is scanning an index while looking up records to be processed. Consider adding a primary key (or unique key) to the table to improve performance. Avoiding the Issue

Of course, this problem is the consequence of sloppy table design: If there were a primary key, it would not occur. But this may not help those who currently have tables without a PK and dare not add one, because it would require prior testing and a maintenance window to alter the table on the master.

Luckily, there are remedies, and even more than the log message (quoted above) mentions: In my tests, I found that the slave will use any index on that table if one is available. (It even uses an index with low selectivity, which may increase the page request count.) I did 5 tests:

• Create an index on "clock" (129 different values).
• Create an index on "inc_num" (10,000 different values).
• Create an index on both "clock" and "inc_num" (all combinations are distinct).
• As before, and declare it as "unique".
• Define the combination of "clock" and "inc_num" to be the primary key.

The "alter table" statement for this was always issued on the slave only, after the inserts, but before the delete.

In all three versions, the slave used any index available. The index on "clock" of course had many different rows per value, so it caused many even more page requests than the no-index case: between 2,800 and 3,165 per row deleted. Obviously, thios makes the problem even worse. But all other indexes were huge improvements, the primary key of course was the best choice. Here are the numbers: Table 2: With Added Key or Index

200,000 rows, status counters on Master Slave Slave Slave Slave Slave






"Alter table ..." on slave before "Delete":
Index on "clock" 129 values Index on "inc_num" 10,000 v. Index
on both Unique I.
on both Primary key on both Version 5.5.44





INNODB_BUFFER_POOL_READ_REQUESTS 2,174,121 633,132,032 10,197,554 4,429,243 4,421,357 1,810,734 Ratio "read_requests" Slave/Master
291.2 4.7 2.0 2.0 0.8 "read_requests" per "rows_deleted" 10.9 3,165.7 51.0 22.1 22.1 9.1






Version 5.6.24





INNODB_BUFFER_POOL_READ_REQUESTS 2,318,685 610,482,315 10,327,132 4,375,106 4,073,543 1,794,524 Ratio "read_requests" Slave/Master
342.1 5.0 2.1 2.0 0.9 "read_requests" per "rows_deleted" 11.6 3,052.4 51.6 21.9 20.4 9.0






Version 5.7.17





INNODB_BUFFER_POOL_READ_REQUESTS 1,598,745 559,398,633 9,531,444 3,859,343 3,836,390 1,720,731 Ratio "read_requests" Slave/Master
354.8 6.0 2.3 2.5 1.1 "read_requests" per "rows_deleted" 8.0 2,797.0 47.7 19.3 19.2 8.6

But one very important fact should be mentioned in addition to the numbers: The fact that it worked! By adding an index, I made the slave's schema differ from the master's. The primary key even totally changed the B-tree in which the rows are stored, and it made the slave drop the internal row ID which InnoDB had added on the master. Still, replication using the row format could handle these differences without problems.

The Way Out

So the good message is:

• Even if you have a table without indexes or primary key, you can add these on the slave without breaking the replication.
• If you suffer from slow replication on such a table, adding a good index or (even better) the PK will solve this problem.
• In a replication setup, you can improve the schema on the slave and then do a failover, effectively improving it for all accesses without any maintenance window - just the short failover time.

This might help many DBAs who otherwise don't see a chance to improve a bad schema once it is used in production.

Take care!

Translate to your preferred language:

Wer sich etwas vertieft mit den MariaDB Status Zählern (SHOW GLOBAL STATUS;) auseinander setzt, wird früher oder später auf den Zähler Aborted_clients stossen:

mariadb> SHOW GLOBAL STATUS LIKE 'aborted_clients'; +-----------------+-------+ | Variable_name | Value | +-----------------+-------+ | Aborted_clients | 5392 | +-----------------+-------+

Wenn man sich dann die MariaDB Dokumentation anschaut, steht da folgendes:

Number of aborted client connections. This can be due to the client not calling mysql_close() before exiting, the client sleeping without issuing a request to the server for more seconds than specified by wait_timeout or interactive_timeout, or by the client program ending in the midst of transferring data.

Also:

• Vergessener Aufruf von mysql_close().
• Inaktive Verbindung (Sleep) für mehr als wait_timeout oder interactive_timeout Sekunden.
• Unerwartete Beendigung der Applikation.

Der erste Punkt geht unter die Kategorie: Unsauber programmiert und somit ein Fehler in der Anwendung.

Der zweite Punkt ist eher ein Konfigurationsproblem sei es auf Datenbankseite oder auf Applikationsseite.

Hier stellt sich die Frage: Warum sind die Timeouts so eingestellt, wenn die Timeouts kurz sind? Default für beide Timeouts ist 28800 Sekunden, also 8 Stunden.

mariadb> SHOW GLOBAL VARIABLES LIKE '%timeout'; +---------------------------+-------+ | Variable_name | Value | +---------------------------+-------+ | interactive_timeout | 28800 | | wait_timeout | 28800 | +---------------------------+-------+

Oder aber: Warum schickt die Anwendung so lange keine Daten über eine geöffnete Verbindung (hat die Anwendung die Verbindung verloren)?

Der zweite Fall trifft üblicherweise dann ein, wenn persistente Verbindungen verwendet werden (Java Connection Pool, Ruby on Rails, PHP Persistent Database Connections, etc.). Dann sollten die Entwickler den Connector so konfigurieren, dass er alle paar Sekunden einen Ping über die Verbindung schickt.

Der dritte Fall hat sehr viel Ähnlichkeit mit dem ersten Fall: Die Applikation beendet sich früher als erwartet. Das kann zum Beispiel auftreten, wenn:

• exit() vor mysql_close() (Fall 1 von oben)
• Applikation wurde unerwartet von aussen beendet (kill, OOM Killer, systemd, etc.)
• Firewalls oder LoadBalancer die eine idelnde Verbindung nach einer bestimmten Zeit terminieren (z.B. 300 Sekunden).

Feststellen, wen es betrifft

Eigentlich sollte die Applikation in den meisten Fällen selber merken, wenn sie unerwartet beendet wurde (Fall 2 und 3). Sehr oft tut sie dies aber nicht. Daher müssen wir als Datenbankverantwortliche der Applikation manchmal auf die Sprünge helfen, und Ihr mitteilen, dass unerwartete Abbrüche überhaupt vorkommen und wo im Applikationscode das ungefähr geschieht.

Das erste Anzeichen dafür ist, wie oben Beschrieben, ein Status Zähler von Aborted_clients grösser 0. Spannend wir das ganze aber erst wenn wir Aborted_clients in Relation zur Uptime setzen. Wenn wir nur 10 Aborted_clients über die letzten 100 Tage haben, dann kann man diesen Zähler getrost vernachlässigen. Wenn Aborted_clients im Minutentakt hochgezählt wird, sollte man sich das Ganze schon genauer anschauen:

mariadb> SHOW GLOBAL STATUS WHERE Variable_name = 'aborted_clients' OR Variable_name = 'uptime'; +-----------------+--------+ | Variable_name | Value | +-----------------+--------+ | Aborted_clients | 5438 | | Uptime | 257991 | +-----------------+--------+ mariadb> SELECT 257991/5438 AS Abort_every_s; +---------------+ | Abort_every_s | +---------------+ | 47.4423 | +---------------+

Die nächste Frage, die sich stellt, ist, welcher Applikationsuser ist davon betroffen? Diese Frage kann auf 2 verschiedene Wege beantwortet werden. Entweder über das PERFORMANCE_SCHEMA mit der Abfrage nach Accounts, welche die Verbindung nicht sauber schliessen:

mariadb> SELECT ess.user, ess.host , (a.total_connections - a.current_connections) - ess.count_star as not_closed , ((a.total_connections - a.current_connections) - ess.count_star) * 100 / (a.total_connections - a.current_connections) as pct_not_closed FROM performance_schema.events_statements_summary_by_account_by_event_name ess JOIN performance_schema.accounts a on (ess.user = a.user and ess.host = a.host) WHERE ess.event_name = 'statement/com/quit' AND (a.total_connections - a.current_connections) > ess.count_star ; +-----------+---------------+------------+----------------+ | user | host | not_closed | pct_not_closed | +-----------+---------------+------------+----------------+ | applicat | 10.0.246.74 | 31 | 0.0001 | | applicat | 10.0.246.73 | 59 | 0.0003 | | replicate | 10.0.246.72 | 1 | 100.0000 | | applicat | 10.0.246.76 | 4 | 0.0024 | | root | localhost | 3 | 0.0053 | | applicat | localhost | 51880 | 0.2991 | | applicat | 10.0.246.77 | 1 | 100.0000 | +-----------+---------------+------------+----------------+

Oder über das Error Log, wenn die die Variable log_warnings auf 2 gesetzt ist:

mariadb> SHOW GLOBAL VARIABLES LIKE 'log_warn%'; +---------------+-------+ | Variable_name | Value | +---------------+-------+ | log_warnings | 2 | +---------------+-------+

Bei MySQL 5.7 und neuer wird hierzu die Variable log_error_verbosity auf 3 gesetzt:

mysql> SHOW GLOBAL VARIABLES LIKE '%verbosity%'; +---------------------+-------+ | Variable_name | Value | +---------------------+-------+ | log_error_verbosity | 3 | +---------------------+-------+

Ein Eintrag ins Error Log sieht dann in etwa wie folgt aus:

[Warning] Aborted connection 411 to db: 'app_production' user: 'app_prod' host: 'mysql_LB' (Got an error writing communication packets) [Warning] Aborted connection 417 to db: 'app_production' user: 'app_prod' host: 'mysql_LB' (Got an error writing communication packets) [Warning] Aborted connection 424 to db: 'billing' user: 'billing' host: 'mysql_LB' (Got an error reading communication packets) [Warning] Aborted connection 433 to db: 'app_production' user: 'app_prod' host: 'mysql_LB' (Got an error reading communication packets) [Warning] Aborted connection 449 to db: 'app_production' user: 'app_prod' host: 'mysql_LB' (Got an error reading communication packets)

Somit wissen wir jetzt also bereits etwas genauer, welchen User von welchem Host mit Zugriff auf welches Schema es erwischt hat. Zudem haben wir noch die Connection ID welche eindeutig und aufsteigen ist.

Feststellen wo im Code es ungefähr passiert

Um festzustellen, wo im Applikationscode der unerwartete Abbruch ungefähr passiert haben wir wiederum 2 Möglichkeiten.

Wir können dazu das General Query Log einschalten (Achtung: kann sehr rasant anwachsen!) und dann die enstprechende Verbindung suchen:

mariadb> SET GLOBAL general_log = 1; mariadb> SHOW GLOBAL VARIABLES LIKE '%general%'; +------------------+----------------------------------------------------------------------+ | Variable_name | Value | +------------------+----------------------------------------------------------------------+ | general_log | ON | | general_log_file | /home/mysql/database/mariadb-10.2/log/chef_mariadb-10.2_general.log | +------------------+----------------------------------------------------------------------+

Eine sauber abgebaute Verbindung sieht darin wie folgt aus:

Time Id Command Argument 2017-04-20T10:26:05.613569Z 26 Connect app@localhost on test using TCP/IP 2017-04-20T10:26:05.613629Z 26 Query SELECT ... 2017-04-20T10:26:05.613681Z 26 Quit

Eine unsauber abgebaute oder noch offene Verbindung wie folgt:

Time Id Command Argument 2017-04-20T10:26:17.165585Z 27 Connect app@localhost on test using TCP/IP 2017-04-20T10:26:17.165785Z 27 Query SELECT ... Fehlendes Quit

Die zweite Möglichkeit besteht darin, die Sequenz von Abfragen über das PERFORMANCE_SCHEMA zu ermitteln. Hierzu müssen wir als erstes herausfinden, wie gross der Unterschied zwischen der Processlist ID und der Datenbankserver internen Thread ID ist:

mariadb> SELECT thread_id, processlist_id, thread_id-processlist_id AS diff FROM performance_schema.threads WHERE processlist_id IS NOT NULL ORDER BY thread_id DESC LIMIT 3; +-----------+----------------+------+ | thread_id | processlist_id | diff | +-----------+----------------+------+ | 436 | 433 | 3 | | 427 | 424 | 3 | | 420 | 417 | 3 | +-----------+----------------+------+

In einem zweiten Schritt können wir über das PERFORMANCE_SCHEMA herausfinden welche Befehle von der Applikation ausgeführt wurden:

UPDATE performance_schema.setup_consumers SET enabled = 1 WHERE name = 'events_statements_history_long'; mariadb> SELECT thread_id, event_name, sql_text, current_schema FROM performance_schema.events_statements_history_long WHERE thread_id = 433 + 3; +-----------+---------------------------------+----------------------------------------------------------+----------------+ | THREAD_ID | EVENT_NAME | SQL_TEXT | CURRENT_SCHEMA | +-----------+---------------------------------+----------------------------------------------------------+----------------+ | 436 | statement/sql/set_option | SET NAMES utf8, @@SESSION.sql_mode = 'STRICT_ALL_TABLES' | app_production | | 436 | statement/com/Ping | NULL | app_production | | 436 | statement/sql/select | select @@character_set_database as 'Value' | app_production | | 436 | statement/sql/show_tables | SHOW TABLES LIKE 'schema_migrations' | app_production | | 436 | statement/sql/show_tables | SHOW TABLES LIKE 'schema_migrations' | app_production | | 436 | statement/sql/select | SELECT `schema_migrations`.* FROM `schema_migrations` | app_production | | 436 | statement/sql/show_fields | SHOW FULL FIELDS FROM `schema_migrations` | app_production | | 436 | statement/sql/show_fields | SHOW FULL FIELDS FROM `settings` | app_production | +-----------+---------------------------------+----------------------------------------------------------+----------------+

Nun sollte es in Zusammenarbeit mit den Entwicklern nicht mehr allzu schwer fallen, die entsprechenden Stellen im Applikationscode zu finden und die Fehler zu beheben.

Taxonomy upgrade extras: verbindungaborted_clientsoomgeneral query log

Translate to your preferred language:

Wer sich etwas vertieft mit den MariaDB Status Zählern (SHOW GLOBAL STATUS;) auseinander setzt, wird früher oder später auf den Zähler Aborted_clients stossen:

mariadb> SHOW GLOBAL STATUS LIKE 'aborted_clients'; +-----------------+-------+ | Variable_name | Value | +-----------------+-------+ | Aborted_clients | 5392 | +-----------------+-------+

Wenn man sich dann die MariaDB Dokumentation anschaut, steht da folgendes:

Number of aborted client connections. This can be due to the client not calling mysql_close() before exiting, the client sleeping without issuing a request to the server for more seconds than specified by wait_timeout or interactive_timeout, or by the client program ending in the midst of transferring data.

Also:

• Vergessener Aufruf von mysql_close().
• Inaktive Verbindung (Sleep) für mehr als wait_timeout oder interactive_timeout Sekunden.
• Unerwartete Beendigung der Applikation.

Der erste Punkt geht unter die Kategorie: Unsauber programmiert und somit ein Fehler in der Anwendung.

Der zweite Punkt ist eher ein Konfigurationsproblem sei es auf Datenbankseite oder auf Applikationsseite.

Hier stellt sich die Frage: Warum sind die Timeouts so eingestellt, wenn die Timeouts kurz sind? Default für beide Timeouts ist 28800 Sekunden, also 8 Stunden.

mariadb> SHOW GLOBAL VARIABLES LIKE '%timeout'; +---------------------------+-------+ | Variable_name | Value | +---------------------------+-------+ | interactive_timeout | 28800 | | wait_timeout | 28800 | +---------------------------+-------+

Oder aber: Warum schickt die Anwendung so lange keine Daten über eine geöffnete Verbindung (hat die Anwendung die Verbindung verloren)?

Der zweite Fall trifft üblicherweise dann ein, wenn persistente Verbindungen verwendet werden (Java Connection Pool, Ruby on Rails, PHP Persistent Database Connections, etc.). Dann sollten die Entwickler den Connector so konfigurieren, dass er alle paar Sekunden einen Ping über die Verbindung schickt.

Der dritte Fall hat sehr viel Ähnlichkeit mit dem ersten Fall: Die Applikation beendet sich früher als erwartet. Das kann zum Beispiel auftreten, wenn:

• exit() vor mysql_close() (Fall 1 von oben)
• Applikation wurde unerwartet von aussen beendet (kill, OOM Killer, systemd, etc.)
• Firewalls oder LoadBalancer die eine idelnde Verbindung nach einer bestimmten Zeit terminieren (z.B. 300 Sekunden).

Feststellen, wen es betrifft

Eigentlich sollte die Applikation in den meisten Fällen selber merken, wenn sie unerwartet beendet wurde (Fall 2 und 3). Sehr oft tut sie dies aber nicht. Daher müssen wir als Datenbankverantwortliche der Applikation manchmal auf die Sprünge helfen, und Ihr mitteilen, dass unerwartete Abbrüche überhaupt vorkommen und wo im Applikationscode das ungefähr geschieht.

Das erste Anzeichen dafür ist, wie oben Beschrieben, ein Status Zähler von Aborted_clients grösser 0. Spannend wir das ganze aber erst wenn wir Aborted_clients in Relation zur Uptime setzen. Wenn wir nur 10 Aborted_clients über die letzten 100 Tage haben, dann kann man diesen Zähler getrost vernachlässigen. Wenn Aborted_clients im Minutentakt hochgezählt wird, sollte man sich das Ganze schon genauer anschauen:

mariadb> SHOW GLOBAL STATUS WHERE Variable_name = 'aborted_clients' OR Variable_name = 'uptime'; +-----------------+--------+ | Variable_name | Value | +-----------------+--------+ | Aborted_clients | 5438 | | Uptime | 257991 | +-----------------+--------+ mariadb> SELECT 257991/5438 AS Abort_every_s; +---------------+ | Abort_every_s | +---------------+ | 47.4423 | +---------------+

Die nächste Frage, die sich stellt, ist, welcher Applikationsuser ist davon betroffen? Diese Frage kann auf 2 verschiedene Wege beantwortet werden. Entweder über das PERFORMANCE_SCHEMA mit der Abfrage nach Accounts, welche die Verbindung nicht sauber schliessen:

mariadb> SELECT ess.user, ess.host , (a.total_connections - a.current_connections) - ess.count_star as not_closed , ((a.total_connections - a.current_connections) - ess.count_star) * 100 / (a.total_connections - a.current_connections) as pct_not_closed FROM performance_schema.events_statements_summary_by_account_by_event_name ess JOIN performance_schema.accounts a on (ess.user = a.user and ess.host = a.host) WHERE ess.event_name = 'statement/com/quit' AND (a.total_connections - a.current_connections) > ess.count_star ; +-----------+---------------+------------+----------------+ | user | host | not_closed | pct_not_closed | +-----------+---------------+------------+----------------+ | applicat | 10.0.246.74 | 31 | 0.0001 | | applicat | 10.0.246.73 | 59 | 0.0003 | | replicate | 10.0.246.72 | 1 | 100.0000 | | applicat | 10.0.246.76 | 4 | 0.0024 | | root | localhost | 3 | 0.0053 | | applicat | localhost | 51880 | 0.2991 | | applicat | 10.0.246.77 | 1 | 100.0000 | +-----------+---------------+------------+----------------+

Oder über das Error Log, wenn die die Variable log_warnings auf 2 gesetzt ist:

mariadb> SHOW GLOBAL VARIABLES LIKE 'log_warn%'; +---------------+-------+ | Variable_name | Value | +---------------+-------+ | log_warnings | 2 | +---------------+-------+

Bei MySQL 5.7 und neuer wird hierzu die Variable log_error_verbosity auf 3 gesetzt:

mysql> SHOW GLOBAL VARIABLES LIKE '%verbosity%'; +---------------------+-------+ | Variable_name | Value | +---------------------+-------+ | log_error_verbosity | 3 | +---------------------+-------+

Ein Eintrag ins Error Log sieht dann in etwa wie folgt aus:

[Warning] Aborted connection 411 to db: 'app_production' user: 'app_prod' host: 'mysql_LB' (Got an error writing communication packets) [Warning] Aborted connection 417 to db: 'app_production' user: 'app_prod' host: 'mysql_LB' (Got an error writing communication packets) [Warning] Aborted connection 424 to db: 'billing' user: 'billing' host: 'mysql_LB' (Got an error reading communication packets) [Warning] Aborted connection 433 to db: 'app_production' user: 'app_prod' host: 'mysql_LB' (Got an error reading communication packets) [Warning] Aborted connection 449 to db: 'app_production' user: 'app_prod' host: 'mysql_LB' (Got an error reading communication packets)

Somit wissen wir jetzt also bereits etwas genauer, welchen User von welchem Host mit Zugriff auf welches Schema es erwischt hat. Zudem haben wir noch die Connection ID welche eindeutig und aufsteigen ist.

Feststellen wo im Code es ungefähr passiert

Um festzustellen, wo im Applikationscode der unerwartete Abbruch ungefähr passiert haben wir wiederum 2 Möglichkeiten.

Wir können dazu das General Query Log einschalten (Achtung: kann sehr rasant anwachsen!) und dann die enstprechende Verbindung suchen:

mariadb> SET GLOBAL general_log = 1; mariadb> SHOW GLOBAL VARIABLES LIKE '%general%'; +------------------+----------------------------------------------------------------------+ | Variable_name | Value | +------------------+----------------------------------------------------------------------+ | general_log | ON | | general_log_file | /home/mysql/database/mariadb-10.2/log/chef_mariadb-10.2_general.log | +------------------+----------------------------------------------------------------------+

Eine sauber abgebaute Verbindung sieht darin wie folgt aus:

Time Id Command Argument 2017-04-20T10:26:05.613569Z 26 Connect app@localhost on test using TCP/IP 2017-04-20T10:26:05.613629Z 26 Query SELECT ... 2017-04-20T10:26:05.613681Z 26 Quit

Eine unsauber abgebaute oder noch offene Verbindung wie folgt:

Time Id Command Argument 2017-04-20T10:26:17.165585Z 27 Connect app@localhost on test using TCP/IP 2017-04-20T10:26:17.165785Z 27 Query SELECT ... Fehlendes Quit

Die zweite Möglichkeit besteht darin, die Sequenz von Abfragen über das PERFORMANCE_SCHEMA zu ermitteln. Hierzu müssen wir als erstes herausfinden, wie gross der Unterschied zwischen der Processlist ID und der Datenbankserver internen Thread ID ist:

mariadb> SELECT thread_id, processlist_id, thread_id-processlist_id AS diff FROM performance_schema.threads WHERE processlist_id IS NOT NULL ORDER BY thread_id DESC LIMIT 3; +-----------+----------------+------+ | thread_id | processlist_id | diff | +-----------+----------------+------+ | 436 | 433 | 3 | | 427 | 424 | 3 | | 420 | 417 | 3 | +-----------+----------------+------+

In einem zweiten Schritt können wir über das PERFORMANCE_SCHEMA herausfinden welche Befehle von der Applikation ausgeführt wurden:

UPDATE performance_schema.setup_consumers SET enabled = 1 WHERE name = 'events_statements_history_long'; mariadb> SELECT thread_id, event_name, sql_text, current_schema FROM performance_schema.events_statements_history_long WHERE thread_id = 433 + 3; +-----------+---------------------------------+----------------------------------------------------------+----------------+ | THREAD_ID | EVENT_NAME | SQL_TEXT | CURRENT_SCHEMA | +-----------+---------------------------------+----------------------------------------------------------+----------------+ | 436 | statement/sql/set_option | SET NAMES utf8, @@SESSION.sql_mode = 'STRICT_ALL_TABLES' | app_production | | 436 | statement/com/Ping | NULL | app_production | | 436 | statement/sql/select | select @@character_set_database as 'Value' | app_production | | 436 | statement/sql/show_tables | SHOW TABLES LIKE 'schema_migrations' | app_production | | 436 | statement/sql/show_tables | SHOW TABLES LIKE 'schema_migrations' | app_production | | 436 | statement/sql/select | SELECT `schema_migrations`.* FROM `schema_migrations` | app_production | | 436 | statement/sql/show_fields | SHOW FULL FIELDS FROM `schema_migrations` | app_production | | 436 | statement/sql/show_fields | SHOW FULL FIELDS FROM `settings` | app_production | +-----------+---------------------------------+----------------------------------------------------------+----------------+

Nun sollte es in Zusammenarbeit mit den Entwicklern nicht mehr allzu schwer fallen, die entsprechenden Stellen im Applikationscode zu finden und die Fehler zu beheben.

Taxonomy upgrade extras: verbindungaborted_clientsoom

Translate to your preferred language:

Wer sich etwas vertieft mit den MariaDB Status Zählern (SHOW GLOBAL STATUS;) auseinander setzt, wird früher oder später auf den Zähler Aborted_clients stossen:

mariadb> SHOW GLOBAL STATUS LIKE 'aborted_clients'; +-----------------+-------+ | Variable_name | Value | +-----------------+-------+ | Aborted_clients | 5392 | +-----------------+-------+

Wenn man sich dann die MariaDB Dokumentation anschaut, steht da folgendes:

Number of aborted client connections. This can be due to the client not calling mysql_close() before exiting, the client sleeping without issuing a request to the server for more seconds than specified by wait_timeout or interactive_timeout, or by the client program ending in the midst of transferring data.

Also:

• Vergessener Aufruf von mysql_close().
• Inaktive Verbindung (Sleep) für mehr als wait_timeout oder interactive_timeout Sekunden.
• Unerwartete Beendigung der Applikation.

Der erste Punkt geht unter die Kategorie: Unsauber programmiert und somit ein Fehler in der Anwendung.

Der zweite Punkt ist eher ein Konfigurationsproblem sei es auf Datenbankseite oder auf Applikationsseite.

Hier stellt sich die Frage: Warum sind die Timeouts so eingestellt, wenn die Timeouts kurz sind? Default für beide Timeouts ist 28800 Sekunden, also 8 Stunden.

mariadb> SHOW GLOBAL VARIABLES LIKE '%timeout'; +---------------------------+-------+ | Variable_name | Value | +---------------------------+-------+ | interactive_timeout | 28800 | | wait_timeout | 28800 | +---------------------------+-------+

Oder aber: Warum schickt die Anwendung so lange keine Daten über eine geöffnete Verbindung (hat die Anwendung die Verbindung verloren)?

Der zweite Fall trifft üblicherweise dann ein, wenn persistente Verbindungen verwendet werden (Java Connection Pool, Ruby on Rails, PHP Persistent Database Connections, etc.). Dann sollten die Entwickler den Connector so konfigurieren, dass er alle paar Sekunden einen Ping über die Verbindung schickt.

Der dritte Fall hat sehr viel Ähnlichkeit mit dem ersten Fall: Die Applikation beendet sich früher als erwartet. Das kann zum Beispiel auftreten, wenn:

• exit() vor mysql_close() (Fall 1 von oben)
• Applikation wurde unerwartet von aussen beendet (kill, OOM Killer, systemd, etc.)
• Firewalls oder LoadBalancer die eine idelnde Verbindung nach einer bestimmten Zeit terminieren (z.B. 300 Sekunden).

Feststellen, wen es betrifft

Eigentlich sollte die Applikation in den meisten Fällen selber merken, wenn sie unerwartet beendet wurde (Fall 2 und 3). Sehr oft tut sie dies aber nicht. Daher müssen wir als Datenbankverantwortliche der Applikation manchmal auf die Sprünge helfen, und Ihr mitteilen, dass unerwartete Abbrüche überhaupt vorkommen und wo im Applikationscode das ungefähr geschieht.

Das erste Anzeichen dafür ist, wie oben Beschrieben, ein Status Zähler von Aborted_clients grösser 0. Spannend wir das ganze aber erst wenn wir Aborted_clients in Relation zur Uptime setzen. Wenn wir nur 10 Aborted_clients über die letzten 100 Tage haben, dann kann man diesen Zähler getrost vernachlässigen. Wenn Aborted_clients im Minutentakt hochgezählt wird, sollte man sich das Ganze schon genauer anschauen:

mariadb> SHOW GLOBAL STATUS WHERE Variable_name = 'aborted_clients' OR Variable_name = 'uptime'; +-----------------+--------+ | Variable_name | Value | +-----------------+--------+ | Aborted_clients | 5438 | | Uptime | 257991 | +-----------------+--------+ mariadb> SELECT 257991/5438 AS Abort_every_s; +---------------+ | Abort_every_s | +---------------+ | 47.4423 | +---------------+

Die nächste Frage, die sich stellt, ist, welcher Applikationsuser ist davon betroffen? Diese Frage kann auf 2 verschiedene Wege beantwortet werden. Entweder über das PERFORMANCE_SCHEMA mit der Abfrage nach Accounts, welche die Verbindung nicht sauber schliessen:

mariadb> SELECT ess.user, ess.host , (a.total_connections - a.current_connections) - ess.count_star as not_closed , ((a.total_connections - a.current_connections) - ess.count_star) * 100 / (a.total_connections - a.current_connections) as pct_not_closed FROM performance_schema.events_statements_summary_by_account_by_event_name ess JOIN performance_schema.accounts a on (ess.user = a.user and ess.host = a.host) WHERE ess.event_name = 'statement/com/quit' AND (a.total_connections - a.current_connections) > ess.count_star ; +-----------+---------------+------------+----------------+ | user | host | not_closed | pct_not_closed | +-----------+---------------+------------+----------------+ | applicat | 10.0.246.74 | 31 | 0.0001 | | applicat | 10.0.246.73 | 59 | 0.0003 | | replicate | 10.0.246.72 | 1 | 100.0000 | | applicat | 10.0.246.76 | 4 | 0.0024 | | root | localhost | 3 | 0.0053 | | applicat | localhost | 51880 | 0.2991 | | applicat | 10.0.246.77 | 1 | 100.0000 | +-----------+---------------+------------+----------------+

Oder über das Error Log, wenn die die Variable log_warnings auf 2 gesetzt ist:

mariadb> SHOW GLOBAL VARIABLES LIKE 'log_warn%'; +---------------+-------+ | Variable_name | Value | +---------------+-------+ | log_warnings | 2 | +---------------+-------+

Bei MySQL 5.7 und neuer wird hierzu die Variable log_error_verbosity auf 3 gesetzt:

mysql> SHOW GLOBAL VARIABLES LIKE '%verbosity%'; +---------------------+-------+ | Variable_name | Value | +---------------------+-------+ | log_error_verbosity | 3 | +---------------------+-------+

Ein Eintrag ins Error Log sieht dann in etwa wie folgt aus:

[Warning] Aborted connection 411 to db: 'app_production' user: 'app_prod' host: 'mysql_LB' (Got an error writing communication packets) [Warning] Aborted connection 417 to db: 'app_production' user: 'app_prod' host: 'mysql_LB' (Got an error writing communication packets) [Warning] Aborted connection 424 to db: 'billing' user: 'billing' host: 'mysql_LB' (Got an error reading communication packets) [Warning] Aborted connection 433 to db: 'app_production' user: 'app_prod' host: 'mysql_LB' (Got an error reading communication packets) [Warning] Aborted connection 449 to db: 'app_production' user: 'app_prod' host: 'mysql_LB' (Got an error reading communication packets)

Somit wissen wir jetzt also bereits etwas genauer, welchen User von welchem Host mit Zugriff auf welches Schema es erwischt hat. Zudem haben wir noch die Connection ID welche eindeutig und aufsteigen ist.

Feststellen wo im Code es ungefähr passiert

Um festzustellen, wo im Applikationscode der unerwartete Abbruch ungefähr passiert haben wir wiederum 2 Möglichkeiten.

Wir können dazu das General Query Log einschalten (Achtung: kann sehr rasant anwachsen!) und dann die enstprechende Verbindung suchen:

mariadb> SET GLOBAL general_log = 1; mariadb> SHOW GLOBAL VARIABLES LIKE '%general%'; +------------------+----------------------------------------------------------------------+ | Variable_name | Value | +------------------+----------------------------------------------------------------------+ | general_log | ON | | general_log_file | /home/mysql/database/mariadb-10.2/log/chef_mariadb-10.2_general.log | +------------------+----------------------------------------------------------------------+

Eine sauber abgebaute Verbindung sieht darin wie folgt aus:

Time Id Command Argument 2017-04-20T10:26:05.613569Z 26 Connect app@localhost on test using TCP/IP 2017-04-20T10:26:05.613629Z 26 Query SELECT ... 2017-04-20T10:26:05.613681Z 26 Quit

Eine unsauber abgebaute oder noch offene Verbindung wie folgt:

Time Id Command Argument 2017-04-20T10:26:17.165585Z 27 Connect app@localhost on test using TCP/IP 2017-04-20T10:26:17.165785Z 27 Query SELECT ... Fehlendes Quit

Die zweite Möglichkeit besteht darin, die Sequenz von Abfragen über das PERFORMANCE_SCHEMA zu ermitteln. Hierzu müssen wir als erstes herausfinden, wie gross der Unterschied zwischen der Processlist ID und der Datenbankserver internen Thread ID ist:

mariadb> SELECT thread_id, processlist_id, thread_id-processlist_id AS diff FROM performance_schema.threads WHERE processlist_id IS NOT NULL ORDER BY thread_id DESC LIMIT 3; +-----------+----------------+------+ | thread_id | processlist_id | diff | +-----------+----------------+------+ | 436 | 433 | 3 | | 427 | 424 | 3 | | 420 | 417 | 3 | +-----------+----------------+------+

In einem zweiten Schritt können wir über das PERFORMANCE_SCHEMA herausfinden welche Befehle von der Applikation ausgeführt wurden:

UPDATE performance_schema.setup_consumers SET enabled = 1 WHERE name = 'events_statements_history_long'; mariadb> SELECT thread_id, event_name, sql_text, current_schema FROM performance_schema.events_statements_history_long WHERE thread_id = 433 + 3; +-----------+---------------------------------+----------------------------------------------------------+----------------+ | THREAD_ID | EVENT_NAME | SQL_TEXT | CURRENT_SCHEMA | +-----------+---------------------------------+----------------------------------------------------------+----------------+ | 436 | statement/sql/set_option | SET NAMES utf8, @@SESSION.sql_mode = 'STRICT_ALL_TABLES' | app_production | | 436 | statement/com/Ping | NULL | app_production | | 436 | statement/sql/select | select @@character_set_database as 'Value' | app_production | | 436 | statement/sql/show_tables | SHOW TABLES LIKE 'schema_migrations' | app_production | | 436 | statement/sql/show_tables | SHOW TABLES LIKE 'schema_migrations' | app_production | | 436 | statement/sql/select | SELECT `schema_migrations`.* FROM `schema_migrations` | app_production | | 436 | statement/sql/show_fields | SHOW FULL FIELDS FROM `schema_migrations` | app_production | | 436 | statement/sql/show_fields | SHOW FULL FIELDS FROM `settings` | app_production | +-----------+---------------------------------+----------------------------------------------------------+----------------+

Nun sollte es in Zusammenarbeit mit den Entwicklern nicht mehr allzu schwer fallen, die entsprechenden Stellen im Applikationscode zu finden und die Fehler zu beheben.

Taxonomy upgrade extras: verbindungaborted_clients

Der Call for Presentations für die DOAG 2017 Konferenz + Ausstellung vom 21. bis 24. November ist nun eröffnet!

Damit die DOAG erneut das umfangreichste Vortrags-Programm für Oracle/MySQL Produkte in Europa anbieten kann, benötigen wir Ihre Unterstützung.

Wir laden Sie hiermit herzlich ein Vorträge jeden Levels von 45 Minuten Länge zum Thema MySQL einzureichen. Es gilt: je mehr Praxisbezug, desto besser.

Themen können zum Beispiel sein:

• Migration von Oracle nach MySQL.
• Praktische Erfahrungen aus dem Betrieb eines MySQL Clusters.
• Stolperfallen bei der Adaption einer Anwendung an MySQL.
• Performance Tuning Tipps aus Sicht eines MySQL DBAs.
• Upgrade nach MySQL 5.7 und Erfahrungen damit im Betrieb.
• Gedanken zur Entscheidung für MySQL als strategische DB-Plattform.

Als Gegenleistung erhalten Sie 3 Tage kostenfreien Zutritt zur Konferenz, zur Ausstellung und allen DOAG Vorträge sowie zum grossen Galadiner.

Mit mehr als 2000 Besuchern pro Jahr ist die DOAG Konferenz + Ausstellung das Highlight der Oracle-Community im deutschsprachigen Raum. Seien Sie als Referent dabei - teilen Sie Ihr Wissen, knüpfen Sie neue Kontakte.

Jetzt bis zum 1. Juni Vortrag einreichen und dabei sein.

Wir freuen uns auf Ihre Mitwirkung
Ihr FromDual Team

Taxonomy upgrade extras: doagconferenceOraclemysql

Der Call for Presentations für die DOAG 2017 Konferenz + Ausstellung vom 21. bis 24. November ist nun eröffnet!

Damit die DOAG erneut das umfangreichste Vortrags-Programm für Oracle/MySQL Produkte in Europa anbieten kann, benötigen wir Ihre Unterstützung.

Wir laden Sie hiermit herzlich ein Vorträge jeden Levels von 45 Minuten Länge zum Thema MySQL einzureichen. Es gilt: je mehr Praxisbezug, desto besser.

Themen können zum Beispiel sein:

• Migration von Oracle nach MySQL.
• Praktische Erfahrungen aus dem Betrieb eines MySQL Clusters.
• Stolperfallen bei der Adaption einer Anwendung an MySQL.
• Performance Tuning Tipps aus Sicht eines MySQL DBAs.
• Upgrade nach MySQL 5.7 und Erfahrungen damit im Betrieb.
• Gedanken zur Entscheidung für MySQL als strategische DB-Plattform.

Als Gegenleistung erhalten Sie 3 Tage kostenfreien Zutritt zur Konferenz, zur Ausstellung und allen DOAG Vorträge sowie zum grossen Galadiner.

Mit mehr als 2000 Besuchern pro Jahr ist die DOAG Konferenz + Ausstellung das Highlight der Oracle-Community im deutschsprachigen Raum. Seien Sie als Referent dabei - teilen Sie Ihr Wissen, knüpfen Sie neue Kontakte.

Jetzt bis zum 1. Juni Vortrag einreichen und dabei sein.

Wir freuen uns auf Ihre Mitwirkung
Ihr FromDual Team

Taxonomy upgrade extras: doag2017conferenceOraclemysql

Der Call for Presentations für die DOAG 2017 Konferenz + Ausstellung vom 21. bis 24. November ist nun eröffnet!

Damit die DOAG erneut das umfangreichste Vortrags-Programm für Oracle/MySQL Produkte in Europa anbieten kann, benötigen wir Ihre Unterstützung.

Wir laden Sie hiermit herzlich ein Vorträge jeden Levels von 45 Minuten Länge zum Thema MySQL einzureichen. Es gilt: je mehr Praxisbezug, desto besser.

Themen können zum Beispiel sein:

• Migration von Oracle nach MySQL.
• Praktische Erfahrungen aus dem Betrieb eines MySQL Clusters.
• Stolperfallen bei der Adaption einer Anwendung an MySQL.
• Performance Tuning Tipps aus Sicht eines MySQL DBAs.
• Upgrade nach MySQL 5.7 und Erfahrungen damit im Betrieb.
• Gedanken zur Entscheidung für MySQL als strategische DB-Plattform.

Als Gegenleistung erhalten Sie 3 Tage kostenfreien Zutritt zur Konferenz, zur Ausstellung und allen DOAG Vorträge sowie zum grossen Galadiner.

Mit mehr als 2000 Besuchern pro Jahr ist die DOAG Konferenz + Ausstellung das Highlight der Oracle-Community im deutschsprachigen Raum. Seien Sie als Referent dabei - teilen Sie Ihr Wissen, knüpfen Sie neue Kontakte.

Jetzt bis zum 1. Juni Vortrag einreichen und dabei sein.

Wir freuen uns auf Ihre Mitwirkung
Ihr FromDual Team

Taxonomy upgrade extras: doag2017conferenceOraclemysql

The PAM authentication plug-in is an extension included in MySQL Enterprise Edition (since 5.5) and in MariaDB (since 5.2).

• Pluggable authentication module
• Understanding PAM

MySQL authentication against pam_unix

• The PAM Authentication Plugin

Check if plug-in is available:

# ll lib/plugin/auth*so -rwxr-xr-x 1 mysql mysql 42937 Sep 18 2015 lib/plugin/authentication_pam.so -rwxr-xr-x 1 mysql mysql 25643 Sep 18 2015 lib/plugin/auth.so -rwxr-xr-x 1 mysql mysql 12388 Sep 18 2015 lib/plugin/auth_socket.so -rwxr-xr-x 1 mysql mysql 25112 Sep 18 2015 lib/plugin/auth_test_plugin.so

Install PAM plug-in:

mysql> INSTALL PLUGIN authentication_pam SONAME 'authentication_pam.so';

Check plug-in information:

mysql> SELECT * FROM information_schema.plugins WHERE plugin_name = 'authentication_pam'\G *************************** 1. row *************************** PLUGIN_NAME: authentication_pam PLUGIN_VERSION: 1.1 PLUGIN_STATUS: ACTIVE PLUGIN_TYPE: AUTHENTICATION PLUGIN_TYPE_VERSION: 1.1 PLUGIN_LIBRARY: authentication_pam.so PLUGIN_LIBRARY_VERSION: 1.7 PLUGIN_AUTHOR: Georgi Kodinov PLUGIN_DESCRIPTION: PAM authentication plugin PLUGIN_LICENSE: PROPRIETARY LOAD_OPTION: ON

It seems like this set-up is persisted and survives a database restart because of the mysql schema table:

mysql> SELECT * FROM mysql.plugin; +--------------------+-----------------------+ | name | dl | +--------------------+-----------------------+ | authentication_pam | authentication_pam.so | +--------------------+-----------------------+

Configuring PAM on Ubuntu/Debian:

#%PAM-1.0 # # /etc/pam.d/mysql # @include common-auth @include common-account @include common-session-noninteractive

Create the database user matching to the O/S user:

mysql> CREATE USER 'oli'@'localhost' IDENTIFIED WITH authentication_pam AS 'mysql' ; mysql> GRANT ALL PRIVILEGES ON test.* TO 'oli'@'localhost';

Verifying user in the database:

mysql> SELECT user, host, authentication_string FROM `mysql`.`user` WHERE user = 'oli'; +-----------+-----------+-------------------------------------------+ | user | host | authentication_string | +-----------+-----------+-------------------------------------------+ | oli | localhost | mysql | +-----------+-----------+-------------------------------------------+ mysql> SHOW CREATE USER 'oli'@'localhost'; +-----------------------------------------------------------------------------------------------------------------------------------+ | CREATE USER for oli@localhost | +-----------------------------------------------------------------------------------------------------------------------------------+ | CREATE USER 'oli'@'localhost' IDENTIFIED WITH 'authentication_pam' AS 'mysql' REQUIRE NONE PASSWORD EXPIRE DEFAULT ACCOUNT UNLOCK | +-----------------------------------------------------------------------------------------------------------------------------------+

Connection tests:

# mysql --user=oli --host=localhost ERROR 2059 (HY000): Authentication plugin 'mysql_clear_password' cannot be loaded: plugin not enabled # mysql --user=oli --host=localhost --enable-cleartext-plugin --password=wrong ERROR 1045 (28000): Access denied for user 'oli'@'localhost' (using password: YES) # tail /var/log/auth.log Feb 13 15:15:14 chef unix_chkpwd[31600]: check pass; user unknown Feb 13 15:15:14 chef unix_chkpwd[31600]: password check failed for user (oli) # mysql --user=oli --host=localhost --enable-cleartext-plugin --password=rigth ERROR 1045 (28000): Access denied for user 'oli'@'localhost' (using password: YES) # tail /var/log/auth.log Feb 13 15:15:40 chef unix_chkpwd[31968]: check pass; user unknown Feb 13 15:15:40 chef unix_chkpwd[31968]: password check failed for user (oli)

Some research led to the following result: The non privileged mysql user is not allowed to access the file /etc/shadow thus it should be added to the group shadow to make it work:

# ll /sbin/unix_chkpwd -rwxr-sr-x 1 root shadow 35536 Mar 16 2016 /sbin/unix_chkpwd # usermod -a -G shadow mysql

• Comments - PAM Authentication Plugin
• MDEV-7032: new pam plugin with a suid wrapper

Connection tests:

# mysql --user=oli --host=localhost --enable-cleartext-plugin --password=rigth mysql> SELECT USER(), CURRENT_USER(), @@proxy_user; +---------------+----------------+--------------+ | USER() | CURRENT_USER() | @@proxy_user | +---------------+----------------+--------------+ | oli@localhost | oli@localhost | NULL | +---------------+----------------+--------------+
MariaDB authentication against pam_unix

• PAM Authentication Plugin

Check if plug-in is available:

# ll lib/plugin/auth*so -rwxr-xr-x 1 mysql mysql 12462 Nov 4 14:37 lib/plugin/auth_0x0100.so -rwxr-xr-x 1 mysql mysql 33039 Nov 4 14:37 lib/plugin/auth_gssapi_client.so -rwxr-xr-x 1 mysql mysql 80814 Nov 4 14:37 lib/plugin/auth_gssapi.so -rwxr-xr-x 1 mysql mysql 19015 Nov 4 14:37 lib/plugin/auth_pam.so -rwxr-xr-x 1 mysql mysql 13028 Nov 4 14:37 lib/plugin/auth_socket.so -rwxr-xr-x 1 mysql mysql 23521 Nov 4 14:37 lib/plugin/auth_test_plugin.so

Install PAM plug-in:

mysql> INSTALL SONAME 'auth_pam';

Check plug-in information:

mysql> SELECT * FROM information_schema.plugins WHERE plugin_name = 'pam'\G *************************** 1. row *************************** PLUGIN_NAME: pam PLUGIN_VERSION: 1.0 PLUGIN_STATUS: ACTIVE PLUGIN_TYPE: AUTHENTICATION PLUGIN_TYPE_VERSION: 2.0 PLUGIN_LIBRARY: auth_pam.so PLUGIN_LIBRARY_VERSION: 1.11 PLUGIN_AUTHOR: Sergei Golubchik PLUGIN_DESCRIPTION: PAM based authentication PLUGIN_LICENSE: GPL LOAD_OPTION: ON PLUGIN_MATURITY: Stable PLUGIN_AUTH_VERSION: 1.0

Configuring PAM on Ubuntu/Debian:

#%PAM-1.0 # # /etc/pam.d/mysql # @include common-auth @include common-account @include common-session-noninteractive

Create the database user matching to the O/S user:

mysql> CREATE USER 'oli'@'localhost' IDENTIFIED VIA pam USING 'mariadb' ; mysql> GRANT ALL PRIVILEGES ON test.* TO 'oli'@'localhost';

Verifying user in the database:

mysql> SELECT user, host, authentication_string FROM `mysql`.`user` WHERE user = 'oli'; +------+-----------+-----------------------+ | user | host | authentication_string | +------+-----------+-----------------------+ | oli | localhost | mariadb | +------+-----------+-----------------------+

Connection tests:

# mysql --user=oli --host=localhost --password=wrong ERROR 2059 (HY000): Authentication plugin 'dialog' cannot be loaded: /usr/local/mysql/lib/plugin/dialog.so: cannot open shared object file: No such file or directory # tail /var/log/auth.log Feb 13 17:11:16 chef mysqld: pam_unix(mariadb:auth): unexpected response from failed conversation function Feb 13 17:11:16 chef mysqld: pam_unix(mariadb:auth): conversation failed Feb 13 17:11:16 chef mysqld: pam_unix(mariadb:auth): auth could not identify password for [oli] Feb 13 17:11:16 chef mysqld: pam_winbind(mariadb:auth): getting password (0x00000388) Feb 13 17:11:16 chef mysqld: pam_winbind(mariadb:auth): Could not retrieve user's password # mysql --user=oli --host=localhost --password=wrong --plugin-dir=$PWD/lib/plugin ERROR 1045 (28000): Access denied for user 'oli'@'localhost' (using password: NO) Feb 13 17:11:30 chef mysqld: pam_unix(mariadb:auth): authentication failure; logname= uid=1001 euid=1001 tty= ruser= rhost= user=oli Feb 13 17:11:30 chef mysqld: pam_winbind(mariadb:auth): getting password (0x00000388) Feb 13 17:11:30 chef mysqld: pam_winbind(mariadb:auth): pam_get_item returned a password Feb 13 17:11:30 chef mysqld: pam_winbind(mariadb:auth): request wbcLogonUser failed: WBC_ERR_AUTH_ERROR, PAM error: PAM_USER_UNKNOWN (10), NTSTATUS: NT_STATUS_NO_SUCH_USER, Error message was: No such user

Add mysql user to the shadow group:

# ll /sbin/unix_chkpwd -rwxr-sr-x 1 root shadow 35536 Mar 16 2016 /sbin/unix_chkpwd # usermod -a -G shadow mysql

Connection tests:

# mysql --user=oli --host=localhost --password=right --plugin-dir=$PWD/lib/plugin mysql> SELECT USER(), CURRENT_USER(), @@proxy_user; +---------------+----------------+--------------+ | USER() | CURRENT_USER() | @@proxy_user | +---------------+----------------+--------------+ | oli@localhost | oli@localhost | NULL | +---------------+----------------+--------------+
Taxonomy upgrade extras: authenticationpamsecuritypluginplug-in

The PAM authentication plug-in is an extension included in MySQL Enterprise Edition (since 5.5) and in MariaDB (since 5.2).

• Pluggable authentication module
• Understanding PAM

MySQL authentication against pam_unix

• The PAM Authentication Plugin

Check if plug-in is available:

# ll lib/plugin/auth*so -rwxr-xr-x 1 mysql mysql 42937 Sep 18 2015 lib/plugin/authentication_pam.so -rwxr-xr-x 1 mysql mysql 25643 Sep 18 2015 lib/plugin/auth.so -rwxr-xr-x 1 mysql mysql 12388 Sep 18 2015 lib/plugin/auth_socket.so -rwxr-xr-x 1 mysql mysql 25112 Sep 18 2015 lib/plugin/auth_test_plugin.so

Install PAM plug-in:

mysql> INSTALL PLUGIN authentication_pam SONAME 'authentication_pam.so';

Check plug-in information:

mysql> SELECT * FROM information_schema.plugins WHERE plugin_name = 'authentication_pam'\G *************************** 1. row *************************** PLUGIN_NAME: authentication_pam PLUGIN_VERSION: 1.1 PLUGIN_STATUS: ACTIVE PLUGIN_TYPE: AUTHENTICATION PLUGIN_TYPE_VERSION: 1.1 PLUGIN_LIBRARY: authentication_pam.so PLUGIN_LIBRARY_VERSION: 1.7 PLUGIN_AUTHOR: Georgi Kodinov PLUGIN_DESCRIPTION: PAM authentication plugin PLUGIN_LICENSE: PROPRIETARY LOAD_OPTION: ON

It seems like this set-up is persisted and survives a database restart because of the mysql schema table:

mysql> SELECT * FROM mysql.plugin; +--------------------+-----------------------+ | name | dl | +--------------------+-----------------------+ | authentication_pam | authentication_pam.so | +--------------------+-----------------------+

Configuring PAM on Ubuntu/Debian:

#%PAM-1.0 # # /etc/pam.d/mysql # @include common-auth @include common-account @include common-session-noninteractive

Create the database user matching to the O/S user:

mysql> CREATE USER 'oli'@'localhost' IDENTIFIED WITH authentication_pam AS 'mysql' ; mysql> GRANT ALL PRIVILEGES ON test.* TO 'oli'@'localhost';

Verifying user in the database:

mysql> SELECT user, host, authentication_string FROM mysql.user WHERE user = 'oli'; +-----------+-----------+-------------------------------------------+ | user | host | authentication_string | +-----------+-----------+-------------------------------------------+ | oli | localhost | mysql | +-----------+-----------+-------------------------------------------+ mysql> SHOW CREATE USER 'oli'@'localhost'; +-----------------------------------------------------------------------------------------------------------------------------------+ | CREATE USER for oli@localhost | +-----------------------------------------------------------------------------------------------------------------------------------+ | CREATE USER 'oli'@'localhost' IDENTIFIED WITH 'authentication_pam' AS 'mysql' REQUIRE NONE PASSWORD EXPIRE DEFAULT ACCOUNT UNLOCK | +-----------------------------------------------------------------------------------------------------------------------------------+

Connection tests:

# mysql --user=oli --host=localhost ERROR 2059 (HY000): Authentication plugin 'mysql_clear_password' cannot be loaded: plugin not enabled # mysql --user=oli --host=localhost --enable-cleartext-plugin --password=wrong ERROR 1045 (28000): Access denied for user 'oli'@'localhost' (using password: YES) # tail /var/log/auth.log Feb 13 15:15:14 chef unix_chkpwd[31600]: check pass; user unknown Feb 13 15:15:14 chef unix_chkpwd[31600]: password check failed for user (oli) # mysql --user=oli --host=localhost --enable-cleartext-plugin --password=rigth ERROR 1045 (28000): Access denied for user 'oli'@'localhost' (using password: YES) # tail /var/log/auth.log Feb 13 15:15:40 chef unix_chkpwd[31968]: check pass; user unknown Feb 13 15:15:40 chef unix_chkpwd[31968]: password check failed for user (oli)

Some research led to the following result: The non privileged mysql user is not allowed to access the file /etc/shadow thus it should be added to the group shadow to make it work:

# ll /sbin/unix_chkpwd -rwxr-sr-x 1 root shadow 35536 Mar 16 2016 /sbin/unix_chkpwd # usermod -a -G shadow mysql

• Comments - PAM Authentication Plugin
• MDEV-7032: new pam plugin with a suid wrapper

Connection tests:

# mysql --user=oli --host=localhost --enable-cleartext-plugin --password=rigth mysql> SELECT USER(), CURRENT_USER(), @@proxy_user; +---------------+----------------+--------------+ | USER() | CURRENT_USER() | @@proxy_user | +---------------+----------------+--------------+ | oli@localhost | oli@localhost | NULL | +---------------+----------------+--------------+
MariaDB authentication against pam_unix

• PAM Authentication Plugin

Check if plug-in is available:

# ll lib/plugin/auth*so -rwxr-xr-x 1 mysql mysql 12462 Nov 4 14:37 lib/plugin/auth_0x0100.so -rwxr-xr-x 1 mysql mysql 33039 Nov 4 14:37 lib/plugin/auth_gssapi_client.so -rwxr-xr-x 1 mysql mysql 80814 Nov 4 14:37 lib/plugin/auth_gssapi.so -rwxr-xr-x 1 mysql mysql 19015 Nov 4 14:37 lib/plugin/auth_pam.so -rwxr-xr-x 1 mysql mysql 13028 Nov 4 14:37 lib/plugin/auth_socket.so -rwxr-xr-x 1 mysql mysql 23521 Nov 4 14:37 lib/plugin/auth_test_plugin.so

Install PAM plug-in:

mysql> INSTALL SONAME 'auth_pam';

Check plug-in information:

mysql> SELECT * FROM information_schema.plugins WHERE plugin_name = 'pam'\G *************************** 1. row *************************** PLUGIN_NAME: pam PLUGIN_VERSION: 1.0 PLUGIN_STATUS: ACTIVE PLUGIN_TYPE: AUTHENTICATION PLUGIN_TYPE_VERSION: 2.0 PLUGIN_LIBRARY: auth_pam.so PLUGIN_LIBRARY_VERSION: 1.11 PLUGIN_AUTHOR: Sergei Golubchik PLUGIN_DESCRIPTION: PAM based authentication PLUGIN_LICENSE: GPL LOAD_OPTION: ON PLUGIN_MATURITY: Stable PLUGIN_AUTH_VERSION: 1.0

Configuring PAM on Ubuntu/Debian:

#%PAM-1.0 # # /etc/pam.d/mysql # @include common-auth @include common-account @include common-session-noninteractive

Create the database user matching to the O/S user:

mysql> CREATE USER 'oli'@'localhost' IDENTIFIED VIA pam USING 'mariadb' ; mysql> GRANT ALL PRIVILEGES ON test.* TO 'oli'@'localhost';

Verifying user in the database:

mysql> SELECT user, host, authentication_string FROM mysql.user WHERE user = 'oli'; +------+-----------+-----------------------+ | user | host | authentication_string | +------+-----------+-----------------------+ | oli | localhost | mariadb | +------+-----------+-----------------------+

Connection tests:

# mysql --user=oli --host=localhost --password=wrong ERROR 2059 (HY000): Authentication plugin 'dialog' cannot be loaded: /usr/local/mysql/lib/plugin/dialog.so: cannot open shared object file: No such file or directory # tail /var/log/auth.log Feb 13 17:11:16 chef mysqld: pam_unix(mariadb:auth): unexpected response from failed conversation function Feb 13 17:11:16 chef mysqld: pam_unix(mariadb:auth): conversation failed Feb 13 17:11:16 chef mysqld: pam_unix(mariadb:auth): auth could not identify password for [oli] Feb 13 17:11:16 chef mysqld: pam_winbind(mariadb:auth): getting password (0x00000388) Feb 13 17:11:16 chef mysqld: pam_winbind(mariadb:auth): Could not retrieve user's password # mysql --user=oli --host=localhost --password=wrong --plugin-dir=$PWD/lib/plugin ERROR 1045 (28000): Access denied for user 'oli'@'localhost' (using password: NO) Feb 13 17:11:30 chef mysqld: pam_unix(mariadb:auth): authentication failure; logname= uid=1001 euid=1001 tty= ruser= rhost= user=oli Feb 13 17:11:30 chef mysqld: pam_winbind(mariadb:auth): getting password (0x00000388) Feb 13 17:11:30 chef mysqld: pam_winbind(mariadb:auth): pam_get_item returned a password Feb 13 17:11:30 chef mysqld: pam_winbind(mariadb:auth): request wbcLogonUser failed: WBC_ERR_AUTH_ERROR, PAM error: PAM_USER_UNKNOWN (10), NTSTATUS: NT_STATUS_NO_SUCH_USER, Error message was: No such user

Add mysql user to the shadow group:

# ll /sbin/unix_chkpwd -rwxr-sr-x 1 root shadow 35536 Mar 16 2016 /sbin/unix_chkpwd # usermod -a -G shadow mysql

Connection tests:

# mysql --user=oli --host=localhost --password=right --plugin-dir=$PWD/lib/plugin mysql> SELECT USER(), CURRENT_USER(), @@proxy_user; +---------------+----------------+--------------+ | USER() | CURRENT_USER() | @@proxy_user | +---------------+----------------+--------------+ | oli@localhost | oli@localhost | NULL | +---------------+----------------+--------------+
Taxonomy upgrade extras: authenticationpamsecuritypluginplug-in