Percona Server moved to https://jira.percona.com/projects/PS

Server crashed with query_cache_strip_comments enabled

Bug #1252610 reported by monty solomon
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
New
Undecided
Unassigned

Bug Description

Server version: 5.1.71-rel14.9-log Percona Server (GPL), 14.9, Revision 589

The slave crashed with the following entry in the error log

*** glibc detected *** /usr/sbin/mysqld: double free or corruption (!prev): 0x00007f99bcd5da20 ***

Revision history for this message
monty solomon (monty+launchpad) wrote :
Download full text (94.1 KiB)

Server version: 5.1.71-rel14.9-log Percona Server (GPL), 14.9, Revision 589

The slave crashed with the following entries in the error log

*** glibc detected *** /usr/sbin/mysqld: double free or corruption (!prev): 0x00007f99bcd5da20 ***
======= Backtrace: =========
/lib64/libc.so.6(+0x76126)[0x7fa62ab09126]
/lib64/libc.so.6(+0x78c53)[0x7fa62ab0bc53]
/usr/sbin/mysqld(_ZN18QueryStripComments7cleanupEv+0x19)[0x6b7a59]
/usr/sbin/mysqld(_ZN18QueryStripComments3setEPKcjj+0x218)[0x6b8218]
/usr/sbin/mysqld(_ZN25QueryStripComments_BackupC1EP3THDP18QueryStripComments+0x67)[0x6ba357]
/usr/sbin/mysqld(_ZN11Query_cache11store_queryEP3THDP10TABLE_LIST+0x221)[0x6bb1a1]
/usr/sbin/mysqld[0x5ab74f]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x4a3)[0x5ac7f3]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjPPKc+0x4fb)[0x5b1f3b]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1066)[0x5b43c6]
/usr/sbin/mysqld(_Z10do_commandP3THD+0x126)[0x5b4be6]
/usr/sbin/mysqld(handle_one_connection+0x325)[0x5a7b25]
/lib64/libpthread.so.0(+0x7851)[0x7fa62bf02851]
/lib64/libc.so.6(clone+0x6d)[0x7fa62ab7b94d]
======= Memory map: ========
00400000-00b32000 r-xp 00000000 ca:01 155195 /usr/sbin/mysqld
00d32000-00d9c000 rw-p 00732000 ca:01 155195 /usr/sbin/mysqld
00d9c000-00db6000 rw-p 00000000 00:00 0
026cc000-4c4f7000 rw-p 00000000 00:00 0 [heap]
7f9934000000-7f9936be1000 rw-p 00000000 00:00 0
7f9936be1000-7f9938000000 ---p 00000000 00:00 0
7f993a172000-7f993a173000 ---p 00000000 00:00 0
7f993a173000-7f993a1a3000 rw-p 00000000 00:00 0
7f993a2c9000-7f993a2ca000 ---p 00000000 00:00 0
7f993a2ca000-7f993a2fa000 rw-p 00000000 00:00 0
7f993a4b3000-7f993a4b4000 ---p 00000000 00:00 0
7f993a4b4000-7f993a4e4000 rw-p 00000000 00:00 0
7f993a8b8000-7f993a8b9000 ---p 00000000 00:00 0
7f993a8b9000-7f993a8e9000 rw-p 00000000 00:00 0
7f993bd33000-7f993bd34000 ---p 00000000 00:00 0
7f993bd34000-7f993bd64000 rw-p 00000000 00:00 0
7f993bf7f000-7f993bf80000 ---p 00000000 00:00 0
7f993bf80000-7f993bfb0000 rw-p 00000000 00:00 0
7f993c632000-7f993c633000 ---p 00000000 00:00 0
7f993c633000-7f993c663000 rw-p 00000000 00:00 0
7f993c663000-7f993c664000 ---p 00000000 00:00 0
7f993c664000-7f993c694000 rw-p 00000000 00:00 0
7f993c694000-7f993c695000 ---p 00000000 00:00 0
7f993c695000-7f993c6c5000 rw-p 00000000 00:00 0
7f993c6c5000-7f993c6c6000 ---p 00000000 00:00 0
7f993c6c6000-7f993c6f6000 rw-p 00000000 00:00 0
7f993c6f6000-7f993c6f7000 ---p 00000000 00:00 0
7f993c6f7000-7f993c727000 rw-p 00000000 00:00 0
7f993c758000-7f993c759000 ---p 00000000 00:00 0
7f993c759000-7f993c789000 rw-p 00000000 00:00 0
7f993c789000-7f993c78a000 ---p 00000000 00:00 0
7f993c78a000-7f993c7ba000 rw-p 00000000 00:00 0
7f993c7ba000-7f993c7bb000 ---p 00000000 00:00 0
7f993c7bb000-7f993c7eb000 rw-p 00000000 00:00 0
7f993c7eb000-7f993c7ec000 ---p 00000000 00:00 0
7f993c7ec000-7f993c81c000 rw-p 00000000 00:00 0
7f993c84d000-7f993c84e000 ---p 00000000 00:00 0
7f993c84e000-7f993c87e000 rw-p 00000000 00:00 0
7f993c87e000-7f993c87f000 ---p 00000000 00:00 0
7f993c87f000-7f993c8af000 rw-p 00000000 00:00 ...

monty solomon (monty+launchpad)
summary: - Server crashed - double free or corruption
+ Server crashed with query_cache_strip_comments enabled
Revision history for this message
Valerii Kravchuk (valerii-kravchuk) wrote :

I do not see the text of the statement in the error log part uploaded. Can you try to identify (from the general query log maybe, or application level logs) what exact query led to this crash?

Changed in percona-server:
status: New → Incomplete
Revision history for this message
monty solomon (monty+launchpad) wrote :

The general log was not enabled. I will take a look at the binary log.

