← Back to team overview

oqgraph-dev team mailing list archive

Re: Oqgraph legacy regression test for latch

 

Hi Antony

FWIW I am running with mysql built with debugging on and it seems to be an
assertion, and our code doesnt show in the trace anywhere

I should probably do a clean (non-debug) build and see if it happens again;
but then I always assume that assertions are in place for a reason


Anyway, here is the test log:



andrew@atlantis3:~/develop/maria/repo/oqgraph-varchar/build/mysql-test$
./mysql-test-run.pl --record oqgraph.legacy_upgrade
Logging:
/home/andrew/develop/maria/repo/oqgraph-varchar/mysql-test/mysql-test-run.pl
--record oqgraph.legacy_upgrade
vardir: /home/andrew/develop/maria/repo/oqgraph-varchar/build/mysql-test/var
Checking leftover processes...
Removing old var directory...
Creating var directory
'/home/andrew/develop/maria/repo/oqgraph-varchar/build/mysql-test/var'...
Checking supported features...
MariaDB Version 10.0.1-MariaDB-debug
Installing system database...
 - skipping ndbcluster
 - SSL connections supported
 - binaries are debug compiled
Collecting tests...
Using server port 37672

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

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
oqgraph.legacy_upgrade                   [ fail ]
        Test ended at 2013-05-28 20:40:52

CURRENT_TEST: oqgraph.legacy_upgrade


Server [mysqld.1 - pid: 10626, winpid: 10626, exit: 256] failed during test run
Server log from this test:
----------SERVER LOG START-----------
130528 20:40:51 [Note] Plugin 'SPHINX' is disabled.
130528 20:40:51 [Note] Plugin 'InnoDB' is disabled.
130528 20:40:51 [Note] Plugin 'INNODB_TRX' is disabled.
130528 20:40:51 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
130528 20:40:51 [Note] Plugin 'INNODB_CMP' is disabled.
130528 20:40:51 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
130528 20:40:51 [Note] Plugin 'INNODB_CMPMEM' is disabled.
130528 20:40:51 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
130528 20:40:51 [Note] Plugin 'INNODB_BUFFER_PAGE' is disabled.
130528 20:40:51 [Note] Plugin 'INNODB_BUFFER_PAGE_LRU' is disabled.
130528 20:40:51 [Note] Plugin 'INNODB_BUFFER_POOL_STATS' is disabled.
130528 20:40:51 [Note] Plugin 'INNODB_METRICS' is disabled.
130528 20:40:51 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
130528 20:40:51 [Note] Plugin 'INNODB_FT_INSERTED' is disabled.
130528 20:40:51 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
130528 20:40:51 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
130528 20:40:51 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
130528 20:40:51 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
130528 20:40:51 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
130528 20:40:51 [Note] Plugin 'INNODB_SYS_TABLES' is disabled.
130528 20:40:51 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
130528 20:40:51 [Note] Plugin 'INNODB_SYS_INDEXES' is disabled.
130528 20:40:51 [Note] Plugin 'INNODB_SYS_COLUMNS' is disabled.
130528 20:40:51 [Note] Plugin 'INNODB_SYS_FIELDS' is disabled.
130528 20:40:51 [Note] Plugin 'INNODB_SYS_FOREIGN' is disabled.
130528 20:40:51 [Note] Plugin 'INNODB_SYS_FOREIGN_COLS' is disabled.
130528 20:40:51 [Note] Plugin 'BLACKHOLE' is disabled.
130528 20:40:51 [Note] Plugin 'FEDERATED' is disabled.
130528 20:40:51 [Note] Plugin 'ARCHIVE' is disabled.
130528 20:40:51 [Note] Plugin 'FEEDBACK' is disabled.
130528 20:40:51 [Note] Plugin 'partition' is disabled.
130528 20:40:51 [Note] Event Scheduler: Loaded 0 events
130528 20:40:51 [Note]
/home/andrew/develop/maria/repo/oqgraph-varchar/build/sql/mysqld: ready for
connections.
Version: '10.0.1-MariaDB-debug-log'  socket:
'/home/andrew/develop/maria/repo/oqgraph-varchar/build/mysql-test/var/tmp/mysqld.1.sock'
 port: 16000  Source distribution
