MySQL Bugs: #42227: Test falcon.falcon_bug_28095 fails sporadically on pushbuild

Bug #42227	Test falcon.falcon_bug_28095 fails sporadically on pushbuild
Submitted:	20 Jan 2009 20:40	Modified:	7 May 2009 16:15
Reporter:	Alfranio Junior	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Falcon storage engine	Severity:	S1 (Critical)
Version:	6.0-rpl, mysql-6.0-falcon-team	OS:	Any
Assigned to:	Vladislav Vaintroub	CPU Architecture:	Any
Tags:	6.0-rpl-green, F_HANDLER, pushbuild, sporadic, test failure

Description:
falcon.falcon_bug_28095 [ fail ] Found warnings in server log file!
Test ended at 2008-12-25 00:23:46
@log_error
/dev/shm/var-falcon-110/mysqld.1/mysqld.err
log_error
==30717== at 0x4A20A56: malloc (vg_replace_malloc.c:149)
^ Found warnings!!

- saving '/dev/shm/var-falcon-110/log/falcon.falcon_bug_28095/' to
'/dev/shm/var-falcon-110/log/falcon.falcon_bug_28095/'

Retrying test, attempt(2/3)...

How to repeat:
https://intranet.mysql.com/secure/pushbuild/showpush.pl?dir=bzr_mysql-6.0-rpl&order=138 

platform  [pb-valgrind]
test type [falcon]

http://tinyurl.com/8qd3vn 

Suggested fix:
Most likely this bug will be fixed by the patch provided in http://bugs.mysql.com/bug.php?id=41653.

This seems to be a Falcon related bug. Repeatable with --valgrind

./mysql-test-run.pl --force --skip-ndb --suite=falcon --valgrind falcon_bug_28095

============================================================

TEST                                      RESULT   TIME (ms)
------------------------------------------------------------

falcon.falcon_bug_28095                  [ fail ]  Found warnings/errors in server log file!
        Test ended at 2009-02-04 16:00:19

hakan@lu0011:~/work/mysql/mysql-6.0-falcon-team/mysql-test/var/log/falcon.falcon_bug_28095/mysqld.1$ more mysqld.err
CURRENT_TEST: falcon.falcon_bug_28095
==24791== Memcheck, a memory error detector.
==24791== Copyright (C) 2002-2007, and GNU GPL'd, by Julian Seward et al.
==24791== Using LibVEX rev 1854, a library for dynamic binary translation.
==24791== Copyright (C) 2004-2007, and GNU GPL'd, by OpenWorks LLP.
==24791== Using valgrind-3.3.1-Debian, a dynamic binary instrumentation framework.
==24791== Copyright (C) 2000-2007, and GNU GPL'd, by Julian Seward et al.
==24791== For more details, rerun with: -v
==24791==
090204 17:59:29 [Warning] The syntax '--log' is deprecated and will be removed in MySQL 7.0. Please use '--gene
ral-log --general-log-file' instead.
090204 17:59:29 [Warning] The syntax '--log-slow-queries' is deprecated and will be removed in MySQL 7.0. Pleas
e use '--slow-query-log'/'--slow-query-log-file' instead.
090204 17:59:30 [Note] Plugin 'InnoDB' disabled by command line option
090204 17:59:31 [Note] Falcon: unable to open system data files.
090204 17:59:31 [Note] Falcon: creating new system data files.
==24791== Warning: set address range perms: large range 134221904 (undefined)
==24791== Warning: set address range perms: large range 127930448 (undefined)
090204 17:59:43 [Note] Event Scheduler: Loaded 0 events
090204 17:59:43 [Note] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld: ready for connections.
Version: '6.0.10-alpha-valgrind-max-debug-log'  socket: '/home/hakan/work/mysql/mysql-6.0-falcon-team/mysql-tes
t/var/tmp/mysqld.1.sock'  port: 12500  Source distribution
090204 17:59:52 [Note] Got signal 15 to shutdown mysqld
090204 17:59:52 [Note] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld: Normal shutdown

