my mysql related ramblings

A Quick Review of Stack Traces

2010-09-29T20:32:00.000+02:00

I'll try to pass on some basic knowledge about those confusing stack traces we sometimes see in the mysql error logs. What can you tell from them, what are they useful for, and how to validate them?

Debugging Crashes

We tried to improve postmortem debugging of crashes + stack traces in the error log:

o) old versions of mysqld only printed numerical numbers instead of function names (if you're lucky!)

o) some platforms/architectures printed no stack trace what-so-ever!

o) faulty implementations of the crash error reporting and running query.

So, the result is that on modern supported platforms and recent versions of mysqld, you should get a useful stack trace. A simple example from 5.5.5 on Windows:

mysqld.exe!mysql_admin_table()[sql_table.cc:5150]
mysqld.exe!mysql_optimize_table()[sql_table.cc:5226]
mysqld.exe!mysql_execute_command()[sql_parse.cc:3107]
mysqld.exe!mysql_parse()[sql_parse.cc:5911]
mysqld.exe!dispatch_command()[sql_parse.cc:1138]
mysqld.exe!do_command()[sql_parse.cc:807]
mysqld.exe!do_handle_one_connection()[sql_connect.cc:1196]
mysqld.exe!handle_one_connection()[sql_connect.cc:1136]
mysqld.exe!pthread_start()[my_winthread.c:62]
mysqld.exe!_callthreadstartex()[threadex.c:348]
mysqld.exe!_threadstartex()[threadex.c:331]
kernel32.dll!BaseThreadStart()

It should be obvious that OPTIMIZE TABLE crashed here, since the function name is clear.

The reason I always use windows stack traces in bug reports is because they are readable. Most GDB and linux error log stack traces are not readable by the human brain at a glance, and therefore not memorable. One reason is excessive wrapping, another reason is offsets and arguments to the functions are irrelevant and not useful for search engine indexes or the average Joe trying to find a bug report matching a stack trace.

In the old days, a crash only this printed (only 32-bit), and you had to resolve it yourself:

0x81a0705
0x8407eef
0x8408a8f
0x8408b75
0x8408dd2
0x8409af7
0x83e7fc9
0x83eefc3
0x826014c
0x826035c
0x825ec43
0x82106fd
0x81b86da
0x81bd78b
0x81bdd16
0x81bfae2

Which, on a side note is not always possible to do properly with optimized binaries so you get a partially bogus looking stack and you might be tempted to wrongly suspect faulty hardware, foul play, or bad binaries:

0x81a0705 handle_segfault + 805
0x8407eef my_write + 671
0x8408a8f init_key_cache + 1279
0x8408b75 init_key_cache + 1509
0x8408dd2 init_key_cache + 2114
0x8409af7 flush_key_blocks + 55
0x83e7fc9 flush_blocks + 41
0x83eefc3 mi_repair_by_sort + 451
0x826014c ha_myisam::repair(THD*, st_mi_check_param&, bool) + 1900
0x826035c ha_myisam::enable_indexes(unsigned int) + 364
0x825ec43 ha_myisam::end_bulk_insert() + 99
0x82106fd mysql_insert(THD*, TABLE_LIST*, List&, List >&, List&, List&, enum_duplicates, bool) + 5037
0x81b86da mysql_execute_command(THD*) + 9610
0x81bd78b mysql_parse(THD*, char const*, unsigned int, char const**) + 379
0x81bdd16 dispatch_command(enum_server_command, THD*, char*, unsigned int) + 1238
0x81bfae2 handle_one_connection + 2578

Using a technique that involves disassembling the mysqld binary into ASM and piecing together C/C++ source code/comments, it's quite possible to find those inlined functions, expanded macros, or functions that have no name in the symbols file. A nice topic for another posting. So, after manually inspecting the binary + numeric offsets, I could get a proper stack trace:

0x81a0705 handle_segfault
0x8407eef unlink_block
0x8408a8f free_block
0x8408b75 flush_cached_blocks
0x8408dd2 flush_key_blocks_int
0x8409af7 flush_key_blocks
0x83e7fc9 flush_blocks
0x83eefc3 mi_repair_by_sort
0x826014c ha_myisam::repair
0x826035c ha_myisam::enable_indexes
0x825ec43 ha_myisam::end_bulk_insert
0x82106fd mysql_insert
0x81b86da mysql_execute_command
0x81bd78b mysql_parse
0x81bdd16 dispatch_command
0x81bfae2 handle_one_connection

This is simply a bulk insert performing a 'repair by sort'. It crashed in the keycache when flushing blocks, perhaps due to a memory corruption or overrun of something. I remember fulltext indexes or large table having this problem..

Some Identifying Elements of a Stack Trace
If your 5.1. or 5.5. server ever crashes, please keep the stack trace as it can help identify exactly what the problem is, and you can search google for clues.

prepared statements

Easily distinguishable by looking for the functions similar to this:

.....
mysqld-debug.exe!Prepared_statement::execute()[sql_prepare.cc:3050]
mysqld-debug.exe!mysql_sql_stmt_execute()[sql_prepare.cc:2393]
mysqld-debug.exe!mysql_execute_command()[sql_parse.cc:2935]
.....

stored routines and their call depth

Seeing sp_* is a sign of some stored routine activity You can even see how many SP calls there are nested, whether they called triggers. Takes some intuition to follow.

.......
06 mysqld_debug!sp_instr_stmt::exec_core
07 mysqld_debug!sp_lex_keeper::reset_lex_and_exec_core
08 mysqld_debug!sp_instr_stmt::execute
09 mysqld_debug!sp_head::execute
0a mysqld_debug!sp_head::execute_procedure
0b mysqld_debug!mysql_execute_command
.......

storage engine code (archive, innodb, myisam, merge)

InnoDB mostly asserts, and this is clearly identified in the error log before a stack trace.

"070223 21:47:40 InnoDB: Assertion failure in thread 1655241648 in file row0mysql.c line 3228"

Archive crashes can be easily seen by ha_archive functions:

