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 Correia 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
Triage: Triaged: D3 (Medium)

[20 Jan 2009 20:40] Alfranio Correia
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.
[4 Feb 2009 15:20] Hakan Küçükyılmaz
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
[4 Feb 2009 16:43] Kevin Lewis
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.
[4 Feb 2009 18:17] Bugs System
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.
[4 Feb 2009 18:23] Vladislav Vaintroub
reassigning it to myself, since already have a fix.
[4 Feb 2009 19:43] Kevin Lewis
Thanks for doing this Vlad.  OK to push.
[13 Feb 2009 7:25] Bugs System
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)
[7 May 2009 16:15] MC Brown
Internal/test fix. No changelog entry required.