Archive for the ‘geek’ Category

Percona Live MySQL Conference

Май 9th, 2012

These are things I like that I consider differences from last years conference. There are plenty of other things I like that don’t need to be listed here.

  • The overall tone and feel of the conference was much less marking and much more technical
  • Refreshingly honest keynotes. There was a lot of coming clean about the history of MySQL and the conference.
  • Percona is very technical but it is also a business. They are very good about bringing out the technical and not being pushy about the business.
  • No ice cream social. A thousand people shaking sticky hands with each other is never a good idea.
  • percona.tv
  • The conference was busy but never crowded

Now for the dislike:

  • Only one song before every session.
  • The chairs. Damn the chairs.
  • Wifi failed more often than it worked. Most of the time I was tethered to my phone.
  • smartcity doesn’t work with ssh port forwarded dns/socks poor man vpn.

Just some things to note and tips for next year

  • Classic rock bump in music for the keynotes didn’t really fit.
  • Percona folks are usually really good about having information in the slides. So if you have to choose between skipping a Percona talk for some other talk skip the Percona one because you can go back and read the slides.
  • There is a secret clean bathroom that usually stays clean until the last day. I’m not saying where this is.
  • Monty’s BoF always has black vodka.
  • The black vodka is dangerous so be careful.

I was tempted to skip the conference this year because last year was so depressing. I decided to give Percona a chance at hosting it and I’m glad I did. I look forward to attending and maybe presenting next year.


PlanetMySQL Voting: Vote UP / Vote DOWN

Percona Live MySQL Conference

Май 9th, 2012

These are things I like that I consider differences from last years conference. There are plenty of other things I like that don’t need to be listed here.

  • The overall tone and feel of the conference was much less marking and much more technical
  • Refreshingly honest keynotes. There was a lot of coming clean about the history of MySQL and the conference.
  • Percona is very technical but it is also a business. They are very good about bringing out the technical and not being pushy about the business.
  • No ice cream social. A thousand people shaking sticky hands with each other is never a good idea.
  • percona.tv
  • The conference was busy but never crowded

Now for the dislike:

  • Only one song before every session.
  • The chairs. Damn the chairs.
  • Wifi failed more often than it worked. Most of the time I was tethered to my phone.
  • smartcity doesn’t work with ssh port forwarded dns/socks poor man vpn.

Just some things to note and tips for next year

  • Classic rock bump in music for the keynotes didn’t really fit.
  • Percona folks are usually really good about having information in the slides. So if you have to choose between skipping a Percona talk for some other talk skip the Percona one because you can go back and read the slides.
  • There is a secret clean bathroom that usually stays clean until the last day. I’m not saying where this is.
  • Monty’s BoF always has black vodka.
  • The black vodka is dangerous so be careful.

I was tempted to skip the conference this year because last year was so depressing. I decided to give Percona a chance at hosting it and I’m glad I did. I look forward to attending and maybe presenting next year.


PlanetMySQL Voting: Vote UP / Vote DOWN

MySQL 5.0 can deadlock when flush logs, show processlist, and a slave connection happen at the same time

Май 9th, 2012