.....
mysqld.exe!ha_archive::free_share()[ha_archive.cc:411]
mysqld.exe!ha_archive::open()[ha_archive.cc:498]
mysqld.exe!handler::ha_open()[handler.cc:2059]
.....

query cache

Any thing involving the Query_Cache class functions:

.....
#5  0x000000000065f390 in Query_cache::insert_table ()
#6  0x000000000065f63a in Query_cache::register_tables_from_list ()
#7  0x000000000065f6a5 in Query_cache::register_all_tables ()
#8  0x000000000065fc0a in Query_cache::store_query ()
#9  0x000000000058cd38 in mysql_execute_command ()
.....

mysql functions (string, math, datetime, comparative)

Look out for specific Item_func* methods...

.....
mysqld.exe!Arg_comparator::compare_binary_string()[item_cmpfunc.cc:1158]
mysqld.exe!Item_func_eq::val_int()[item_cmpfunc.cc:1692]
mysqld.exe!Item::val_bool()[item.cc:184]
mysqld.exe!Item_cond_and::val_int()[item_cmpfunc.cc:4222]
.....

first calling function in the application

You can nearly always expect a valid stack trace to have these functions at the bottom:

.....
mysqld-debug.exe!mysql_execute_command()[sql_parse.cc:2256]
mysqld-debug.exe!mysql_parse()[sql_parse.cc:5974]
mysqld-debug.exe!dispatch_command()[sql_parse.cc:1233]
mysqld-debug.exe!do_command()[sql_parse.cc:872]
mysqld-debug.exe!handle_one_connection()[sql_connect.cc:1127]

last calling functions before the crash

Crashing is usually handled by mysqld's segfault handler. It depends on the OS and environment. Most of the time you'll have:

mysqld-debug.exe!my_sigabrt_handler()[mysqld.cc:2048]
mysqld-debug.exe!raise()[winsig.c:597]
mysqld-debug.exe!abort()[abort.c:78]
......

0   mysqld   0x00579d3e my_print_stacktrace + 44
1   mysqld   0x00100f78 handle_segfault + 836
......

Debugging Hangs

When mysqld hangs or flatlines the CPU and logging in or killing queries doesn't help, you'd better either create a corefile, break into the process with a debugger, or just use the PMP.

You'll probably need stack trace of all the threads to determine what is going on:

A single thread is looping endlessly in some loop
Multiple threads are hitting a hot mutex, or totally deadlocked, waiting for each other.

If the deadlock is in innodb you often get useful innodb outputs in the error log
for each waiting thread. But it can be extremely helpful to get full stack traces too.

--Thread 3003468656 has waited at fsp/fsp0fsp.c line 2204 for 556.00 seconds the
semaphore:
X-lock on RW-latch at 0xb759ceb0 created in file fil/fil0fil.c line 1061

That's all for now.!

quick update from down under...

2010-06-16T09:53:00.002+02:00

I'm pleased to report that so far the Soccer World Cup has been pulled off rather successfully, with only minor incidents reported. I have however noticed local news showing some 'feel-good' stories that are obviously written to give a false impression to the international media of the real situation here. Let's hope the unions and Eskom workers don't mess things up by holding a gun to the Country's head with protesting/striking too much in the international media's light.. Hold thumbs..

BTW, I hate the vuvuzela :)

I thought I should share two important MySQL bugs with you today. In case you ever used YaSSL to establish SSL connections, you were at risk of hitting random crashes due to bug #34236 (Various possibly related SSL crashes) if more than one concurrent connection was ever made. The reason is the YaSSL code was built without mutexes as if for single threaded apps...

Next bug I think is widespread enough to mention is optimizer/query plan related. Examine the testcase on bug #48537 (difference of index selection between rpm binary and .tar.gz, windows vs linux..) And read the changeset notes:



   On Intel x86 machines index selection by the MySQL query
   optimizer could sometimes depend on the compiler version and
   optimization flags used to build the server binary.

   The problem was a result of a known issue with floating point
   calculations on x86: since internal FPU precision (80 bit)
   differs from precision used by programs (32-bit float or 64-bit
   double), the result of calculating a complex expression may
   depend on how FPU registers are allocated by the compiler and
   whether intermediate values are spilled from FPU to memory. In
   this particular case compiler versions and optimization flags
   had an effect on cost calculation when choosing the best index
   in best_access_path().

   A possible solution to this problem which has already been
   implemented in mysql-trunk is to limit FPU internal precision
   to 64 bits. So the fix is a backport of the relevant code to
   5.1 from mysql-trunk.

Now I'll get back to enjoying the public holiday and bugs reporting ;-)

vmstat/iostat replacement for windows ?

2010-05-14T08:14:00.003+02:00

I dislike the old perfmon interface and it's unreadable graphs and logs. For a long time I've been searching for a basic vmstat and/or iostat windows port, and one that doesn't rely on that nonsensical cygwin. If anybody knows of one, please leave a comment.

Here's a proof on concept I cooked up in 20 minutes using the PDH (performance data helper) functions. In a nutshell, it queries the PDH counters directly and I'm be free to display

the data however I like.

Here's what I got so far:


proc_q_len  pagefile  interrupt/s   cswitch/s  %cpu_user  %cpu_sys  %cpu_idle  %disk_busy   %disk_read  %disk_write
  10      2308780032  2016          2555         64         26         9         100            0           100
   3      2308911104  2863          3669         62         13        23         100            1           100
   0      2309206016  1857          3057         79         10         9           2            0             2
   0      2310217728  2579          3664         64          9        26         100            0           100
   1      2309140480  2195          2985         71          3        25         100            0           100
   2      2309140480  2241          3042         76          4        18         100            0           100

Not perfect, and I'm still trying to devise a proper layout for the stuff I want to display.

The columns shown correspond to the counters:

\System\Processor Queue Length
\Process(_Total)\Page File Bytes
\Processor(_Total)\Interrupts/sec
\System\Context Switches/sec
\Processor(_Total)\% User Time
\Processor(_Total)\% Privileged Time
\Processor(_Total)\% Idle Time
\PhysicalDisk(_Total)\% Disk Time
\PhysicalDisk(_Total)\% Disk Read Time
\PhysicalDisk(_Total)\% Disk Write Time

The general flow of code is like this (there are samples online):

1. PdhOpenQuery

2. PdhAddCounter for each counter

3. for each X seconds:

3.1 PdhCollectQueryData

3.2 PdhGetFormattedCounterValue for each counter

3.3 print the result for each counter

4. PdhCloseQuery

Beware of RBR and tables without indexes

2010-05-03T16:40:00.003+02:00

I always knew RBR and unindexed tables didn't play along very well, but never realized just how much you can distress a slave can in some cases.
Consider this statement (yeah yeah, i know :)

mysql> delete from t1 order by rand();
Query OK, 78130 rows affected (2.61 sec)

t1 has no indexes and is an int field with numbers from 1 to 78130. However, this will cause the slave to re-read entire table for each row deleted! Here it's still running, causing 100% cpu usage:

---TRANSACTION 0 1799, ACTIVE 2390 sec, OS thread id 3672 fetching rows mysql tables in use 1, locked 1 153 lock struct(s), heap size 30704, 78281 row lock(s), undo log entries 35423

Number of rows inserted 78130, updated 0, deleted 35423, read 1076560253 0.00 inserts/s, 0.00 updates/s, 17.58 deletes/s, 367099.91 reads/s

Over a billion row reads 40 minutes later and it's not even half done yet.For a large table this could take weeks or years to complete. It would be nice if there was a way to prevent this situation from happening.

debugging mysqld corefile on AIX

2010-02-12T16:22:00.005+02:00

I recently had the pleasure of logging into an AIX 5.3 machine for the first time ever, to debug a corefile.

Firstly, having the mysqld binary and core is not enough, unless you have an identical machine on which to study the corefile. Library mismatches can be a problem.. IBM was kind enough to provide the snapcore utility to solve this easily.

Snapcore will gather all the libraries and create a single archive contain libs, binary, core.

So we now have a file called something like: snapcore_555060.pax

On our dev box, extract the pax archive:

gunzip snapcore_555060.pax.Z

pax -r -f snapcore_555060.pax

On your dev AIX box, make sure you have DBX installed!!

bash-3.00# lslpp -l | grep bos.adt.debug
bos.adt.debug 5.3.8.0 COMMITTED Base Application Development

Now, we are ready to debug a core. But we have to instruct DBX to read the libraries

that we got from the pax archive, instead of the default libraries on this system.

dbx -F -p /usr=/home/sbester/core/usr ./mysqld ./core

And since this isn't a DBX tutorial, I'll stop here, but you'll use normal DBX commands to print a stack trace, move up/down frames, print variables, list the source code.

a little challenge

2009-12-01T20:20:00.002+02:00

How do you make mysqld write a DELETE to the binlog just by entering a SELECT statement ?
No triggers and no stored routines/functions are involved.

partitioning + auto_increment is buggy!

2009-08-27T07:53:00.004+02:00

Folks, I just want to warn you how buggy partitioned tables with negative values are. Never use negative values for InnoDB auto_increment columns!!!!

There are more bugs than I listed here..

5.1 doesn't solve all merge table hell from 5.0.

2009-06-27T13:29:00.004+02:00

This week I've had to revisit merge tables once again due to customers experiencing problems. Although 5.1 merge table implementation is a huge improvement over 5.0, there still remains some critical bugs.

My list is still growing:

bug #45800: crash when replacing into a merge table and there is a duplicate
bug #45781: infinite hang/crash in "opening tables" after handler tries to open merge table
bug #45796: invalid memory reads and writes when altering merge and base tables
bug #45777: check table doesn't show all problems for merge table compliance in 5.1

Not to mention a few feature requests, and even documentation clarification for some manual sections.

some useful additions to query generator

2009-06-19T07:38:00.002+02:00

I've been on vacation this week, and decided to fine-tune some old QA code. Opened the manual to see the syntax for a select statement, and afterwards added to my random select generator the following:

all index hints (force, use, ignore, for join, for order by, for group by)
lock in share mode, for update
key_block_size for individual indexes
hash, btree, rtree for individual indexes
unique, fulltext, spatial for indexes

Especially important is the 'lock in share mode' addition. The reason is InnoDB
has many serious bugs with this locking mode (insert ... select, and others) in read committed mode.

So, I don't need multitable delete or update to reproduce those bugs, since I can just do a simple select locking in share mode. For example, the following bugs previously went without proper testcase until I discovered this:

assert btr/btr0pcur.c line 217 -innodb_locks_unsafe_for_binlog or read committed
5.1.35 crashes with Failing assertion: index->type & DICT_CLUSTERED
Strange error messages about locks from InnoDB

some bug stats

2009-06-02T07:47:00.002+02:00

So I did some checking at the number of bugs I've reported since start of 2005. Seems I'm at the top of my game here!

P1 Server bugs: 180 (next runner up PeterG with 127)
P1 + P2 Server bugs: 321 (next runner up PeterG with 311)

Interesting to note that most of my bug filing happened after 2006, but I started working at MySQL in 2005, so that's why I've used that start date.

The runner ups mostly report bugs in alpha versions, falcon, maria, and beta versions of mysql.
Nearly all of my bugs are in the current GA versions since that is what most of our customers use.

On occasion I go off on a tangent and try break the subquery optimizations in 6.0, but this
is only a small percentage of the total.

been a shocking week for 5.1.35

2009-05-11T10:35:00.003+02:00

so last week i started tweaking some of my old 'rainbow' scripts, and found 1 bug for each day of the week. there are a few more in the pipeline still...