090204 17:59:52 [Note] Event Scheduler: Purging the queue. 0 events
==24791== Warning: set address range perms: large range 134221936 (noaccess)
==24791== Warning: set address range perms: large range 127930480 (noaccess)
090204 17:59:57 [Warning] Forcing shutdown of 3 plugins
090204 17:59:57 [Note] Debug sync points hit:                   154
090204 17:59:57 [Note] Debug sync points executed:              0
090204 17:59:57 [Note] Debug sync points max active per thread: 0
090204 17:59:57 [Note] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld: Shutdown complete

==24791==
==24791== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 8 from 1)
==24791== malloc/free: in use at exit: 33,960 bytes in 10 blocks.
==24791== malloc/free: 7,090 allocs, 7,080 frees, 344,759,727 bytes allocated.
==24791== For counts of detected errors, rerun with: -v
==24791== searching for pointers to 10 not-freed blocks.
==24791== checked 63,108,576 bytes.
==24791==
==24791== 32,176 (176 direct, 32,000 indirect) bytes in 1 blocks are definitely lost in loss record 3 of 4
==24791==    at 0x4C2260E: malloc (vg_replace_malloc.c:207)
==24791==    by 0xDAB0FC: my_malloc (my_malloc.c:34)
==24791==    by 0xD9DDAF: my_multi_malloc (mulalloc.c:50)
==24791==    by 0xDA2554: safe_mutex_init (thr_mutex.c:111)
==24791==    by 0xD7B593: thr_lock_init (thr_lock.c:341)
==24791==    by 0xA46F84: StorageInterface::open(char const*, int, unsigned) (ha_falcon.cpp:523)
==24791==    by 0x8AD28D: handler::ha_open(TABLE*, char const*, int, int) (handler.cc:2030)
==24791==    by 0x7CADFA: open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned, unsigned, unsigned,
TABLE*, open_table_mode) (table.cc:2022)
==24791==    by 0x7BFD64: open_table(THD*, TABLE_LIST*, st_mem_root*, enum_open_table_action*, unsigned) (sql_b
ase.cc:2744)
==24791==    by 0x7C0B3E: open_tables(THD*, TABLE_LIST**, unsigned*, unsigned) (sql_base.cc:3737)
==24791==    by 0x7C1280: open_and_lock_tables_derived(THD*, TABLE_LIST*, bool, unsigned) (sql_base.cc:4186)
==24791==    by 0x772F37: open_and_lock_tables(THD*, TABLE_LIST*) (mysql_priv.h:1574)
==24791==    by 0x8146F1: mysql_insert(THD*, TABLE_LIST*, List<Item>&, List<List<Item> >&, List<Item>&, List<It
em>&, enum_duplicates, bool) (sql_insert.cc:622)
==24791==    by 0x76ACCA: mysql_execute_command(THD*) (sql_parse.cc:3122)
==24791==    by 0x77016C: mysql_parse(THD*, char const*, unsigned, char const**) (sql_parse.cc:5750)
==24791==    by 0x770D23: dispatch_command(enum_server_command, THD*, char*, unsigned) (sql_parse.cc:1009)
==24791==
==24791==
==24791== 32,000 bytes in 2 blocks are indirectly lost in loss record 4 of 4
==24791==    at 0x4C2260E: malloc (vg_replace_malloc.c:207)
==24791==    by 0xDAB0FC: my_malloc (my_malloc.c:34)
==24791==    by 0xDAD3E3: init_dynamic_array2 (array.c:60)
==24791==    by 0xD993E8: _my_hash_init (hash.c:58)
==24791==    by 0xDA25E1: safe_mutex_init (thr_mutex.c:123)
==24791==    by 0xD7B593: thr_lock_init (thr_lock.c:341)
==24791==    by 0xA46F84: StorageInterface::open(char const*, int, unsigned) (ha_falcon.cpp:523)
==24791==    by 0x8AD28D: handler::ha_open(TABLE*, char const*, int, int) (handler.cc:2030)
==24791==    by 0x7CADFA: open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned, unsigned, unsigned,
TABLE*, open_table_mode) (table.cc:2022)
==24791==    by 0x7BFD64: open_table(THD*, TABLE_LIST*, st_mem_root*, enum_open_table_action*, unsigned) (sql_b
ase.cc:2744)
==24791==    by 0x7C0B3E: open_tables(THD*, TABLE_LIST**, unsigned*, unsigned) (sql_base.cc:3737)
==24791==    by 0x7C1280: open_and_lock_tables_derived(THD*, TABLE_LIST*, bool, unsigned) (sql_base.cc:4186)
==24791==    by 0x772F37: open_and_lock_tables(THD*, TABLE_LIST*) (mysql_priv.h:1574)
==24791==    by 0x8146F1: mysql_insert(THD*, TABLE_LIST*, List<Item>&, List<List<Item> >&, List<Item>&, List<It
em>&, enum_duplicates, bool) (sql_insert.cc:622)
==24791==    by 0x76ACCA: mysql_execute_command(THD*) (sql_parse.cc:3122)
==24791==    by 0x77016C: mysql_parse(THD*, char const*, unsigned, char const**) (sql_parse.cc:5750)
==24791==
==24791== LEAK SUMMARY:
==24791==    definitely lost: 176 bytes in 1 blocks.
==24791==    indirectly lost: 32,000 bytes in 2 blocks.
==24791==      possibly lost: 0 bytes in 0 blocks.
==24791==    still reachable: 0 bytes in 0 blocks.
==24791==         suppressed: 1,784 bytes in 7 blocks.
==24997== Memcheck, a memory error detector.
==24997== Copyright (C) 2002-2007, and GNU GPL'd, by Julian Seward et al.
==24997== Using LibVEX rev 1854, a library for dynamic binary translation.
==24997== Copyright (C) 2004-2007, and GNU GPL'd, by OpenWorks LLP.
==24997== Using valgrind-3.3.1-Debian, a dynamic binary instrumentation framework.
==24997== Copyright (C) 2000-2007, and GNU GPL'd, by Julian Seward et al.
==24997== For more details, rerun with: -v
==24997==
090204 18:00:02 [Warning] The syntax '--log' is deprecated and will be removed in MySQL 7.0. Please use '--gene
ral-log --general-log-file' instead.
090204 18:00:02 [Warning] The syntax '--log-slow-queries' is deprecated and will be removed in MySQL 7.0. Pleas
e use '--slow-query-log'/'--slow-query-log-file' instead.
090204 18:00:03 [Note] Plugin 'InnoDB' disabled by command line option
==24997== Warning: set address range perms: large range 134221904 (undefined)
==24997== Warning: set address range perms: large range 127930448 (undefined)
090204 18:00:12 [Note] Event Scheduler: Loaded 0 events
090204 18:00:12 [Note] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld: ready for connections.
Version: '6.0.10-alpha-valgrind-max-debug-log'  socket: '/home/hakan/work/mysql/mysql-6.0-falcon-team/mysql-tes
t/var/tmp/mysqld.1.sock'  port: 12500  Source distribution