It may not be related to a specific query. It appears that the query cache may have filled up just before the crash.

query_cache_limit = 4M
query_cache_size = 64M
query_cache_type = 1

Revision history for this message
monty solomon (monty+launchpad) wrote :

This happened on a slave. The binary log was not enabled.

The master and the other slave did not crash.

Revision history for this message
Valerii Kravchuk (valerii-kravchuk) wrote :

OK, so no way to find out what the query was from this slave. But maybe you can check the content of the logs on other slave and master for the same time (assuming your slaves are not lagging) for something suspicious, query with a comment.

As for the query cache, can you share the typical output of:

show global status like 'qcache%';

from this and other slave? I also wonder if both crashing and non-crashing slaves are configured with the same settings.

Revision history for this message
monty solomon (monty+launchpad) wrote :

The slaves are configured the same with the same settings but the slave that crashed was executing many more SELECTs than the other slave.

All the slave traffic has been routed to the other slave for now.

Is it possible that the crash is not due to a specific query but due to how the query cache is managed when query_cache_strip_comments is enabled. Due to some sort of boundary/edge condition or thread memory corruption?

Is it possible that the fix for bug 856404 is suitable for version 5.1?

Revision history for this message
monty solomon (monty+launchpad) wrote :

master

mysql> show global status like 'qcache%';
+-------------------------+------------+
| Variable_name | Value |
 +-------------------------+------------+
| Qcache_free_blocks | 15 |
| Qcache_free_memory | 63965064 |
| Qcache_hits | 1103410716 |
| Qcache_inserts | 261936089 |
| Qcache_lowmem_prunes | 35153891 |
| Qcache_not_cached | 273479539 |
| Qcache_queries_in_cache | 235 |
| Qcache_total_blocks | 540 |
 +-------------------------+------------+
8 rows in set (0.00 sec)

mysql> show global variables like "query%";
+--------------------------------+----------+
| Variable_name | Value |
 +--------------------------------+----------+
| query_alloc_block_size | 8192 |
| query_cache_limit | 4194304 |
| query_cache_min_res_unit | 4096 |
| query_cache_size | 67108864 |
| query_cache_strip_comments | OFF |
| query_cache_type | ON |
| query_cache_wlock_invalidate | OFF |
| query_prealloc_size | 8192 |
| query_response_time_range_base | 10 |
 +--------------------------------+----------+
9 rows in set (0.00 sec)

Revision history for this message
monty solomon (monty+launchpad) wrote :

Current slave

mysql> show global status like 'qcache%';
+-------------------------+----------+
| Variable_name | Value |
 +-------------------------+----------+
| Qcache_free_blocks | 5727 |
| Qcache_free_memory | 45597344 |
| Qcache_hits | 25765726 |
| Qcache_inserts | 7886671 |
| Qcache_lowmem_prunes | 215270 |
| Qcache_not_cached | 17840185 |
| Qcache_queries_in_cache | 15294 |
| Qcache_total_blocks | 36521 |
 +-------------------------+----------+
8 rows in set (0.00 sec)

mysql> show global variables like "query%";
+--------------------------------+----------+
| Variable_name | Value |
 +--------------------------------+----------+
| query_alloc_block_size | 8192 |
| query_cache_limit | 4194304 |
| query_cache_min_res_unit | 4096 |
| query_cache_size | 67108864 |
| query_cache_strip_comments | OFF |
| query_cache_type | ON |
| query_cache_wlock_invalidate | OFF |
| query_prealloc_size | 8192 |
| query_response_time_range_base | 10 |
 +--------------------------------+----------+
9 rows in set (0.00 sec)

Revision history for this message
monty solomon (monty+launchpad) wrote :

Other slave (the one that crashed and is now idle)

mysql> show global status like 'qcache%';
+-------------------------+----------+
| Variable_name | Value |
 +-------------------------+----------+
| Qcache_free_blocks | 1 |
| Qcache_free_memory | 67091112 |
| Qcache_hits | 0 |
| Qcache_inserts | 568 |
| Qcache_lowmem_prunes | 0 |
| Qcache_not_cached | 6191 |
| Qcache_queries_in_cache | 0 |
| Qcache_total_blocks | 1 |
 +-------------------------+----------+
8 rows in set (0.00 sec)

mysql> show global variables like "query%";
+--------------------------------+----------+
| Variable_name | Value |
 +--------------------------------+----------+
| query_alloc_block_size | 8192 |
| query_cache_limit | 4194304 |
| query_cache_min_res_unit | 4096 |
| query_cache_size | 67108864 |
| query_cache_strip_comments | OFF |
| query_cache_type | ON |
| query_cache_wlock_invalidate | OFF |
| query_prealloc_size | 8192 |
| query_response_time_range_base | 10 |
 +--------------------------------+----------+
9 rows in set (0.00 sec)

Valerii Kravchuk (valerii-kravchuk)
Changed in percona-server:
status: Incomplete → New
Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

Monty -

Indeed not all the 5.5 query_cache_strip_comments fixes are present in 5.1. But, just to confirm, all the "show global variables like "query%"" outputs above have query_cache_strip_comments off. Have you disabled them on the crashed slave after the crash or were they not turned on during the crash in the first place?

Revision history for this message
monty solomon (monty+launchpad) wrote :

I turned off query_cache_strip_comments on the servers after the crash to prevent another one.

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

The query_cache_strip_comments fix that is present in 5.5 but not 5.1 is https://code.launchpad.net/~akopytov/percona-server/bug915814-5.5 revision 228, to fix bug 856404. Since now bug 856404 is closed as a duplicate of bug 705688, I'm targetting the latter for 5.1 and closing this one as its duplicate. If, after the fix is backported, the issue still resurfaces, let's reopen this one then.

Thanks.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.