Warning:  984 bytes lost, allocated by T@2 at mysys/my_alloc.c:233,
sql/thr_malloc.cc:77, sql/field.h:163, sql/field.cc:9501, sql/table.cc:1590,
sql/table.cc:747, ??:0, sql/handler.cc:2347
Warning: 1744 bytes lost, allocated by T@2 at mysys/my_alloc.c:233,
sql/sql_list.h:43, myisam/ha_myisam.cc:128, sql/handler.cc:252,
sql/table.cc:1370, sql/table.cc:747, ??:0, sql/handler.cc:2347
Warning:  984 bytes lost, allocated by T@2 at mysys/my_alloc.c:233, ??:0,
sql/handler.cc:2347, sql/table.cc:2663, sql/sql_base.cc:3207,
sql/sql_base.cc:4564, sql/sql_base.cc:5115, sql/sql_base.cc:5718
Memory lost: 3712 bytes in 2223 chunks
mysqld: /home/andrew/develop/maria/repo/oqgraph-varchar/sql/sql_class.cc:1572:
virtual THD::~THD(): Assertion `status_var.memory_used == 0' failed.
130528 20:40:52 [ERROR] mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.

To report this bug, see http://kb.askmonty.org/en/reporting-bugs

We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.

Server version: 10.0.1-MariaDB-debug-log
key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=1
max_threads=153
thread_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 62249 K
 bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0x232e6a0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x7f87eeff6e18 thread_stack 0x48000
mysys/stacktrace.c:246(my_print_stacktrace)[0xdbbc02]
sql/signal_handler.cc:155(handle_fatal_signal)[0x7dfd05]
??:0(??)[0x7f87fca6dff0]
??:0(??)[0x7f87fbe6a1b5]
??:0(??)[0x7f87fbe6cfc0]
??:0(??)[0x7f87fbe63301]
sql/sql_class.cc:1575(~THD)[0x5d9a7e]
sql/mysqld.cc:2600(unlink_thd(THD*))[0x5622c1]
sql/mysqld.cc:2703(one_thread_per_connection_end(THD*, bool))[0x5625b2]
sql/sql_connect.cc:1278(do_handle_one_connection(THD*))[0x721c4c]
sql/sql_connect.cc:1182(handle_one_connection)[0x721651]
perfschema/pfs.cc:1802(pfs_spawn_thread)[0x9c5b46]
??:0(??)[0x7f87fca658ca]
??:0(??)[0x7f87fbf0792d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x0):
Connection ID (thread ID): 2
Status: KILL_CONNECTION

Optimizer switch:
index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=off

The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
Writing a core file
----------SERVER LOG END-------------
mysqltest failed but provided no output
The result from queries just before the failure was:
< snip >
1	1	4	NULL	0	1
1	1	4	1	1	3
1	1	4	1	2	4
SELECT * FROM graph WHERE latch=1 AND origid=4 AND destid=1;
latch	origid	destid	weight	seq	linkid
1	4	1	NULL	0	4
1	4	1	1	1	3
1	4	1	1	2	1
# Adding new row to base table
INSERT INTO graph_base (from_id,to_id) VALUES (4,6);
# Deleting rows from base table
DELETE FROM graph_base WHERE from_id=5;
DELETE FROM graph_base WHERE from_id=3 AND to_id=5;
# Execising latch==1 on new data
SELECT * FROM graph WHERE latch=1 AND origid=1 AND destid=6;
latch	origid	destid	weight	seq	linkid
1	1	6	NULL	0	1
1	1	6	1	1	3
1	1	6	1	2	4
1	1	6	1	3	6



 - saving
'/home/andrew/develop/maria/repo/oqgraph-varchar/build/mysql-test/var/log/oqgraph.legacy_upgrade/'
to
'/home/andrew/develop/maria/repo/oqgraph-varchar/build/mysql-test/var/log/oqgraph.legacy_upgrade/'
 - found 'core' (0/5)

Trying 'dbx' to get a backtrace

Trying 'gdb' to get a backtrace
Core generated by
'/home/andrew/develop/maria/repo/oqgraph-varchar/build/sql/mysqld'
Output from gdb follows. The first stack trace is from the failing thread.
The following stack traces are from all threads (so the failing one is
duplicated).
--------------------------
[New Thread 10627]
[New Thread 10632]
[New Thread 10629]

warning: Can't read pathname for load map: Input/output error.
Core was generated by
`/home/andrew/develop/maria/repo/oqgraph-varchar/build/sql/mysqld --defaults-gro'.
Program terminated with signal 6, Aborted.
#0  0x00007f87fca6b45c in __pthread_kill (threadid=<value optimized out>,
signo=<value optimized out>) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:63
63	../nptl/sysdeps/unix/sysv/linux/pthread_kill.c: No such file or directory.
	in ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c