[ Note: I haven't fully investigated this problem but the post has been hanging around in my queue for months. Rather than have it rot there I am publishing what I know in hopes that it helps someone else. ]

There are a lot of different kinds of locks in MySQL. Some of these locks are exposed to users such as intention locks, table locks, and row locks. There are other locks that aren’t exposed as well. These are mutexes that MySQL uses internally to protect resources from being modified by more than one thread at a time. These locks are numerous and complicated. When these locks deadlock mysql can stop dead in it’s tracks. The last deadlock I found happens when flush logs, show processlist, and a slave reconnect happen at the same time. I don’t have a core from the mysqld process, only stack traces. The breakdowns of stack traces are locks that I’m pretty sure the threads own and ones that they may be stuck trying on. I am working on gathering more data and making a repeatable test case. I will update this post or link to a new one when I do.

Flush logs is responsible for rotating and deleting old logs. It rotates every log under the sun including the relay and binary logs. I created a patch a few years ago to allow users to specify which log to rotate that is now included in MySQL 5.5. Flush logs has a safe guard built in when flushing binary logs to a make sure that it isn’t going to delete  a log that a binlog dump thread hasn’t sent to a slave yet. For this safe guard to work it has to loop through every client thread in MySQL and check if it is a dump thread. If it is then it has to check which log it is on to make sure the log isn’t in use.

Each log file has a few mutexes associated with it. The flush logs thread owns LOCK_log and LOCK_index from the binary log. bl in this case refers to the binary log object. linfo is the log info object which is part of the thread for some reason.

Owns locks
bl->LOCK_log
bl->LOCK_index
Tries to lock
LOCK_thread_count
linfo->lock

Thread 11 (Thread 0x458e6940 (LWP 27068)):
#0 0x000000377560d4c4 in __lll_lock_wait () from /lib64/libpthread.so.0
#1 0x0000003775608e50 in _L_lock_1233 () from /lib64/libpthread.so.0
#2 0x0000003775608dd3 in pthread_mutex_lock () from /lib64/libpthread.so.0
#3 0x000000000066f8f6 in log_in_use(char const*) () <– LOCK_thread_count
#4 0x00000000005f88d0 in MYSQL_LOG::purge_logs_before_date(long) () <– gets bl->LOCK_index
#5 0x00000000005fa09c in MYSQL_LOG::rotate_and_purge(unsigned int) () <– gets bl->LOCK_log
#6 0x000000000058715d in reload_acl_and_cache(THD*, unsigned long, TABLE_LIST*, bool*) ()
#7 0x000000000058c3d3 in mysql_execute_command(THD*) ()
#8 0x00000000005915f1 in mysql_parse(THD*, char const*, unsigned int, char const**) ()
#9 0x000000000059279e in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
#10 0x000000000059374b in handle_one_connection ()
#11 0x000000377560673d in start_thread () from /lib64/libpthread.so.0
#12 0x0000003774ad3d1d in clone () from /lib64/libc.so.6

 

What I mean by slave connection is what happens on the master when a slave connects. The master will spawn a thread that is responsible for killing any other threads with the same server id and then sending binlogs to the slave. This is why when two slaves are configured with the same server id they will disconnect each other. Slaves will try to reconnect a minute later by default 60 seconds. So every minute each slave will get to download binlogs for a minute. The important part for this deadlock is that when a new slave connects the thread spawned by the master will walk through every thread connected to MySQL looking for an old thread with the same slave server id and try to kill it.

This is the stack from the new slave thread trying to kill the old one

Owns
tmp->LOCK_delete from thread 16.
16->mysys_var->mutex
Tries
bl->LOCK_log from thread 16->mysys_var->current_mutex

Thread 17 (Thread 0×45968940 (LWP 27194)):
#0 0x000000377560d4c4 in __lll_lock_wait () from /lib64/libpthread.so.0
#1 0x0000003775608e1a in _L_lock_1034 () from /lib64/libpthread.so.0
#2 0x0000003775608cdc in pthread_mutex_lock () from /lib64/libpthread.so.0
#3 0x000000000056863f in THD::awake(THD::killed_state) ()
#4 0x000000000066f8a3 in kill_zombie_dump_threads(unsigned int) ()
#5 0x0000000000592a6e in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
#6 0x000000000059374b in handle_one_connection ()
#7 0x000000377560673d in start_thread () from /lib64/libpthread.so.0
#8 0x0000003774ad3d1d in clone () from /lib64/libc.so.6

The current_mutex deserves a bit of explanation here. In MySQL when a thread wants to wait on a condition it copies the mutex and condition into mysys_var->current_mutex and mysys_var->current_cond. The mysys_var->mutex is the mutex that protects the mysys_var struct. This way if any other thread needs to kill it it knows the condition and mutex it is waiting on so it can be woken up. This is an easy mechanism to kill threads but it makes it more difficult to figure out what a thread is locking on. In this case I think current_mutex is bl->LOCK_log from thread 16 which is coming up.

Thread 16 (Thread 0x45aee940 (LWP 3819)):
#0 0x000000377560d4c4 in __lll_lock_wait () from /lib64/libpthread.so.0
#1 0x00000037756101b1 in _L_cond_lock_989 () from /lib64/libpthread.so.0
#2 0x000000377561007f in __pthread_mutex_cond_lock () from /lib64/libpthread.so.0
#3 0x000000377560af84 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#4 0x00000000005f6637 in MYSQL_LOG::wait_for_update(THD*, bool) ()
#5 0x000000000067133a in mysql_binlog_send(THD*, char*, unsigned long long, unsigned short) ()
#6 0×0000000000592639 in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
#7 0x000000000059374b in handle_one_connection ()
#8 0x000000377560673d in start_thread () from /lib64/libpthread.so.0
#9 0x0000003774ad3d1d in clone () from /lib64/libc.so.6

Thread 16 is the old master thread waiting to dump a binglog. It should be killed by the new thread but isn’t.

Show processlist also loop through the list of client threads to get their id, hostname, user, state and query that they may be running. The common theme between all of these threads is that they all need to loop through the list of client threads in order to do their jobs. When looping through this list they must grab the LOCK_thread_count mutex. Owning this mutex means that no other thread will be able to change the list of client threads making it safe to loop through.

Owns
LOCK_thread_count
Tries
mysys_var->mutex probably from thread 16/17

Thread 3 (Thread 0x45a6c940 (LWP 13482)):
#0 0x000000377560d4c4 in __lll_lock_wait () from /lib64/libpthread.so.0
#1 0x0000003775608e50 in _L_lock_1233 () from /lib64/libpthread.so.0
#2 0x0000003775608dd3 in pthread_mutex_lock () from /lib64/libpthread.so.0
#3 0x000000000065879a in mysqld_list_processes(THD*, char const*, bool) ()
#4 0x000000000058ecf6 in mysql_execute_command(THD*) ()
#5 0x00000000005915f1 in mysql_parse(THD*, char const*, unsigned int, char const**) ()
#6 0x000000000059279e in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
#7 0x000000000059374b in handle_one_connection ()
#8 0x000000377560673d in start_thread () from /lib64/libpthread.so.0
#9 0x0000003774ad3d1d in clone () from /lib64/libc.so.6

I haven’t quite solved this one yet but I hope the breakdown may help someone else with the same issue. I worked around this one by disabling a script that runs show processlist and records this output. This makes it far less likely that all three conditions will be met to produce the deadlock. Other options are changing the log rotation script to only flush the logs it needs or figure out why the slave reconnect happens. I have a few theories on long running log rotations causing this but I haven’t been able to reproduce them.


PlanetMySQL Voting: Vote UP / Vote DOWN

MySQL 5.0 can deadlock when flush logs, show processlist, and a slave connection happen at the same time

Май 9th, 2012

[ Note: I haven't fully investigated this problem but the post has been hanging around in my queue for months. Rather than have it rot there I am publishing what I know in hopes that it helps someone else. ]

There are a lot of different kinds of locks in MySQL. Some of these locks are exposed to users such as intention locks, table locks, and row locks. There are other locks that aren’t exposed as well. These are mutexes that MySQL uses internally to protect resources from being modified by more than one thread at a time. These locks are numerous and complicated. When these locks deadlock mysql can stop dead in it’s tracks. The last deadlock I found happens when flush logs, show processlist, and a slave reconnect happen at the same time. I don’t have a core from the mysqld process, only stack traces. The breakdowns of stack traces are locks that I’m pretty sure the threads own and ones that they may be stuck trying on. I am working on gathering more data and making a repeatable test case. I will update this post or link to a new one when I do.

Flush logs is responsible for rotating and deleting old logs. It rotates every log under the sun including the relay and binary logs. I created a patch a few years ago to allow users to specify which log to rotate that is now included in MySQL 5.5. Flush logs has a safe guard built in when flushing binary logs to a make sure that it isn’t going to delete  a log that a binlog dump thread hasn’t sent to a slave yet. For this safe guard to work it has to loop through every client thread in MySQL and check if it is a dump thread. If it is then it has to check which log it is on to make sure the log isn’t in use.

Each log file has a few mutexes associated with it. The flush logs thread owns LOCK_log and LOCK_index from the binary log. bl in this case refers to the binary log object. linfo is the log info object which is part of the thread for some reason.

Owns locks
bl->LOCK_log
bl->LOCK_index
Tries to lock
LOCK_thread_count
linfo->lock

Thread 11 (Thread 0x458e6940 (LWP 27068)):
#0 0x000000377560d4c4 in __lll_lock_wait () from /lib64/libpthread.so.0
#1 0x0000003775608e50 in _L_lock_1233 () from /lib64/libpthread.so.0
#2 0x0000003775608dd3 in pthread_mutex_lock () from /lib64/libpthread.so.0
#3 0x000000000066f8f6 in log_in_use(char const*) () <– LOCK_thread_count
#4 0x00000000005f88d0 in MYSQL_LOG::purge_logs_before_date(long) () <– gets bl->LOCK_index
#5 0x00000000005fa09c in MYSQL_LOG::rotate_and_purge(unsigned int) () <– gets bl->LOCK_log
#6 0x000000000058715d in reload_acl_and_cache(THD*, unsigned long, TABLE_LIST*, bool*) ()
#7 0x000000000058c3d3 in mysql_execute_command(THD*) ()
#8 0x00000000005915f1 in mysql_parse(THD*, char const*, unsigned int, char const**) ()
#9 0x000000000059279e in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
#10 0x000000000059374b in handle_one_connection ()
#11 0x000000377560673d in start_thread () from /lib64/libpthread.so.0
#12 0x0000003774ad3d1d in clone () from /lib64/libc.so.6

 

What I mean by slave connection is what happens on the master when a slave connects. The master will spawn a thread that is responsible for killing any other threads with the same server id and then sending binlogs to the slave. This is why when two slaves are configured with the same server id they will disconnect each other. Slaves will try to reconnect a minute later by default 60 seconds. So every minute each slave will get to download binlogs for a minute. The important part for this deadlock is that when a new slave connects the thread spawned by the master will walk through every thread connected to MySQL looking for an old thread with the same slave server id and try to kill it.

This is the stack from the new slave thread trying to kill the old one

Owns
tmp->LOCK_delete from thread 16.
16->mysys_var->mutex
Tries
bl->LOCK_log from thread 16->mysys_var->current_mutex

Thread 17 (Thread 0×45968940 (LWP 27194)):
#0 0x000000377560d4c4 in __lll_lock_wait () from /lib64/libpthread.so.0
#1 0x0000003775608e1a in _L_lock_1034 () from /lib64/libpthread.so.0
#2 0x0000003775608cdc in pthread_mutex_lock () from /lib64/libpthread.so.0
#3 0x000000000056863f in THD::awake(THD::killed_state) ()
#4 0x000000000066f8a3 in kill_zombie_dump_threads(unsigned int) ()
#5 0x0000000000592a6e in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
#6 0x000000000059374b in handle_one_connection ()
#7 0x000000377560673d in start_thread () from /lib64/libpthread.so.0
#8 0x0000003774ad3d1d in clone () from /lib64/libc.so.6

The current_mutex deserves a bit of explanation here. In MySQL when a thread wants to wait on a condition it copies the mutex and condition into mysys_var->current_mutex and mysys_var->current_cond. The mysys_var->mutex is the mutex that protects the mysys_var struct. This way if any other thread needs to kill it it knows the condition and mutex it is waiting on so it can be woken up. This is an easy mechanism to kill threads but it makes it more difficult to figure out what a thread is locking on. In this case I think current_mutex is bl->LOCK_log from thread 16 which is coming up.

Thread 16 (Thread 0x45aee940 (LWP 3819)):
#0 0x000000377560d4c4 in __lll_lock_wait () from /lib64/libpthread.so.0
#1 0x00000037756101b1 in _L_cond_lock_989 () from /lib64/libpthread.so.0
#2 0x000000377561007f in __pthread_mutex_cond_lock () from /lib64/libpthread.so.0
#3 0x000000377560af84 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#4 0x00000000005f6637 in MYSQL_LOG::wait_for_update(THD*, bool) ()
#5 0x000000000067133a in mysql_binlog_send(THD*, char*, unsigned long long, unsigned short) ()
#6 0×0000000000592639 in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
#7 0x000000000059374b in handle_one_connection ()
#8 0x000000377560673d in start_thread () from /lib64/libpthread.so.0
#9 0x0000003774ad3d1d in clone () from /lib64/libc.so.6

Thread 16 is the old master thread waiting to dump a binglog. It should be killed by the new thread but isn’t.

Show processlist also loop through the list of client threads to get their id, hostname, user, state and query that they may be running. The common theme between all of these threads is that they all need to loop through the list of client threads in order to do their jobs. When looping through this list they must grab the LOCK_thread_count mutex. Owning this mutex means that no other thread will be able to change the list of client threads making it safe to loop through.

Owns
LOCK_thread_count
Tries
mysys_var->mutex probably from thread 16/17

Thread 3 (Thread 0x45a6c940 (LWP 13482)):
#0 0x000000377560d4c4 in __lll_lock_wait () from /lib64/libpthread.so.0
#1 0x0000003775608e50 in _L_lock_1233 () from /lib64/libpthread.so.0
#2 0x0000003775608dd3 in pthread_mutex_lock () from /lib64/libpthread.so.0
#3 0x000000000065879a in mysqld_list_processes(THD*, char const*, bool) ()
#4 0x000000000058ecf6 in mysql_execute_command(THD*) ()
#5 0x00000000005915f1 in mysql_parse(THD*, char const*, unsigned int, char const**) ()
#6 0x000000000059279e in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
#7 0x000000000059374b in handle_one_connection ()
#8 0x000000377560673d in start_thread () from /lib64/libpthread.so.0
#9 0x0000003774ad3d1d in clone () from /lib64/libc.so.6

I haven’t quite solved this one yet but I hope the breakdown may help someone else with the same issue. I worked around this one by disabling a script that runs show processlist and records this output. This makes it far less likely that all three conditions will be met to produce the deadlock. Other options are changing the log rotation script to only flush the logs it needs or figure out why the slave reconnect happens. I have a few theories on long running log rotations causing this but I haven’t been able to reproduce them.


PlanetMySQL Voting: Vote UP / Vote DOWN

Is group_concat_max_len in bytes or characters?

Сентябрь 5th, 2011

The manual says bytes but sometimes it is measured in characters. It seems like group_concat_max_len is in bytes when being passed through a temporary table and in characters otherwise. This works fine when using latin1 but when converting to utf8 mysql must reserve 3 bytes per character when setting types in a temporary table. This is yet another reason to dislike group_concat..

mysql> create table group_concat_bug (str1 varchar(255), str2 varchar(255), str3 varchar(255)) charset=utf8 engine=innodb;
Query OK, 0 rows affected (0.02 sec)

mysql> show create table group_concat_bug;
+——————+———————————————————————————————————————————————————————————–+
| Table | Create Table |
+——————+———————————————————————————————————————————————————————————–+
| group_concat_bug | CREATE TABLE `group_concat_bug` (
`str1` varchar(255) default NULL,
`str2` varchar(255) default NULL,
`str3` varchar(255) default NULL
) ENGINE=InnoDB DEFAULT CHARSET=utf8 |
+——————+———————————————————————————————————————————————————————————–+
1 row in set (0.00 sec)

mysql> insert into group_concat_bug set str1=’a';
Query OK, 1 row affected (0.01 sec)

mysql> insert into group_concat_bug set str1=’a';
Query OK, 1 row affected (0.00 sec)

mysql> insert into group_concat_bug set str1=’a';
Query OK, 1 row affected (0.00 sec)

mysql> insert into group_concat_bug set str1=’a';
Query OK, 1 row affected (0.00 sec)

mysql> insert into group_concat_bug set str1=’a';
Query OK, 1 row affected (0.00 sec)

mysql> insert into group_concat_bug set str1=’a';
Query OK, 1 row affected (0.00 sec)

mysql> select group_concat(str1) from group_concat_bug group by str2;
+——————–+
| group_concat(str1) |
+——————–+
| a,a,a,a,a,a |
+——————–+
1 row in set (0.00 sec)

mysql> set group_concat_max_len=5;
Query OK, 0 rows affected (0.00 sec)

mysql> explain select group_concat(str1) from group_concat_bug group by str2;
+—-+————-+——————+——+—————+——+———+——+——+—————-+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+—-+————-+——————+——+—————+——+———+——+——+—————-+
| 1 | SIMPLE | group_concat_bug | ALL | NULL | NULL | NULL | NULL | 6 | Using filesort |
+—-+————-+——————+——+—————+——+———+——+——+—————-+
1 row in set (0.00 sec)

mysql> select group_concat(str1) from group_concat_bug group by str2;
+——————–+
| group_concat(str1) |
+——————–+
| a,a,a |
+——————–+
1 row in set, 1 warning (0.00 sec)

mysql> explain select group_concat(str1) from group_concat_bug group by str2 order by str3;
+—-+————-+——————+——+—————+——+———+——+——+———————————+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+—-+————-+——————+——+—————+——+———+——+——+———————————+
| 1 | SIMPLE | group_concat_bug | ALL | NULL | NULL | NULL | NULL | 6 | Using temporary; Using filesort |
+—-+————-+——————+——+—————+——+———+——+——+———————————+
1 row in set (0.00 sec)

mysql> select group_concat(str1) from group_concat_bug group by str2 order by str3;
+——————–+
| group_concat(str1) |
+——————–+
| a |
+——————–+
1 row in set, 1 warning (0.00 sec)

mysql> show variables like ‘group_concat_max_len’;
+———————-+——-+
| Variable_name | Value |
+———————-+——-+
| group_concat_max_len | 5 |
+———————-+——-+
1 row in set (0.00 sec)

I tried to patch item_sum.cc dump_leaf_key() to include the max character length in bytes in the string max length calculation with:

- if (result->length() > item->max_length)
+ if ((result->length() * item->collation.collation->mbmaxlen) > item->max_length)

This didn’t work out as I planned. Repeat runs of queries return different results.

mysql> set group_concat_max_len=5; select group_concat(str1 separator ”) from group_concat_bug group by str2;
Query OK, 0 rows affected (0.00 sec)

+———————————+
| group_concat(str1 separator ”) |
+———————————+
| aa |
+———————————+
1 row in set, 1 warning (0.00 sec)

mysql> set group_concat_max_len=5; select group_concat(str1 separator ”) from group_concat_bug group by str2;
Query OK, 0 rows affected (0.00 sec)

+———————————+
| group_concat(str1 separator ”) |
+———————————+
| aau |
+———————————+
1 row in set, 1 warning (0.00 sec)

At this point I stopped investigating the problem because the application that was using group_concat was just parsing the result back into an array anyway. The developers agreed it was best to just get rid of the group_concat and issue two queries. This is what I recommend for fixing group_concat. The risk of having truncated values or running out of memory is too much to justify saving the cost of issuing a second query.


PlanetMySQL Voting: Vote UP / Vote DOWN

The #mysql drinking game

Август 13th, 2011

These are the rules of the Freenode #mysql drinking game.

  1. Any non op posts a pastebin link either either the query and no error or the error and no query drink
  2. Any non op posts a query with, “why doesn’t this work?” without any explanation about the results they want or what their getting drink
  3. Domas trolls the channel with a legit issue drink
  4. When a postgres guy answers a question about sqlite in #mysql 3 drinks
  5. Someone answers a question with, “kill yourself” drink
  6. Someone asks a phpmyadmin question
  7. Someone asks a workbench question
  8. Someone can’t figure out how to reset the root password
  9. Someone says they are getting an access denied error but they insist the username and password are correct.
  10. Somone asks a mssql question but tries to disguise it as a mysql question because there is no mssql channel.

Special set of rules for Alexander Keremidarski (salle)

  1. Just drink.

 


PlanetMySQL Voting: Vote UP / Vote DOWN

Second update of modifying table statistics in MariaDB

Июль 28th, 2011

Since my last post I’ve changed how the table statistics work quite a bit in MariaDB. I ran into a few problems with my original changes. In the TiVo 5.0 patch the show table_statistics command chose from one of three hash tables to read from depending on the flags. There is a global hash table for global stats and two in the thd object for session and query stats. Each time a non show query is executed the query statistics are reset. In 5.1 the implementation of show command changed from reading arbitrary data structures to constructing queries to run against information_schema tables. The information_schema tables are constructed on the fly, placed into a temporary table and have the select resulting from the show command executed on them. This works ok for the show commands but broke my new information schema tables.

As part of porting my changes into mariadb 5.2 I added a few new information schema tables called QUERY_TABLE_STATISTICS, QUERY_INDEX_STATISTICS, SESSION_TABLE_STATISTICS, and SESSION_INDEX_STATISTICS. For the part these tables query the hash tables from the 5.0 implementation. This worked fine for the show commands in my previous update. It broke when querying the QUERY_TABLE_STATISTICS directly. In 5.0 I reset the per query table statistics on every query that isn’t a SHOW query. This works fine except that SELECT * FROM QUERY_TABLE_STATISTICS reset the query statistics that the select query was supposed to retrieve.

After a conversation with serg in #mariadb on freenode we came up with a plan to fix the QUERY_TABLE_STATISTICS and QUERY_INDEX_STATISTICS tables. Instead of tracking the most recent query the plan is to track the most recent N queries tracked with a QUERY_ID. I realized this is very similar to how SHOW PROFILES worked. I decided to try to integrate the query statistics in with the profile. This seemed like a good idea until I realized that I want to enable the slow query log statistics without the overhead of leaving profiling on in production.

All of the profiling methods are controlled by the profiling variable. All of the table, index, and user statistics are controlled by the userstat variable. The profiling and my changes to the table statistics both use a QUERY_ID to show a list of queries. The problem is that depending on when the profiling and userstat variables are enabled the query_ids can be inconsistent. For example if a user enables userstat, executes a query, then enables profiling and executes another query the table statistics query_id 1 and the profiling query_id 1 will be different.

Every show command that uses a information schema table puts rows into a temporary table. I’ve also added temporary table tracking into the table statistics. This has an interesting side effect when combined with per query statistics tracking. Queries are only put into the queue of queries for query statistics when they read/write rows. The query_statistics_history_size controls how many queries to keep stats for. Each show command now uses a temporary table so the show commands are now tracked using row statistics. Here is an example using show variables.

mysql> set query_statistics_history_size=5;
Query OK, 0 rows affected (0.00 sec)

mysql> show variables;
+——————————————-+—————————————————————————————————————-+
| Variable_name | Value |
+——————————————-+—————————————————————————————————————-+
| aria_block_size | 8192
………
| warning_count | 0 |
+——————————————-+—————————————————————————————————————-+
395 rows in set (0.00 sec)

mysql> show query table_statistics;
+———-+————–+————+———–+————–+————————-+
| Query_id | Table_schema | Table_name | Rows_read | Rows_changed | Rows_changed_x_#indexes |
+———-+————–+————+———–+————–+————————-+
| 8 | #temp# | #temp# | 395 | 395 | 395 |
+———-+————–+————+———–+————–+————————-+
1 row in set (0.00 sec)

mysql> show query table_statistics;
+———-+————–+————+———–+————–+————————-+
| Query_id | Table_schema | Table_name | Rows_read | Rows_changed | Rows_changed_x_#indexes |
+———-+————–+————+———–+————–+————————-+
| 8 | #temp# | #temp# | 395 | 395 | 395 |
| 9 | #temp# | #temp# | 1 | 1 | 1 |
+———-+————–+————+———–+————–+————————-+
2 rows in set (0.00 sec)

mysql> show query table_statistics;
+———-+————–+————+———–+————–+————————-+
| Query_id | Table_schema | Table_name | Rows_read | Rows_changed | Rows_changed_x_#indexes |
+———-+————–+————+———–+————–+————————-+
| 8 | #temp# | #temp# | 395 | 395 | 395 |
| 9 | #temp# | #temp# | 1 | 1 | 1 |
| 10 | #temp# | #temp# | 2 | 2 | 2 |
+———-+————–+————+———–+————–+————————-+
3 rows in set (0.00 sec)

See how each new show command adds in another query into the queue of tracked queries? While technically correct I don’t think this is ideal. I’m open to suggestions on how to keep the temp table tracking useful while not polluting the list of queries with unnecessary results.

I went back to #mariadb again and we came up with a single unified query_id per thread that both show profiles and the table statistics can use. This unifies the query ids with the down side that a lot of ids can be wasted. Doing set profiling=1, executing a query, and running show profiles isn’t guaranteed to use query_id 1 like it did before. This is where I’m looking to the community to decide how to handle the two different commands and query ids.

The main reason for tracking the per query statistics is to dump them to the slow query log. If userstat is enabled and a query is written to the slow query log it will include two new comments that look like:

# Time: 110712 13:12:16
# User@Host: [ebergen] @ localhost []
# Thread_id: 1 Schema: test QC_hit: No
# Query_time: 64.666276 Lock_time: 0.000113 Rows_sent: 10 Rows_examined: 719488
# Row_Stats: test:rows_read=677984,rows_changed=0,rows_changed_x_indexes=0;#temp#:rows_read=41504,rows_changed=41494,rows_changed_x_indexes=41494;
# Index_Stats:
SET timestamp=1310501536;
select * from t2 group by u order by u desc limit 10;

Things that are missing or wrong so far. The first thing is that I don’t have a query similar to show profiles for queries with their ids. I don’t want to duplicate show profiles for statistics. I’m open to suggestion on how to unify the profiling and table statistics. Some of the structures for profiling and query stats are similar. I think they can be unified but this is more work than I want to put into the tivo branch. If mariadb is willing to accept this kind of feature I can work on unifying them.

Here is an example of where I’m stuck with show profiles vs show query statistics.

mysql> use test;
Database changed
mysql> set query_statistics_history_size=5;
Query OK, 0 rows affected (0.00 sec)

mysql> set profiling=1;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from t limit 5;
+——-+——–+
| t | u |
+——-+——–+
| 14515 | 282874 |
| 14521 | 258653 |
| 14573 | 113276 |
| 14577 | 826475 |
| 14585 | 444645 |
+——-+——–+
5 rows in set (0.00 sec)

mysql> show profiles;
+———-+————+————————-+
| Query_ID | Duration | Query |
+———-+————+————————-+
| 7 | 0.00052300 | select * from t limit 5 |
+———-+————+————————-+
1 row in set (0.00 sec)

mysql> set profiling=0;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from t limit 10;
+——-+——–+
| t | u |
+——-+——–+
| 14515 | 282874 |
| 14521 | 258653 |
| 14573 | 113276 |
| 14577 | 826475 |
| 14585 | 444645 |
| 14612 | 792545 |
| 14626 | 483300 |
| 14842 | 447267 |
| 15325 | 38865 |
| 15340 | 744424 |
+——-+——–+
10 rows in set (0.00 sec)

mysql> show query table_statistics;
+———-+————–+————+———–+————–+————————-+
| Query_id | Table_schema | Table_name | Rows_read | Rows_changed | Rows_changed_x_#indexes |
+———-+————–+————+———–+————–+————————-+
| 2 | #temp# | #temp# | 15 | 15 | 15 |
| 7 | test | t | 5 | 0 | 0 |
| 10 | test | t | 10 | 0 | 0 |
+———-+————–+————+———–+————–+————————-+
3 rows in set (0.00 sec)

mysql> show profiles;
+———-+————+————————-+
| Query_ID | Duration | Query |
+———-+————+————————-+
| 7 | 0.00052300 | select * from t limit 5 |
+———-+————+————————-+
1 row in set (0.00 sec)

Notice how show query table_statistics has three queries. Query id 2 is actually the first show command. With profiling enabled or disabled show profiles doesn’t have as many queries as show table_statistics does.


PlanetMySQL Voting: Vote UP / Vote DOWN

Second draft of the per session row and index stats patch

Декабрь 24th, 2010

I’ve taken the part of the tivo patch that includes table and index statistics and broken it out into it’s own patch. This patch includes the ability to do show [session | global ] table_statistics and the same for index_statistics. In this version the row stats are also logged in the slow query log. To log per query stats I had to track them separately from the per session stats. Because the tracking was already done for the slow query log I’ve modified the command to allow uses to access row stats for the previous query separate from the sum for the current session. The flush commands also act similarly.

Along with changing the slow query log format I’ve also change it to log the timestamp with every query. This made it easier to do automated parsing of the slow query log.

The queries now support three different modes. I’ve detailed how the show commands work in a previous post. This patch has helped developers diagnose numerous query problems that weren’t obvious by the row estimates in the explain output. I highly recommend it for users who run more complicated queries in mysql and have been having a hard time diagnosing why they are slow. This has proved particularly adept at finding misbehaving sub queries and bad join optimization which doesn’t show up in explain output. As I find example queries I will try to post them here.

The patch.


PlanetMySQL Voting: Vote UP / Vote DOWN

max_allowed_packet replication and global variables

Ноябрь 9th, 2010

The max_allowed_packet variable is used to control the maximum size of a query sent to MySQL. It’s function is fairly well defined in the manual but there is a significant gotcha that exists when changing the size of max_allowed_packet while using replication.

When the replication threads are created the global max_allowed_packet value is copied in to the thread context like doing a set session command in the slave connection. This is done because replication enforces max_allowed_packet a bit differently than other threads. It accounts for both the size of the packet and the overhead of the replication header. This makes the max_allowed_packet enforcement accurate in replication but it means that the slave thread won’t account for set global max_allowed_packet=N until replication is restarted. It should be possible to do the same calculation while checking incoming packets but I haven’t looked into making a patch.

I think this has flown under the radar because as soon as the slave hits a query that is larger than max_allowed_packet the i/o thread dies. For example when increasing the max_allowed_packet on a master and slave without restarting replication then running a query larger than the old max_allowed_packet but smaller than the new size and replication will break on the slave. When the operator runs slave start the slave i/o thread will pick up the new global max_allowed_packet and die with:

Last_Error: Could not parse relay log event entry. The possible reasons are: the master’s binary log is corrupted (you can check this by running ‘mysqlbinlog’ on the binary log), the slave’s relay log is corrupted (you can check this by running ‘mysqlbinlog’ on the relay log), a network problem, or a bug in the master’s or slave’s MySQL code. If you want to check the master’s binary log or slave’s relay log, you will be able to know their names by issuing ‘SHOW SLAVE STATUS’ on this slave.

This really only means that the relay log was corrupted. The fix for a corrupted relay log is to do slave stop then a change master to back to the same Exec_master_log_pos and Relay_Master_Log_File from show slave status. Only these two fields need to be specified. The username, password, and host will be reused from the old connection. This will delete the old binary log and download a new one. The new slave threads will have the new max_allowed_packet and everything will move along.

I think there are two things to consider here. First is that mysql can behave in unexpected ways when setting global variables. The other is that it’s important to restart replication when increasing max_allowed_packet on a slave. I haven’t looked into writing a patch for this because it’s so easy to work around by remembering to restart replication.


PlanetMySQL Voting: Vote UP / Vote DOWN

How to be a MySQL DBA and the best MySQL book on the planet.

Июль 20th, 2010

Recently there was a thread on the mysql mailing list discussing how to become a MySQL DBA. I’m not sure the MySQL DBA role exists in the same capacity that it does in Oracle. Historically the Oracle’s DBAs that I’ve met are focused purely on Oracle. They focus on maintaining Oracle based systems including managing migrations, upgrades, table space sizes and other tasks. MySQL DBAs tend to be filed in to two different buckets, people that work like developers and help with query optimization and people that work like sys admins and are focused on the operation of MySQL. There are very few people who can fill both roles and I think that’s why there are so many MySQL DBA jobs on the market. Companies are looking for one DBA when they should really be looking for two.

Jeremy’s post on how to hire a MySQL DBA is still true today. These people still don’t exist. I’ve noticed there are two groups of people with part of the skills needed to be a MySQL DBA. Good Oracle DBAs tend to be very well versed in SQL and query optimization. They’re good at working with developers to write queries that will play nice with the database. They have brains that think in sets of data and can handle complex query logic. The downside is that they have only been exposed to Oracle which includes everything and have a hard time with the LAMP world where systems must be built out of a lot of separate components.

Sys admins on the other hand are used to managing daemons, working with rsync, linux, and shells. They can handle software deployment, monitoring, and understand system performance from the operating system level. They understand the basics of configuration and quite a few of them can handle simple MySQL tasks such as installation and basic replication configuration. They tend to not have very much experience in query optimization or the specifics of how applications interact with databases. I’ve long held the opinion that MySQL should just be another component in the system and doesn’t need specialized and isolated monitoring solutions which makes it easier for a group of sys admins for it to monitor along side apache and other daemons. To turn a sys admin in to a DBA they need to understand the special requirements MySQL has such as i/o latency and atomicity of backups. Good sys admins can pick up these skills quickly.

This brings me to the best MySQL book on the planet, High Performance MySQL Second Edition. Why is it the best? Because it applies to both types of DBAs and can help them develop the skills they need to become a super DBA that can handle both the sys admin tasks and the query optimization tasks. The book has been out for roughly two years and is still very relevant. I recommend it to everyone that asks me where they can go to learn how to be a MySQL DBA and it’s never disappointed. A quick note on books. Don’t loan out your copy, ask the person you recommend it to to buy a copy. It helps the writers and this book should be on the desk of anyone working with MySQL.


PlanetMySQL Voting: Vote UP / Vote DOWN