Bug #44774 (load_file function produces valgrind warnings)
Bug #44768 (SIGFPE crash when selecting rand from a view containing null)
Bug #44767 (invalid memory reads in password() and old_password() functions)
Bug #44766 (valgrind error when using convert() in a subquery)
Bug #44684 (valgrind reports invalid reads in Item_func_spatial_collection::val_str)
Bug #44672 (Assertion failed: thd->transaction.xid_state.xid.is_null())
Bug #44664 (valgrind warning for COMMIT_AND_CHAIN and ROLLBACK_AND_CHAIN)
Bug #44633 (Automatic search depth and nested join's results in server crash - v2)

so, it seems i am still useful for bug finding, even with old tools i created pre-5.1 GA

MXit !

2009-01-10T20:07:00.002+02:00

Today I started writing a PC client for MXit, because the existing ones suck. Since the company uses a proprietary variation of the jabber protocol to reduce bandwidth usage, I have to decode the protocol myself.. Will post details of it later...

Get MXit http://www.mxit.co.za/web/downloadmxit.htm

Kilimanjaro preparations

2009-01-05T14:01:00.005+02:00

So I have started training to get fit enough to gracefully reach the top of Kilimanjaro in 2009.
Information on the various routes here.

Here I will keep a log of certain walks I do, and their timings.
Note that time_down usually includes time spent at the summit.


+------------+------------+------------+-----------+------------+------------------------------------------------------+
| date       | start_time | time_there | time_back | time_total | venue                                                |
+------------+------------+------------+-----------+------------+------------------------------------------------------+
| 2008-12-27 | 16:37:00   | 00:47:00   | 00:32:00  | 01:19:00   | Lions Head                                           |
| 2008-12-28 | 05:47:00   | 00:48:00   | 00:35:00  | 01:23:00   | Lions Head                                           |
| 2008-12-30 | 12:57:00   | 00:42:00   | 00:30:00  | 01:12:00   | Lions Head                                           |
| 2008-12-31 | 12:24:00   | 00:39:00   | 00:30:00  | 01:09:00   | Lions Head                                           |
| 2009-01-02 | 12:09:00   | 00:37:00   | 00:28:00  | 01:05:00   | Lions Head                                           |
| 2009-01-05 | 12:45:00   | 00:39:00   | 00:22:00  | 01:01:00   | Lions Head                                           |
| 2009-01-07 | 17:19:00   | 00:37:00   | 00:21:00  | 00:58:00   | Lions Head                                           |
| 2009-01-14 | 12:10:00   | 01:01:00   | 01:29:00  | 02:30:00   | Home->La Med (via KloofNek)->Joburg (via Sea Point)  |
| 2009-01-24 | 06:00:00   | 01:05:00   | 00:47:00  | 01:52:00   | Platteklip                                           |
| 2009-01-29 | 13:30:00   | 00:38:00   | 00:27:00  | 01:05:00   | Lions Head                                           |
| 2009-02-21 | 07:26:00   | 00:58:00   | 01:31:00  | 02:29:00   | Home->La Med (via KloofNek)->Joburg) (via Sea Point) |
+------------+------------+------------+-----------+------------+------------------------------------------------------+
11 rows in set (0.03 sec)

innodb index page format

2008-09-20T06:34:00.005+02:00

Today I had to decode an innodb index page, so I documented the entire process here:

E:\mysql-enterprise-gpl-5.0.66a-winx64\bin>mysqld-nt --console --skip-grant-tables --skip-name-resolve
InnoDB: The first specified data file .\ibdata1 did not exist:
InnoDB: a new database to be created!
080919 14:29:00  InnoDB: Setting file .\ibdata1 size to 10 MB
InnoDB: Database physically writes the file full: wait...
080919 14:29:00  InnoDB: Log file .\ib_logfile0 did not exist: new to be created
InnoDB: Setting log file .\ib_logfile0 size to 5 MB
InnoDB: Database physically writes the file full: wait...
080919 14:29:01  InnoDB: Log file .\ib_logfile1 did not exist: new to be created
InnoDB: Setting log file .\ib_logfile1 size to 5 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Doublewrite buffer not found: creating new
InnoDB: Doublewrite buffer created
InnoDB: Creating foreign key constraint system tables
InnoDB: Foreign key constraint system tables created
080919 14:29:01  InnoDB: Started; log sequence number 0 0
080919 14:29:01 [Note] mysqld-nt: ready for connections.
Version: '5.0.66a-enterprise-gpl-nt'  socket: ''  port: 3306  MySQL Enterprise Server (GPL)


create table t1(a varchar(20) primary key, b varchar(20), c varchar(20),key(b),key(c,b))engine=innodb;
insert into t1(a,b,c) values ('aaaa','bbbbb','cccccc');
insert into t1(a,b,c) values ('aaaaaaa',null,'ccc');
insert into t1(a,b,c) values ('a','b',null);
insert into t1(a,b,c) values ('aaaaaaaaaa','bbb','c');



080919 14:37:59 [Note] mysqld-nt: Normal shutdown

080919 14:37:59  InnoDB: Starting shutdown...
080919 14:38:14  InnoDB: Shutdown completed; log sequence number 0 48536
080919 14:38:14 [Note] mysqld-nt: Shutdown complete



we have secondary indexes on this table

this is key(c,b) (directly from ibdata1):


