| Bug #30056 | replicate-rewrite-db causing slave to crash | ||
|---|---|---|---|
| Submitted: | 25 Jul 2007 21:19 | Modified: | 1 Dec 2008 10:22 |
| Reporter: | Elan Ruusamäe (OCA) | Email Updates: | |
| Status: | Can't repeat | Impact on me: | |
| Category: | MySQL Server: Replication | Severity: | S3 (Non-critical) |
| Version: | 5.0.37, 5.0.45, 5.1.26 | OS: | Linux (PLD Linux) |
| Assigned to: | CPU Architecture: | Any | |
| Tags: | replication crash replicate rewrite-db | ||
[26 Jul 2007 8:56]
Elan Ruusamäe
the problem started to appear when our master server was upgraded from 4.1.x to 5.0.45. i have similar replication running with the one that is crashing, and only difference i see is that crashing slaves do: replicate-rewrite-db=db1->db2 replicate-do-table=db2.comments replicate-do-table=db2.commentCounts replicate-do-table=db2.articles ... i've noticed that some times it crashes when query string is insert into `table`, where the `table` is not list of replicate-do-table list.
[26 Jul 2007 10:36]
Elan Ruusamäe
after making such changes that i don't use replicate-rewrite-db, the server no longer crashes. mysqld.conf diff: -replicate-rewrite-db=db1->db2 -replicate-do-table=db2.comments -replicate-do-table=db2.commentCounts -replicate-do-table=db2.articles -replicate-do-table=db2.articleXCategory -replicate-do-table=db2.newsCategories -replicate-do-table=db2.ratings +;replicate-rewrite-db=db1->db2 +replicate-do-table=db1.comments +replicate-do-table=db1.commentCounts +replicate-do-table=db1.articles +replicate-do-table=db1.articleXCategory +replicate-do-table=db1.newsCategories +replicate-do-table=db1.ratings
[26 Jul 2007 20:25]
MySQL Verification Team
Thank you for the bug report. Are you able to provide a test case which will allow to repeat the slave crash (my.cnf slave/master and tables, queries statements)?. Thanks in advance.
[26 Aug 2007 23:00]
Bugs System
No feedback was provided for this bug for over a month, so it is being suspended automatically. If you are able to provide the information that was originally requested, please do so and change the status of the bug back to "Open".
[14 Dec 2007 15:22]
Sergey Kostyliov
I believe I've just hit the same bug. In my case MySQL version is 5.0.51 MySQL slave uses `replicate-rewrite-db' constantly segfaults (compiled without any debug options) and produces: Error: Memory allocated at log_event.cc:1532 was overrun, discovered at 'my_alloc.c:357' Error: Memory allocated at log_event.cc:1532 was overrun, discovered at 'my_alloc.c:201' Error: Memory allocated at log_event.cc:1532 was overrun, discovered at 'sql_lex.cc:215' Error: Memory allocated at log_event.cc:1532 was overrun, discovered at 'sql_lex.cc:216' Error: Memory allocated at log_event.cc:1532 was overrun, discovered at 'sql_class.h:1788' Error: Memory allocated at log_event.cc:1532 was overrun, discovered at 'log_event.h:828' Error: Memory allocated at log_event.cc:1532 was overrun, discovered at 'my_alloc.c:357' Error: Memory allocated at log_event.cc:1532 was overrun, discovered at 'my_alloc.c:201' Error: Memory allocated at log_event.cc:1532 was overrun, discovered at 'sql_lex.cc:215' Error: Memory allocated at log_event.cc:1532 was overrun, discovered at 'sql_lex.cc:216' Error: Memory allocated at log_event.cc:1532 was overrun, discovered at 'sql_class.h:1788' Error: Memory allocated at log_event.cc:1532 was overrun, discovered at 'log_event.h:828' Error: Memory allocated at log_event.cc:1532 was overrun, discovered at 'my_alloc.c:357' Error: Memory allocated at log_event.cc:1532 was overrun, discovered at 'my_alloc.c:201' Error: Memory allocated at log_event.cc:1532 was overrun, discovered at 'sql_lex.cc:215' Error: Memory allocated at log_event.cc:1532 was overrun, discovered at 'sql_lex.cc:216' Error: Memory allocated at log_event.cc:1532 was overrun, discovered at 'sql_class.h:1788' Error: Memory allocated at log_event.cc:1532 was overrun, discovered at 'log_event.h:828' compiled with `--debug=full' Unfortunately, initial master logs from where suspected query(queries)come have been already removed. So currently I have only relay logs which lead to a memory overrun. But it seems that bug by itself is unrelated to any actually executed sql queries. In my case steps to reproduce was next: 1) copy relay log file, relay info file, relay index file and master.info file to a test server. 2) add next 3 lines of replication options to my.cnf: "replicate-rewrite-db = mb->mb_ro replicate-do-db = mb_ro replicate-do-table = mb_ro.table_that_doesnt_exist" 3) mysql> START SLAVE SQL_THREAD; 4) See nice "Error: Memory allocated at log_event.cc:1532" in error logs. table_that_doesnt_exist is just table that doesn't really exist so actually sql slave thread executes nothing. A can provide any files (i.e.: relay log file, relay info file, relay index file and master.info). Fill free to say me if you need them.
[24 Jan 2008 12:10]
Sergey Kostyliov
The bug seems to be still here in today bk (i.e. mysql-5.0.56-pre as of 20080124). Below is the same error pattern I've just extracted from my error log. *** glibc detected *** /usr/sbin/mysqld: free(): invalid pointer: 0x00002aabadad8b30 *** ======= Backtrace: ========= /lib/libc.so.6[0x2b8200e6caad] /lib/libc.so.6(cfree+0x76)[0x2b8200e6e796] /usr/sbin/mysqld(_ZN15Query_log_event10exec_eventEP17st_relay_log_infoPKcj+0x164)[0x63ad14] /usr/sbin/mysqld(handle_slave_sql+0x5c9)[0x6cba59] /lib/libpthread.so.0[0x2b820051d047] /lib/libc.so.6(clone+0x6d)[0x2b8200ec025d] ...
[18 Aug 2008 8:15]
Sveta Smirnova
Sergey, thank you for the feedback. Please try with current version 5.0.67 and if problem still exists provide full error log file, output of SHOW SLAVE STATUS and related replication files (relay log file, relay info file, relay index file, one of relay logs and master.info).
[18 Sep 2008 23:00]
Bugs System
No feedback was provided for this bug for over a month, so it is being suspended automatically. If you are able to provide the information that was originally requested, please do so and change the status of the bug back to "Open".
[6 Oct 2008 19:48]
Brian Moon
Error log with 5.0.60
Attachment: mbug.txt (text/plain), 11.58 KiB.
[19 Nov 2008 13:37]
Sergey Kostyliov
Hello Sveta Smirnova and others, The bug is still there for mysql 5.1.26. We've just triggered it again. Do you need the files you mentioned from mysql 5.1.26?
[19 Nov 2008 14:09]
Sergey Kostyliov
In any case all file are in the link below: http://sysadminday.org.ru/bug30056.tar.gz rathamahata@static ~ $ tar -tzvf bug30056.tar.gz drwxr-xr-x mysql/mysql 0 2008-11-19 16:58 bug30056/ -rw-r----- mysql/mysql 546 2008-11-19 16:55 bug30056/cutter-relay-bin.index -rw-r----- mysql/mysql 75 2008-11-19 16:55 bug30056/cutter-relay-log.info -rw-r----- mysql/mysql 1074390024 2008-11-19 16:44 bug30056/cutter-relay-bin.000281 -rw-r--r-- mysql/mysql 3964 2008-11-19 16:53 bug30056/show_slave_status -rw-r----- mysql/mysql 69 2008-11-19 16:58 bug30056/master.info rathamahata@static ~ $ mysql> SHOW SLAVE STATUS\G *************************** 1. row *************************** Slave_IO_State: Master_Host: 127.0.0.1 Master_User: replication Master_Port: 3308 Connect_Retry: 60 Master_Log_File: binlog.002888 Read_Master_Log_Pos: 492488174 Relay_Log_File: cutter-relay-bin.000281 Relay_Log_Pos: 617956159 Relay_Master_Log_File: binlog.002885 Slave_IO_Running: No Slave_SQL_Running: No Replicate_Do_DB: marex_bo,shop_ro,mb_ro Replicate_Ignore_DB: Replicate_Do_Table: shop_ro.person_type,shop_ro.catrelation_ext_data,shop_ro.product_isbn,shop_ro.catrelation_shops,shop_ro.ms_family,shop_ro.shop_product,mb_ro.export_models_xml2,shop_ro.catrelation,shop_ro.shop_settings_list,shop_ro.category_document,shop_ro.partner_news,shop_ro.catrelation_link_type,shop_ro.person,shop_ro.city,shop_ro.product,shop_ro.detail_date,shop_ro.product_detail_type,shop_ro.banner_template,mb_ro.export_models3,shop_ro.ms_language,shop_ro.loan,shop_ro.category,shop_ro.top_product,shop_ro.catrelation_link,shop_ro.product_detail_group,shop_ro.delivery_zone,shop_ro.product_type,shop_ro.catrelation_person,shop_ro.orderstatname,shop_ro.catrelation_type,shop_ro.manufacturer,shop_ro.detail,shop_ro.pub_banner_group,shop_ro.delivery_type,shop_ro.loan_repayment_period,shop_ro.detail_shop,shop_ro.partner_product_stake,shop_ro.ms_package,shop_ro.delivery_payment,shop_ro.discount,shop_ro.banner_category,shop_ro.product_supplier,shop_ro.detail_blob,shop_ro.firm,shop_ro.product_person,shop_ro.man_cid_title,shop_ro.tax,shop_ro.delivery_rule,shop_ro.pub_banner_group_catrelation,shop_ro.country,shop_ro.product_ext_data,shop_ro.detail_fastspvalue,shop_ro.catrelation_type_property,shop_ro.fake_random,mb_ro.object_link_type,shop_ro.ms_pool,shop_ro.partner_payment,shop_ro.moscow_street_zip,mb_ro.categories,shop_ro.directory,shop_ro._fo_optimize_cats,shop_ro.orderstatlist,shop_ro.user_account,shop_ro.man_cid,shop_ro.ms_product,shop_ro.mview_partner_stat,shop_ro.currency,shop_ro.news_txs,shop_ro.ms_part,shop_ro.holiday,shop_ro.ms_pricing,shop_ro.detail_type,shop_ro.price_range,shop_ro.players,shop_ro.couriers,shop_ro.currency_rate,shop_ro.full_search,shop_ro.partner_refhost,shop_ro.city_payment,shop_ro.prodrelation,shop_ro._product_document_type,shop_ro.metro,shop_ro.shop_setting_value,shop_ro.catrelation_ext_desc,shop_ro._product_document,shop_ro.product_ext_desc,shop_ro.new_product,shop_ro.partner_stake_shop,shop_ro.shop_settings,shop_ro.mag_product,shop_ro.zone_country,shop_ro.product_document_type,shop_ro.product_type_property,shop_ro.pub_banner,shop_ro.loan_required_data,shop_ro.account,shop_ro.product_rating,shop_ro.partner_vip_shop,shop_ro.detail_real,shop_ro.shop_group,shop_ro.detail_string,shop_ro.shop,shop_ro.product_document,shop_ro.product_ext_data_value,shop_ro.payment,shop_ro.review,shop_ro.vote,shop_ro.banner_banner,shop_ro.news_cats,shop_ro.user_account_operation,shop_ro.pub_banner_group_banner,shop_ro.product_ordered_with,shop_ro.mag,shop_ro.directory_type,mb_ro.export_objects Replicate_Ignore_Table: Replicate_Wild_Do_Table: marex_bo.% Replicate_Wild_Ignore_Table: Last_Errno: 0 Last_Error: Skip_Counter: 0 Exec_Master_Log_Pos: 617956017 Relay_Log_Space: 3715733997 Until_Condition: None Until_Log_File: Until_Log_Pos: 0 Master_SSL_Allowed: No Master_SSL_CA_File: Master_SSL_CA_Path: Master_SSL_Cert: Master_SSL_Cipher: Master_SSL_Key: Seconds_Behind_Master: NULL Master_SSL_Verify_Server_Cert: No Last_IO_Errno: 0 Last_IO_Error: Last_SQL_Errno: 0 Last_SQL_Error: 1 row in set (0.00 sec) mysql>
[19 Nov 2008 21:32]
Sveta Smirnova
Sergey, thank you for the feedback and files. We are analyzing them now.
[20 Nov 2008 13:41]
Susanne Ebrecht
Sergey, please provide my.cnf of your master and of your slave.
[20 Nov 2008 14:00]
Sergey Kostyliov
my.cnf from my slave
Attachment: my.cnf.slave (application/octet-stream, text), 10.53 KiB.
[20 Nov 2008 14:01]
Sergey Kostyliov
my.cnf from my master
Attachment: my.cnf.master (application/octet-stream, text), 4.20 KiB.
[20 Nov 2008 14:07]
Sergey Kostyliov
Btw, as I've already wrote full configs are not required to reproduce the bug on slave: "In my case steps to reproduce was next: 1) copy relay log file, relay info file, relay index file and master.info file to a test server. 2) add next 3 lines of replication options to my.cnf: "replicate-rewrite-db = mb->mb_ro replicate-do-db = mb_ro replicate-do-table = mb_ro.table_that_doesnt_exist" 3) mysql> START SLAVE SQL_THREAD;"
[28 Nov 2008 10:12]
Sveta Smirnova
Sergey, thank you for the data provided. It is hard to follow your instructions "how-to-repeat" exactly without schema. Additionally I can not repeat the problem using part of relay log and guess about table structure. So if you could provide table definitions it would be helpful. Could you also please add more information about your environment: which operating system do you run, 32 or 64 bit, how much physical RAM do you have? If I understood correctly you build MySQL yourself. Please provide configure options you used.
[1 Dec 2008 10:11]
Sergey Kostyliov
Sorry for the delay. I've tried to reproduce bug by myself with either your mysql-5.1.30-linux-x86_64-glibc23.tar.gz or our customly compiled 5.1.30 one. And I should say, that I can not reproduce this bug anymore with mysql 5.1.30.
[1 Dec 2008 10:22]
Sveta Smirnova
Thank you for the feedback. Report closed as "Can't repeat" as bug is not repeatable anymore.
Description: *** glibc detected *** free(): invalid next size (fast): 0x087fe3e8 *** [New LWP 11805] Program received signal SIGABRT, Aborted. [Switching to LWP 11805] 0xffffe410 in __kernel_vsyscall () (gdb) (gdb) (gdb) (gdb) bt #0 0xffffe410 in __kernel_vsyscall () #1 0xb7bf1f41 in raise () from /lib/tls/libc.so.6 #2 0xb7bf361d in abort () from /lib/tls/libc.so.6 #3 0xb7c2557e in __fsetlocking () from /lib/tls/libc.so.6 #4 0xb7c2f297 in mallopt () from /lib/tls/libc.so.6 #5 0xb7c2df6d in mallopt () from /lib/tls/libc.so.6 #6 0xb7c2ccbb in free () from /lib/tls/libc.so.6 #7 0x08542410 in my_no_flags_free (ptr=0x87fe3e8 "//") at my_malloc.c:59 #8 0x0823fd11 in get_form_pos (file=16, head=0xa6b29650 "Å£\001\a\t\003", save_names=0x0) at table.cc:1055 #9 0x0823d271 in openfrm (thd=0x8826ab0, name=0xa6b29c00 "./peloton/commentCounts", alias=0x882c640 "commentCounts", db_stat=8231, prgflag=44, ha_open_flags=8, outparam=0x880d4b0) at table.cc:153 #10 0x08234925 in open_unireg_entry (thd=0x8826ab0, entry=0x880d4b0, db=0x882c7f0 "peloton", name=0x882c618 "commentCounts", alias=0x882c640 "commentCounts", table_desc=0x882c650, mem_root=0xa6b2a910, flags=0) at sql_base.cc:2422 #11 0x082332b1 in open_table (thd=0x8826ab0, table_list=0x882c650, mem_root=0xa6b2a910, refresh=0xa6b2a93b, flags=0) at sql_base.cc:1887 #12 0x082353fa in open_tables (thd=0x8826ab0, start=0xa6b2abb4, counter=0xa6b2ab68, flags=0) at sql_base.cc:2731 #13 0x08280223 in mysql_update (thd=0x8826ab0, table_list=0x882c650, fields=@0x8827b0c, values=@0x8827cd8, conds=0x882ce60, order_num=0, order=0x0, limit=18446744073709551615, handle_duplicates=DUP_ERROR, ignore=false) at sql_update.cc:143 #14 0x08206644 in mysql_execute_command (thd=0x8826ab0) at sql_parse.cc:3458 #15 0x0820d502 in mysql_parse (thd=0x8826ab0, inBuf=0x88281e2 "update commentCounts set count=479, visible=479 where objectTable='articles' and objectID=16429190", length=98, found_semicolon=0xa6b2b24c) at sql_parse.cc:6097 #16 0x08297e7d in Query_log_event::exec_event (this=0x8828150, rli=0x8807934, query_arg=0x88281e2 "update commentCounts set count=479, visible=479 where objectTable='articles' and objectID=16429190", q_len_arg=98) at log_event.cc:1902 #17 0x0829790a in Query_log_event::exec_event (this=0x8828150, rli=0x8807934) at log_event.cc:1756 #18 0x0834d97c in exec_relay_log_event (thd=0x8826ab0, rli=0x8807934) at slave.cc:3338 #19 0x0834f36f in handle_slave_sql (arg=0x8806ad8) at slave.cc:3929 #20 0xb7dcfc7b in __pthread_initialize_minimal () from /lib/tls/libpthread.so.0 #21 0xb7c81bbe in clone () from /lib/tls/libc.so.6 (gdb) another output from resolve_stack_dump output (different run): 0x81e9ca8 handle_segfault + 556 0xffffe410 _end + -142444672 0xb7b716e7 _end + -1355175337 0xb7ba357e _end + -1354970898 0xb7bad297 _end + -1354930681 0xb7babe1a _end + -1354935926 0xb7baab34 _end + -1354940764 0x85422b2 my_malloc + 142 0x8542ea4 alloc_root + 417 0x81ad3d4 _Z9sql_allocj + 42 0x8146529 _ZN9Sql_allocnwEj + 17 0x827ac25 _Z12push_warningP3THDN11MYSQL_ERROR18enum_warning_levelEjPKc + 611 0x81ea980 _Z14my_message_sqljPKci + 372 0x8543f01 my_message + 33 0x8203f90 _Z21mysql_execute_commandP3THD + 568 0x820d502 _Z11mysql_parseP3THDPKcjPS2_ + 420 0x8297e7d _ZN15Query_log_event10exec_eventEP17st_relay_log_infoPKcj + 1393 0x829790a _ZN15Query_log_event10exec_eventEP17st_relay_log_info + 44 0x834d97c _Z20exec_relay_log_eventP3THDP17st_relay_log_info + 988 0x834f36f handle_slave_sql + 1673 0xb7d4dc7b _end + -1353224213 0xb7bffbbe _end + -1354592466 How to repeat: it's probably related heavily on my tables on disk and binlog coming from server.