Valgrind error at THD::update_stats

[Laurynas Biveinis]

http://jenkins.percona.com/job/percona-server-5.5-valgrind/183/BUILD_TYPE=valgrind,Host=ubuntu-precise-64bit/consoleFull

01:10:44.475 main.percona_bug1008278 w2 [ fail ] Found warnings/errors in server log file!
01:10:44.476 Test ended at 2013-02-13 17:45:20
01:10:44.476 line
01:10:44.476 ==2282== Thread 18:
01:10:44.476 ==2282== Conditional jump or move depends on uninitialised value(s)
01:10:44.476 ==2282== at 0x575C9E: THD::update_stats(bool) (sql_class.cc:1356)
01:10:44.476 ==2282== by 0x5A23B2: mysql_parse(THD*, char*, unsigned int, Parser_state*) (sql_parse.cc:5918)
01:10:44.476 ==2282== by 0x73CE67: Query_log_event::do_apply_event(Relay_log_info const*, char const*, unsigned int) (log_event.cc:3496)
01:10:44.476 ==2282== by 0x54198C: apply_event_and_update_pos(Log_event*, THD*, Relay_log_info*) (log_event.h:1144)
01:10:44.476 ==2282== by 0x542AE6: handle_slave_sql (slave.cc:2559)
01:10:44.476 ==2282== by 0x9A00C8: pfs_spawn_thread (pfs.cc:1015)
01:10:44.476 ==2282== by 0x5882E99: start_thread (pthread_create.c:308)
01:10:44.476 ==2282== by 0x6187CBC: clone (clone.S:112)
01:10:44.476 ^ Found warnings in /home/jenkins/workspace/percona-server-5.5-valgrind/BUILD_TYPE/valgrind/Host/ubuntu-precise-64bit/Percona-Server/mysql-test/var/2/log/mysqld.2.err

This is against older 5.5 trunk, as Jenkins Valgrind jobs were broken since.

[Laurynas Biveinis (laurynas-biveinis)]

Reproduced locally.

./mysql-test-run --mem percona_bug1008278 --valgrind-mysqld

==18483== Thread 18:
==18483== Conditional jump or move depends on uninitialised value(s)
==18483== at 0x5D0940: THD::update_stats(bool) (sql_class.cc:1371)
==18483== by 0x60FA4C: mysql_parse(THD*, char*, unsigned int, Parser_state*) (sql_parse.cc:5934)
==18483== by 0x84E798: Query_log_event::do_apply_event(Relay_log_info const*, char const*, unsigned int) (log_event.cc:3496)
==18483== by 0x84DC61: Query_log_event::do_apply_event(Relay_log_info const*) (log_event.cc:3239)
==18483== by 0x588B15: Log_event::apply_event(Relay_log_info const*) (log_event.h:1144)
==18483== by 0x580F71: apply_event_and_update_pos(Log_event*, THD*, Relay_log_info*) (slave.cc:2399)
==18483== by 0x5814EF: exec_relay_log_event(THD*, Relay_log_info*) (slave.cc:2559)
==18483== by 0x583CBC: handle_slave_sql (slave.cc:3377)
==18483== by 0x9C2D5B: pfs_spawn_thread (pfs.cc:1015)
==18483== by 0x545AE99: start_thread (pthread_create.c:308)
==18483== by 0x619FCBC: clone (clone.S:112)
==18483== Uninitialised value was created by a heap allocation
==18483== at 0x4C2B3F8: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==18483== by 0x90E42B: my_malloc (my_malloc.c:38)
==18483== by 0x56688D: ilink::operator new(unsigned long) (sql_list.h:541)
==18483== by 0x583327: handle_slave_sql (slave.cc:3201)
==18483== by 0x9C2D5B: pfs_spawn_thread (pfs.cc:1015)
==18483== by 0x545AE99: start_thread (pthread_create.c:308)
==18483== by 0x619FCBC: clone (clone.S:112)

sql_class.cc:1371: if ((old_command == COM_QUERY || command == COM_CONNECT) &&

[Valerii Kravchuk (valerii-kravchuk)]

Test is included only into percona-5.5 (and XtraDB Cluster), so other versions can not be directly affected:

[openxs@chief bzr2]$ find . -name "percona_bug1008278.*"
./percona-5.5/Percona-Server/mysql-test/t/percona_bug1008278.test
./percona-5.5/Percona-Server/mysql-test/r/percona_bug1008278.result
./percona-xtradb-cluster/Percona-Server/mysql-test/t/percona_bug1008278.test
./percona-xtradb-cluster/Percona-Server/mysql-test/r/percona_bug1008278.result

Still easy to reproduce locally on recent 5.5 from bzr.

[Alexey Kopytov (akopytov)]

old_command is only initialized in dispatch_command(), i.e. in user threads, but not in the replication SQL thread. So when THD::update_stats() is called by the SQL thread, it reads an uninitialized old_command value.

This also means the bug is 5.1 too, it's just that we don't have a test case covering this condition in 5.1. And we should make sure we fix this in 5.6 as well after merging userstat, so setting to Confirmed in 5.6 too.

[Roel Van de Paar (roel11)]

Also seen during TokuDB testing

2014-05-21 15:24:07 8796 [Note] Execution of init_file '/ssd/randgen/conf/percona_qa/5.6/TokuDB.sql' started.
2014-05-21 15:24:08 8796 [ERROR] TokuDB not initialized because jemalloc is not loaded
2014-05-21 15:24:08 8796 [ERROR] Plugin 'TokuDB' init function returned error.
2014-05-21 15:24:08 8796 [ERROR] Plugin 'TokuDB' registration as a STORAGE ENGINE failed.
2014-05-21 15:24:08 8796 [Note] Shutting down plugin 'TokuDB'
==8796== Thread 26:
==8796== Conditional jump or move depends on uninitialised value(s)
==8796== at 0x702E8C: THD::update_stats(bool) (sql_class.cc:1540)
==8796== by 0x73658D: mysql_parse(THD*, char*, unsigned int, Parser_state*) (sql_parse.cc:6839)
==8796== by 0x736BDF: handle_bootstrap_impl(THD*) (sql_parse.cc:790)
==8796== by 0x736E65: do_handle_bootstrap(THD*) (sql_parse.cc:845)
==8796== by 0x736ECF: handle_bootstrap (sql_parse.cc:822)
==8796== by 0x906962: pfs_spawn_thread (pfs.cc:1860)
==8796== by 0x4E369D0: start_thread (in /lib64/libpthread-2.12.so)
==8796== by 0x6764B6C: clone (in /lib64/libc-2.12.so)
==8796== Uninitialised value was created by a heap allocation
==8796== at 0x4C285BC: operator new(unsigned long) (vg_replace_malloc.c:298)
==8796== by 0x61EBC9: bootstrap(st_mysql_file*) (mysqld.cc:6092)
==8796== by 0x61ED30: read_init_file(char*) (mysqld.cc:6142)
==8796== by 0x627D0E: mysqld_main(int, char**) (mysqld.cc:5781)
==8796== by 0x669AD1C: (below main) (in /lib64/libc-2.12.so)
==8796==
ERROR: 1123 Can't initialize function 'tokudb'; Plugin initialization function failed.
2014-05-21 15:24:08 8796 [Note] Execution of init_file '/ssd/randgen/conf/percona_qa/5.6/TokuDB.sql' ended.
2014-05-21 15:24:08 8796 [Note] /ssd/percona-server-5.6.17-65.0.el6.x86_64-valgrind/bin/mysqld: ready for connections.

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1354