000d0000h: 35 56 71 04 00 00 00 34 FF FF FF FF FF FF FF FF ; 5Vq....4ÿÿÿÿÿÿÿÿ
000d0010h: 00 00 00 00 00 00 BD 92 45 BF 00 00 00 00 00 00 ; ......½’E¿......
000d0020h: 00 00 00 00 00 00 00 02 00 C3 80 06 00 00 00 00 ; .........Ã€.....
000d0030h: 00 B5 00 05 00 00 00 04 00 00 00 00 00 00 03 05 ; .µ..............
000d0040h: 00 00 00 00 00 00 00 00 00 11 00 00 00 00 00 00 ; ................
000d0050h: 00 02 15 F2 00 00 00 00 00 00 00 02 15 32 01 00 ; ...ò.........2..
000d0060h: 02 00 47 69 6E 66 69 6D 75 6D 00 05 00 0B 00 00 ; ..Ginfimum......
000d0070h: 73 75 70 72 65 6D 75 6D 04 05 06 00 00 00 10 FF ; supremum.......ÿ
000d0080h: EF 63 63 63 63 63 63 62 62 62 62 62 61 61 61 61 ; ïccccccbbbbbaaaa
000d0090h: 07 03 02 00 00 18 FF E9 63 63 63 61 61 61 61 61 ; ......ÿécccaaaaa
000d00a0h: 61 61 01 01 01 00 00 20 00 0B 62 61 0A 03 01 00 ; aa..... ..ba....
000d00b0h: 00 00 28 FF E3 63 62 62 62 61 61 61 61 61 61 61 ; ..(ÿãcbbbaaaaaaa
000d00c0h: 61 61 61 00 00 00 00 00 00 00 00 00 00 00 00 00 ; aaa.............




Let's reformat this page into the correct fields as seen by InnoDB:

0000: 35567104           -> FIL_PAGE_SPACE_OR_CHKSUM
0004: 00000034           -> FIL_PAGE_OFFSET                                    
0008: FFFFFFFF           -> FIL_PAGE_PREV                                      
0012: FFFFFFFF           -> FIL_PAGE_NEXT                                       
0016: 000000000000BD92   -> FIL_PAGE_LSN
0024: 45BF               -> FIL_PAGE_TYPE  (#define FIL_PAGE_INDEX 17855)
0026: 0000000000000000   -> FIL_PAGE_FILE_FLUSH_LSN
0034: 00000000           -> FIL_PAGE_ARCH_LOG_NO_OR_SPACE_ID

0038: 0002               -> PAGE_N_DIR_SLOTS
0040: 00C3               -> PAGE_HEAP_TOP   (195 ...)
0042: 8006               -> PAGE_N_HEAP  (6 records in heap (remove 15th bit)
0044: 0000               -> PAGE_FREE
0046: 0000               -> PAGE_GARBAGE
0048: 00B5               -> PAGE_LAST_INSERT
0050: 0005               -> PAGE_DIRECTION  (PAGE_NO_DIRECTION)
0052: 0000               -> PAGE_N_DIRECTION
0054: 0004               -> PAGE_N_RECS
0056: 0000000000000305   -> PAGE_MAX_TRX_ID (773)
0064: 0000               -> PAGE_LEVEL
0066: 0000000000000011     -> PAGE_INDEX_ID ( Page may be an index page where index id is 0 277385)
0074: 000000000000000215F2 -> PAGE_BTR_SEG_LEAF
0084: 00000000000000021532 -> PAGE_BTR_SEG_TOP

infimum:
0094: 01                -> info_bits=0, n_owned=1 (always 1 for the infimum)
0095: 00                -> heap number
0096: 02                -> status bits
0097: 0047              -> next record (71 bytes)
0099: 696E66696D756D00  -> "infimum"

supremum:
0107: 05000b            -> extra bytes
0110: 0000              -> next record, zero since supremum is always last
0112: 73757072656D756D  -> "supremum"

index row1:
0120: 040506            -> field offsets, starting with the last field.
0123: 00000010          -> extra bytes
0127: FFEF              -> offset to next record (17 bytes back (offset 112))
0129: 636363636363      -> 'cccccc' (keypart1)
0135: 6262626262        -> 'bbbbb'  (keypart2)
0140: 61616161          -> 'aaaa'   (primary key appended)

index row2:
0144: 0703              -> field lengths, starting with the last field (excluding null!).
0146: 02000018          -> extra bytes
0150: FFE9              -> offset to next record (23 bytes back (offset 129))
0152: 636363            -> 'ccc' (keypart1)
0155: 61616161616161    -> 'aaaaaaa' (primary key appended)

index row3:
0162: 0101              -> field lengths, starting with the last field (excluding null!).
0164: 01000020          -> extra bytes
0168: 000B              -> offset to next record (11 bytes (offset 181))
0170: 62                -> 'b' (keypart2)
0171: 61                -> 'a' (primary key appended)

index row4:
0172: 0A0301            -> field lengths
0175: 00000028          -> extra bytes
0179: FFE3              -> offset to next record (29 bytes back (offset 152!))
0181: 63                -> 'c' (keypart1)
0182: 626262            -> 'bbb' (keypart2)
0185: 61616161616161616161 -> 'aaaaaaaaaa' (primary key appended)

explanation of "extra bytes" still to be done

how to debug a mysqld core file from an rpm install

2008-08-21T21:25:00.005+02:00

You have a typical rpm installation of mysql, and the process is crashing. Here are the basic steps needed to find out more info about a crash:

Configure the OS to be able to create corefiles. (Redhat details), (Solaris details)
Tell mysqld to create a corefile by adding the following options to my.cnf:

[mysqld_safe]
core-file-size=unlimited

[mysqld]
core-file

Usually the corefile will be created in the datadir with a name like core.2921 where 2921 was the pid of the running process. The location is configurable on most OS's.

You'll need the following to study the core file:

exact mysqld binary that created the core file
the core file
the glibc version of the original system (rpm -qa|grep -i glibc)
the debuginfo package corresponding to the original mysql rpms.

Let's go through a hypothetical example next.
On my server I have installed MySQL-server-community-5.0.67-0.rhel5.x86_64.rpm and it's been crashing. I have a corefile called core.12345 which I've moved to a test system because I don't want to impact production while playing around with it.

On the production server we have glibc 2.3.4-2.36 installed. So to setup the test box to study the core I do this:

From dev.mysql.com download the MySQL-community-debuginfo-5.0.67-0.rhel5.x86_64.rpm
Download the glibc-2.3.4-2.36.x86_64.rpm from somewhere (in case test system isn't running same version). Next we extract the RPMS and launch gdb and tell it the path to load libraries and symbol files:

rpm2cpio MySQL-community-debuginfo-5.0.67-0.rhel5.x86_64.rpm | cpio -idvu
rpm2cpio glibc-2.3.4-2.36.x86_64.rpm | cpio -idvu

gdb ./mysqld --core ./core.12345
set solib-absolute-prefix .
file ./usr/lib/debug/usr/sbin/mysqld.debug

From here you should get reasonable output from GDB, such as "thread apply all bt" and "bt full" and continue to examine the corefile...

gypsy is resumed

2008-07-04T16:28:00.005+02:00

In search of better qa tools, i have resumed work on my gypsy. Within hours i verified a bug i thought was not possible any time soon...

crash on prepared statement + cursor + geometry + too many open files !

The code is also in launchpad (bzr branch lp:gypsy) if anybody cares.

innodb plugin and new features!

2008-04-16T20:50:00.003+02:00

check it out:
the announcement

plugin documentation

o) Fast Index Creation in the InnoDB Storage Engine
o) InnoDB Data Compression
o) InnoDB File Format Management
o) InnoDB INFORMATION_SCHEMA tables