Sergey, Will you have time to look into this bug?  Valgrind reports that 32,000 bytes in 2 blocks are indirectly lost in loss record 4 of 4.  But the call stack is back in the server after going through Falcon.

handler::ha_open -> StorageInterface::open -> thr_lock_init ->
safe_mutex_init -> init_dynamic_array2 -> my_malloc -> malloc

We will need a server knowledgeable person to debug this.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/65222

2999 Vladislav Vaintroub	2009-02-04
      Bug#42227 : Test falcon.falcon_bug_28095 fails sporadically on pushbuild
      
      The reason for test failure is a memory leak found by valgrind.
      Falcon has THR_LOCK in its StorageTalbeShareStructure ( dubbed "impure"). The lock is initialized when table is opened, but it is  normally not destroyed (only when table is deleted). In the failing test case valgrind notices the leak, because table is created  and not deleted before shutdown.
      
      Fix is to destroy the THR_LOCK  when StorageTableShare is destroyed.

reassigning it to myself, since already have a fix.

Thanks for doing this Vlad.  OK to push.

Pushed into 6.0.10-alpha (revid:alik@sun.com-20090211182317-uagkyj01fk30p1f8) (version source revid:christopher.powers@sun.com-20090205054006-tkor0eqqnlyo4za3) (merge vers: 6.0.10-alpha) (pib:6)

Internal/test fix. No changelog entry required.