#0  0x00007f87fca6b45c in __pthread_kill (threadid=<value optimized out>,
signo=<value optimized out>) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:63
#1  0x0000000000dbbcd6 in my_write_core (sig=6) at
/home/andrew/develop/maria/repo/oqgraph-varchar/mysys/stacktrace.c:457
#2  0x00000000007e0016 in handle_fatal_signal (sig=6) at
/home/andrew/develop/maria/repo/oqgraph-varchar/sql/signal_handler.cc:262
#3  <signal handler called>
#4  0x00007f87fbe6a1b5 in *__GI_raise (sig=<value optimized out>) at
../nptl/sysdeps/unix/sysv/linux/raise.c:64
#5  0x00007f87fbe6cfc0 in *__GI_abort () at abort.c:92
#6  0x00007f87fbe63301 in *__GI___assert_fail (assertion=0xe2e4a0
"status_var.memory_used == 0", file=<value optimized out>, line=1572,
function=0xe30250 "virtual THD::~THD()") at assert.c:81
#7  0x00000000005d9a7e in ~THD (this=0x232e6a0, __in_chrg=<value optimized
out>) at /home/andrew/develop/maria/repo/oqgraph-varchar/sql/sql_class.cc:1572
#8  0x00000000005622c1 in unlink_thd (thd=0x232e6a0) at
/home/andrew/develop/maria/repo/oqgraph-varchar/sql/mysqld.cc:2599
#9  0x00000000005625b2 in one_thread_per_connection_end (thd=0x232e6a0,
put_in_cache=true) at
/home/andrew/develop/maria/repo/oqgraph-varchar/sql/mysqld.cc:2701
#10 0x0000000000721c4c in do_handle_one_connection (thd_arg=0x232e6a0) at
/home/andrew/develop/maria/repo/oqgraph-varchar/sql/sql_connect.cc:1278
#11 0x0000000000721651 in handle_one_connection (arg=0x232e6a0) at
/home/andrew/develop/maria/repo/oqgraph-varchar/sql/sql_connect.cc:1181
#12 0x00000000009c5b46 in pfs_spawn_thread (arg=0x2183d80) at
/home/andrew/develop/maria/repo/oqgraph-varchar/storage/perfschema/pfs.cc:1800
#13 0x00007f87fca658ca in start_thread (arg=<value optimized out>) at
pthread_create.c:300
#14 0x00007f87fbf0792d in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#15 0x0000000000000000 in ?? ()
Current language:  auto
The current source language is "auto; currently c".