yay!! gonna test the compression immediately :)

putting it all together

2007-10-23T20:40:00.000+02:00

Last post was about Rainbow testing. So that's old news, and I lost count of the number of bugs it found, and have been fixed. Probably 30+ crashes.

Now, I have to put together all these odds & ends of code I wrote disparately over the last 18 months into a single collection to enable complete end-to-end testing.

I have now got roughly the following:

o) random table maker
o) query maker based on any tables, (using predefined rules)
o) data generator for any tables
o) complete charset collection for each valid character
o) database of mysql functions, data types
o) multi-threaded testing environment for any queries
o) query results comparer for any queries
o) rainbow, which will provide help in making good coverage of functions, etc.

What's needed still? Well, I would like 56 hours in a day ... More posts later when v0.001 of the integrated is semi-functional :)

mysql crash log analyzer ?

2007-09-19T17:05:00.000+02:00

So with over 1000 crashes in my logs from just one night of simple queries, I have a painful time to find new crashes in the 90MB file. So I'm taking a detour on the rainbow query generator for 2 days. Will be writing an error log analyzer instead :)


step 1: upload the mysqld and the mysqld.sym file for the version you're working with.
step 2: import the binary and symbols into a mysql table
step 3: upload the error log
step 4: parse the error log into seperate crashes
step 5: find the stack traces for each crash, and resolve them using the symbols
step 6: determine if this crash is matching any existing crashes.

With thousands of crashes on various builds of mysqld, the above system can be useful to me. Also, I'd import all the crashes from reports on bugs.mysql.com for searching purposes. This toy will allow me to identify whether a crash is new, or it's been seen before.

some results of rainbow

2007-09-19T13:45:00.000+02:00

ok folks. here's some results:



mysql> select last_errno,count(*) from 
queryqueue group by last_errno;
+------------+----------+
| last_errno | count(*) |
+------------+----------+
|          0 |  1600796 |
|       1048 |     1971 |
|       1053 |        1 |
|       1139 |       35 |
|       1267 |    19722 |
|       1270 |     4243 |
|       1271 |     8944 |
|       1416 |     2284 |
|       1580 |    23225 |
|       2003 |       28 |
|       2013 |     1606 |
+------------+----------+
11 rows in set (0.00 sec)

error 2013 means lost connection to server (read: server crashed).
so there are many bugs found already. 1606 crashes out of 1.6 million
executed queries, is great.

check my rss feed for the exact bugs ...

good news!

2007-09-12T11:01:00.000+02:00

my girlfriend's grandfather wants a blog!

sql rainbow tables

2007-09-07T09:03:00.000+02:00

I thought of a brilliant QA plan. Create sql rainbow tables! Just trust me, this system of QA will be very powerful in bug finding. Especially important will be the comparison of old/new versions of mysql. Writing a prototype now, on my day off.

Just during prototype development, I've discovered a handful of bugs. I'm testing all functions that are documented in the manual. This is alot that I've written up:


mysql> select count(*),category from func group by category;
+----------+--------------+
| count(*) | category     |
+----------+--------------+
|        6 | arithmetic   |
|        7 | bit          |
|       60 | casting      |
|       47 | comparison   |
|       52 | datetime     |
|       18 | encryption   |
|      127 | geometry     |
|       17 | information  |
|        7 | logical      |
|       32 | mathematical |
|        9 | misc         |
|       47 | string       |
|        2 | xml          |
+----------+--------------+
13 rows in set (0.00 sec)

Let me explain this rainbow tables concept with a simple example.
Suppose we have a function, like "GREATEST()".

I run a query like this:

SELECT GREATEST(col1,col2,col3) FROM table0;

The columns col1,col2,col3 will form any combination of column type. So we have int, date, string, blob, spatial! Given a combination of all datatypes and all function parameters, it leaves us with a good few million queries. Of course, a few million queries is not so much for a machine to execute quickly..

cross-check results using triggers and views

2007-08-26T19:47:00.001+02:00

I've been struggling to come up with a decent prototype for the self-verifying random testcases I wrote about earlier. In the mean time, I wrote a set of triggers and a view which should yield the same information, no matter what you do to the underlying table. If they don't, there's a bug in the server.

The test table, t1 is simple. It has an int and a varchar column. There are triggers after insert/update/delete. The triggers update an evolving summary table.

The evolving summary table maintains the average+sum value of the int, and the average+sum length of the varchar field. The view selects these values from the table too.

To test it, I ran 50 threads of random insert/update/delete queries to table t1 for a few minutes. Then after the test had stopped I confirmed the results matched. (i.e. the running totals had been correctly maintained - if they match the view).

Here's the setup of table t1, the running summary table, and the view

Next, I hit the server with random update/insert/delete for a few minutes:


- completed spawning new database worker threads
- 15 threads running, 0003961 successful queries. (330.083333 QPS).
- 15 threads running, 0005334 successful queries. (114.416667 QPS).
- 15 threads running, 0006206 successful queries. (72.666667 QPS).
- 15 threads running, 0006783 successful queries. (48.083333 QPS).
- 15 threads running, 0007779 successful queries. (83.000000 QPS).
- 15 threads running, 0008981 successful queries. (100.166667 QPS).
- 15 threads running, 0010393 successful queries. (117.666667 QPS).
- 15 threads running, 0010979 successful queries. (48.833333 QPS).
- 15 threads running, 0011373 successful queries. (32.833333 QPS).
- 15 threads running, 0011875 successful queries. (41.833333 QPS).
- 15 threads running, 0012399 successful queries. (43.666667 QPS).
- 15 threads running, 0012870 successful queries. (39.250000 QPS).
- 15 threads running, 0013566 successful queries. (58.000000 QPS).
- 15 threads running, 0013775 successful queries. (17.416667 QPS).
- 15 threads running, 0014001 successful queries. (18.833333 QPS).
- 15 threads running, 0014265 successful queries. (22.000000 QPS).
- 15 threads running, 0014869 successful queries. (50.333333 QPS).
- 15 threads running, 0015325 successful queries. (38.000000 QPS).
- 15 threads running, 0016425 successful queries. (91.666667 QPS).
- 15 threads running, 0016743 successful queries. (26.500000 QPS).
- 15 threads running, 0016919 successful queries. (14.666667 QPS).
- 15 threads running, 0017180 successful queries. (21.750000 QPS).
- 15 threads running, 0017448 successful queries. (22.333333 QPS).
- 15 threads running, 0017745 successful queries. (24.750000 QPS).
- 15 threads running, 0017997 successful queries. (21.000000 QPS).
- 15 threads running, 0018095 successful queries. (8.166667 QPS).
- waiting for threads to finish

And - let's see if the results match up.


mysql> select * from t1_summary;
+--------------+-------------+-----------------+--------------------+-----------------+
|num_elements  | sum_id      | sum_length_name | avg_id             | avg_length_name |
|     10237    | 76231668630 |         1198066 | 7446680.5343377098 |  117.0329195294 |
+--------------+-------------+-----------------+--------------------+-----------------+
1 row in set (0.00 sec)

mysql> select * from t1_view;
+-------------+-----------------+--------------+-----------------+
|sum_id       | sum_length_name | avg_id       | avg_length_name |
+-------------+-----------------+--------------+-----------------+
|76231668630  |         1198066 | 7446680.5343 |        117.0329 |
+-------------+-----------------+--------------+-----------------+
1 row in set (0.05 sec)

Yup, they do :) What have I actually tested here ?? Hm. At least one thing. The trigger's execution didn't miss anything. Why is this first step important ?? Because my program doesn't know the correct answer to the above 2 queries. It sends random garbage to server, hence it doesn't know how to verify a result. Having the server keep a running total, and comparing that to a final total from the view, is some very small assurance I think.

Next step will be to use more detailed functions instead of SUM and AVG. Something whereby the order of execution will matter... More on this later.

how to undelete rows from a fixed length myisam table

2007-08-25T09:09:00.000+02:00

You have inadvertently deleted some rows from your table and want them back. This is semi-doable with fixed row format of MyISAM. I put together a few steps, which I'll compliment with a program that does it for you, later.

save output of SHOW TABLE STATUS LIKE 't1' and SHOW CREATE TABLE `t1`.
shutdown mysql server asap!
backup t1.frm, t1.MYI, t1.MYD immediately
create a new table t1_recover, which has no auto-inc and no unique/pk.
remove the files t1_recover.MYD and t1_recover.MYI
write a C program that scans through t1.MYD reading blocks of length Avg_row_length and checking if first byte indicates a row is marked as deleted.
if it's deleted, dump it as is into the file t1_recover.MYD
goto mysql prompt. issue REPAIR TABLE `t1_recover` USE_FRM

Some notes.

You cannot recover entire record. You'll lose first 6 bytes of each record (or how every long data pointer length is). Typically, this is the first 2 int columns trashed.

You cannot determine which columns contained NULL in the recovered records (assuming some columns are nullable).

If you anticipate to have to use this recovery method often, then you can create a fake char(9) column at the beginning of the table, so that when a row is deleted, this column will be overridden instead of your real data..

Here is the code! myisam undeleter

Example usage below:
1) create a table and delete some records:


mysql> create table mydel(id int, name char(15), address char(15), bday datetime, daysleft decimal(10,5));
Query OK, 0 rows affected (0.06 sec)

mysql> insert into mydel values (1,'shane','down south','2005-09-01',10.5);
Query OK, 1 row affected (0.01 sec)

mysql> insert into mydel values (2,'susan car','up north','2001-02-01',14.1);
Query OK, 1 row affected (0.00 sec)

mysql> insert into mydel values (3,'bobby scott','chinatown','1976-12-21',55.5);
Query OK, 1 row affected (0.00 sec)

mysql> delete from mydel where id=2 or id=3;
Query OK, 2 rows affected (0.00 sec)

mysql> flush tables;
Query OK, 0 rows affected (0.00 sec)

mysql> show table status;
+--------+--------+------------+------+----------------+-------------+
| Name   | Engine | Row_format | Rows | Avg_row_length | Data_length |
+--------+--------+------------+------+----------------+-------------+
| mydel  | MyISAM | Fixed      |    1 |             49 |         147 |
+--------+--------+------------+------+----------------+-------------+

2) next, build and run the app:


> gcc -o undeleter -lm ./undeleter.c
>
> ./undeleter /5.1/data/test/mydel.MYD /5.1/data/test/mydel_recover.MYD 49
allocating a block of memory for records, 49 bytes
starting to read records
found deleted record at offset 49
found deleted record at offset 98
-----------------
 completed 
-----------------
records copied into '/5.1/data/test/mydel_recover.MYD': 2
records present in '/5.1/data/test/mydel.MYD': 1

next steps:
1. remove the MYI for '/5.1/data/test/mydel_recover.MYD'
2. make sure '/5.1/data/test/mydel_recover.MYD' definition .frm is created without any unique or PK keys
3. repair table  use_frm

3) next, sort out the recovered table


sbester@www:/5.1/data/test> cp ./mydel.frm ./mydel_recover.frm



mysql> repair table mydel_recover use_frm;
+--------------------+--------+----------+------------------------------------+
| Table              | Op     | Msg_type | Msg_text                           |
+--------------------+--------+----------+------------------------------------+
| test.mydel_recover | repair | warning  | Number of rows changed from 0 to 2 |
| test.mydel_recover | repair | status   | OK                                 |
+--------------------+--------+----------+------------------------------------+
2 rows in set (0.00 sec)

mysql> select * from mydel_recover;
+------+-------------+-----------+---------------------+----------+
| id   | name        | address   | bday                | daysleft |
+------+-------------+-----------+---------------------+----------+
|   -1 |   san car   | up north  | 2001-02-01 00:00:00 | 14.10000 |
|    0 |  ☺bby scott | chinatown | 1976-12-21 00:00:00 | 55.50000 |
+------+-------------+-----------+---------------------+----------+
2 rows in set (0.00 sec)

Notice! I just cp the .frm. That's only because I didn't need to strip out the
PK or auto-increment column. As you seen, `id` is trashed. `name`
is partially trash. the `id` would have caused alot of duplicate key
errors if you still had a PK.

More information here: MySQL_Internals_MyISAM

new direction for test development

2007-08-21T19:26:00.000+02:00

I've been thinking about this today. My attempts thus far to write random queries which stress various parts of the server have worked, and served a purpose - but have been rather huge and clumsy.

For example a 5 union select, each comprising of 7 joins did have it's value.. The problem with huge random queries is simply that the results cannot be verified as easily as they were constructed (unless you run the same on various DBMS). These huge tests are mostly only good for checking if the server crashes.

Now, I wish to try write testcases that have these properties:

small
results are self-verified
each test is random, but reproducible given a seed value

Tonight I'll throw together a code-generator to do simple insert/select and post any interesting results here later.

a moment in time

2007-08-13T20:18:00.000+02:00

I pulled the latest 5.1BK sources today and built mysqld. I must admit, it fared pretty well against my little charset tester. 0 failures and over 120 tests done which took >5 hours.

To give a clue to the score last time I run the same tests, here are the bugs I opened!

load data infile into table with big5 chinese fulltext index hangs 100% cpu

corruption with character set macce collate macce_bin

myisam corruption with character set cp932 collate cp932_japanese_ci

repeatable myisam fulltext index corruption

repeatable innodb and myisam corruption

sad news

2007-08-12T09:57:00.000+02:00

my girlfriend hates blogs :(

That error 127 MyISAM bug finally...

2007-07-24T22:08:00.000+02:00

Gotcha: Bug #29838

The bug itself seems so simple to repeat. I'm boggling how it was not seen before. :-0 I really tried too many overly-complex tests, IMHO. Sometimes, it's still best to keep it simple!

that key_cache bug, 17332

2007-05-24T11:03:00.000+02:00

This massive fix has been pushed into 5.1.19 and so far I cannot repeat any crashes!! Well done Ingo and reviewers ! My testing continues!

changing key_buffer_size on a running server can crash under load

Using 'insert delayed into ... '?

2007-05-21T10:44:00.000+02:00

Think again!. There are many corruptions, crashes, and hangs caused by insert delayed statements. Be especially cautious of using an old version of mysql to do delayed inserts in combination with triggers, stored routines, and merge tables.

Bug #28280 - insert delayed on a table containing trigger leads to server crash

Bug #27998 - mysqld crashed when executing INSERT DELAYED on a BLACKHOLE table

Bug #26464 - insert delayed + update + merge = corruption

Bug #26445 - MySQL crash: drop trigger and insert delayed

Bug #26238 - inserted delayed always inserts 0 for BIT columns

Bug #25712 - insert delayed and check table run together report crashed tables

Bug #25507 - multi-row insert delayed + auto increment causes duplicate key entries on slave

Bug #23312 - server hangs 'closing tables' with insert delayed,flush tables,alter table

Bug #21483 - Server abort or deadlock on INSERT DELAYED with another implicit insert

Bug #16218 - Crash on insert delayed

partition maintenance?

2007-05-20T17:18:00.000+02:00

It seems doing any partition maintenance in combination with some concurrent workload will fail with many different errors in 5.1. For more or less the same underlying lack of locking, I've filed a few bugs.

To cause a myisam table corruption or server crash (or innodb assert) all you need is 1 thread inserting, and 1 thread altering/optimizing partitions: Of course, the more threads the easier the problems will happen..

Bug #28477
Bug #28487
Bug #28488
Bug #28489
Bug #28490

to get started

2007-05-19T14:30:00.000+02:00

A short list of some recent bug reports opened by me.

bug #28519 falcon crash with signal 4

bug #28492 subselect returns LONG in >5.0.24a and LONGLONG in <=5.0.24a

bug #28490 crash in handler.cc, handler::print_error(int error, myf errflag)

bug #28489 spurious out of memory message in comment of show table status

bug #28488 Incorrect information in file: './test/t1_test#.frm'

bug #28487 during alter table .. add partition temporary tables are visible to users

bug #28477 innodb assertion and crash during alter table to add/drop partitions

bug #28476 force index on a disabled myisam index gives error 124

bug #28414 please add more useful information to error logs when corruption occurs

bug #28375 mysql crash with subselect and null values

bug #28280 insert delayed on a table containing trigger leads to server crash

bug #28272 server crash during EXPLAIN SELECT ..

bug #28254 innodb crash if shutdown during innodb_table_monitor is running

bug #28211 RENAME DATABASE and query cache don't play nicely together

bug #27860 parser doesn't handle memory well for large queries. crashes server

bug #27854 'mysqladmin debug' command invokes 64bit unaware mallinfo()

bug #27643 query failed : 1114 (The table '' is full)

bug #27594 Can't find file: '.\db1\t1.frm' (errno: 13)

bug #27592 stack overrun when storing datetime value using prepared statements

bug #27516 divide by zero crash during optimize table