Thread 4 (Thread 10629):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at
../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:211
#1  0x0000000000dc3e3c in safe_cond_timedwait (cond=0x1e9c9a0, mp=0x1e9c8e0,
abstime=0x7f87fbe36db0, file=0xf24ae0
"/home/andrew/develop/maria/repo/oqgraph-varchar/include/mysql/psi/mysql_thread.h",
line=1191) at
/home/andrew/develop/maria/repo/oqgraph-varchar/mysys/thr_mutex.c:547
#2  0x0000000000a25a88 in inline_mysql_cond_timedwait (that=0x1e9c9a0,
mutex=0x1e9c8e0, abstime=0x7f87fbe36db0, src_file=0xf24b38
"/home/andrew/develop/maria/repo/oqgraph-varchar/storage/maria/ma_servicethread.c",
src_line=119) at
/home/andrew/develop/maria/repo/oqgraph-varchar/include/mysql/psi/mysql_thread.h:1191
#3  0x0000000000a25fab in my_service_thread_sleep (control=0x1520450,
sleep_time=29000000000) at
/home/andrew/develop/maria/repo/oqgraph-varchar/storage/maria/ma_servicethread.c:118
#4  0x0000000000a1a266 in ma_checkpoint_background (arg=0x1e) at
/home/andrew/develop/maria/repo/oqgraph-varchar/storage/maria/ma_checkpoint.c:709
#5  0x00000000009c5b46 in pfs_spawn_thread (arg=0x20483a0) at
/home/andrew/develop/maria/repo/oqgraph-varchar/storage/perfschema/pfs.cc:1800
#6  0x00007f87fca658ca in start_thread (arg=<value optimized out>) at
pthread_create.c:300
#7  0x00007f87fbf0792d in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#8  0x0000000000000000 in ?? ()

Thread 3 (Thread 10632):
#0  do_sigwait (set=0x7f87ef03fdb0, sig=0x7f87ef03fe68) at
../nptl/sysdeps/unix/sysv/linux/../../../../../sysdeps/unix/sysv/linux/sigwait.c:65
#1  0x00007f87fca6ddb7 in __sigwait (set=<value optimized out>, sig=<value
optimized out>) at
../nptl/sysdeps/unix/sysv/linux/../../../../../sysdeps/unix/sysv/linux/sigwait.c:100
#2  0x00000000005631f0 in signal_hand (arg=0x0) at
/home/andrew/develop/maria/repo/oqgraph-varchar/sql/mysqld.cc:3153
#3  0x00000000009c5b46 in pfs_spawn_thread (arg=0x205a3a0) at
/home/andrew/develop/maria/repo/oqgraph-varchar/storage/perfschema/pfs.cc:1800
#4  0x00007f87fca658ca in start_thread (arg=<value optimized out>) at
pthread_create.c:300
#5  0x00007f87fbf0792d in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#6  0x0000000000000000 in ?? ()
Current language:  auto
The current source language is "auto; currently asm".

Thread 2 (Thread 10627):
#0  __lll_lock_wait () at
../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
#1  0x00007f87fca681af in _L_lock_1172 () from /lib/libpthread.so.0
#2  0x00007f87fca680fa in __pthread_mutex_lock (mutex=0x1661368) at
pthread_mutex_lock.c:101
#3  0x0000000000dc32fe in safe_mutex_lock (mp=0x1661340, my_flags=0,
file=0xe2e1c0
"/home/andrew/develop/maria/repo/oqgraph-varchar/sql/sql_class.cc", line=970)
at /home/andrew/develop/maria/repo/oqgraph-varchar/mysys/thr_mutex.c:294
#4  0x00000000005d451e in inline_mysql_mutex_lock (that=0x1661340,
src_file=0xe2e1c0
"/home/andrew/develop/maria/repo/oqgraph-varchar/sql/sql_class.cc",
src_line=970) at
/home/andrew/develop/maria/repo/oqgraph-varchar/include/mysql/psi/mysql_thread.h:672
#5  0x00000000005d7402 in THD (this=0x227fd30) at
/home/andrew/develop/maria/repo/oqgraph-varchar/sql/sql_class.cc:970
#6  0x0000000000567bb8 in handle_connections_sockets () at
/home/andrew/develop/maria/repo/oqgraph-varchar/sql/mysqld.cc:5962
#7  0x00000000005669ee in mysqld_main (argc=103, argv=0x1ebf1f0) at
/home/andrew/develop/maria/repo/oqgraph-varchar/sql/mysqld.cc:5257
#8  0x000000000055d8b4 in main (argc=8, argv=0x7fffbe7d5d48) at
/home/andrew/develop/maria/repo/oqgraph-varchar/sql/main.cc:25
Current language:  auto
The current source language is "auto; currently c".

Thread 1 (Thread 10640):
#0  0x00007f87fca6b45c in __pthread_kill (threadid=<value optimized out>,
signo=<value optimized out>) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:63
#1  0x0000000000dbbcd6 in my_write_core (sig=6) at
/home/andrew/develop/maria/repo/oqgraph-varchar/mysys/stacktrace.c:457
#2  0x00000000007e0016 in handle_fatal_signal (sig=6) at
/home/andrew/develop/maria/repo/oqgraph-varchar/sql/signal_handler.cc:262
#3  <signal handler called>
#4  0x00007f87fbe6a1b5 in *__GI_raise (sig=<value optimized out>) at
../nptl/sysdeps/unix/sysv/linux/raise.c:64
#5  0x00007f87fbe6cfc0 in *__GI_abort () at abort.c:92
#6  0x00007f87fbe63301 in *__GI___assert_fail (assertion=0xe2e4a0
"status_var.memory_used == 0", file=<value optimized out>, line=1572,
function=0xe30250 "virtual THD::~THD()") at assert.c:81
#7  0x00000000005d9a7e in ~THD (this=0x232e6a0, __in_chrg=<value optimized
out>) at /home/andrew/develop/maria/repo/oqgraph-varchar/sql/sql_class.cc:1572
#8  0x00000000005622c1 in unlink_thd (thd=0x232e6a0) at
/home/andrew/develop/maria/repo/oqgraph-varchar/sql/mysqld.cc:2599
#9  0x00000000005625b2 in one_thread_per_connection_end (thd=0x232e6a0,
put_in_cache=true) at
/home/andrew/develop/maria/repo/oqgraph-varchar/sql/mysqld.cc:2701
#10 0x0000000000721c4c in do_handle_one_connection (thd_arg=0x232e6a0) at
/home/andrew/develop/maria/repo/oqgraph-varchar/sql/sql_connect.cc:1278
#11 0x0000000000721651 in handle_one_connection (arg=0x232e6a0) at
/home/andrew/develop/maria/repo/oqgraph-varchar/sql/sql_connect.cc:1181
#12 0x00000000009c5b46 in pfs_spawn_thread (arg=0x2183d80) at
/home/andrew/develop/maria/repo/oqgraph-varchar/storage/perfschema/pfs.cc:1800
#13 0x00007f87fca658ca in start_thread (arg=<value optimized out>) at
pthread_create.c:300
#14 0x00007f87fbf0792d in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#15 0x0000000000000000 in ?? ()
Current language:  auto
The current source language is "auto; currently asm".
Current language:  auto
The current source language is "auto; currently c".

--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 0.000 of 7 seconds executing testcases

Failure: Failed 1/1 tests, 0.00% were successful.

Failing test(s): oqgraph.legacy_upgrade

The log files in var/log may give you some hint of what went wrong.

If you want to report this error, please read first the documentation
at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html

mysql-test-run: *** ERROR: there were failing test cases

On 28/05/13 20:48, Antony T Curtis wrote:
> Do you have a stack trace?
> 
> On May 28, 2013 4:16 AM, "Andrew McDonnell" <bugs@xxxxxxxxxxxxxxxxxxx
> <mailto:bugs@xxxxxxxxxxxxxxxxxxx>> wrote:
> 
>     Hi,
> 
>     I added a legacy_upgrade.test and .result file to exercise that the new code
>     will still work if there happens to be an existing table with an integer latch
>     as might exist after upgrade.
> 
>     It passes, although for some reason mysqld would segfault at exit if I didnt
>     manually drop the tables in the test script.
> 
>     I need to go back to basic test and make that now just applicable for the
>     varchar latch and update the expected results.
> 
>     --Andrew
> 
>     --
>     Mailing list: https://launchpad.net/~oqgraph-dev
>     Post to     : oqgraph-dev@xxxxxxxxxxxxxxxxxxx
>     <mailto:oqgraph-dev@xxxxxxxxxxxxxxxxxxx>
>     Unsubscribe : https://launchpad.net/~oqgraph-dev
>     More help   : https://help.launchpad.net/ListHelp
> 



References