MySQL Bugs: #35514: Item_func_uuid::val_str(String*): Assertion `tv > uuid

Bug #35514	Item_func_uuid::val_str(String*): Assertion `tv > uuid_time' failed.
Submitted:	24 Mar 2008 16:26	Modified:	4 Dec 2008 4:37
Reporter:	Philip Stoev	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: DML	Severity:	S2 (Serious)
Version:	6.0-falcon-team	OS:	Any
Assigned to:	Tatiana Azundris Nuernberg	CPU Architecture:	Any

Description:
When executing a concurrent DML workload, the server crashed as follows:

#0  0x00110402 in __kernel_vsyscall ()
#1  0x00bdc617 in pthread_kill () from /lib/libpthread.so.0
#2  0x084471a7 in write_core (sig=6) at stacktrace.c:305
#3  0x082a2097 in handle_segfault (sig=6) at mysqld.cc:2598
#4  <signal handler called>
#5  0x00110402 in __kernel_vsyscall ()
#6  0x00a6e690 in raise () from /lib/libc.so.6
#7  0x00a6ff91 in abort () from /lib/libc.so.6
#8  0x00a6793e in __assert_fail () from /lib/libc.so.6
#9  0x0822a839 in Item_func_uuid::val_str (this=0xa039518, str=0xa039a1c) at item_strfunc.cc:3630
#10 0x082038ab in Item_func_set_user_var::check (this=0xa039598, use_result_field=false) at item_func.cc:4147
#11 0x082c5d2b in set_var_user::check (this=0xa039a80, thd=0xa9b43be8) at set_var.cc:3435
#12 0x082c5daf in sql_set_variables (thd=0xa9b43be8, var_list=0xa9b45234) at set_var.cc:3284
#13 0x082b6554 in mysql_execute_command (thd=0xa9b43be8) at sql_parse.cc:3190
#14 0x082bb89a in mysql_parse (thd=0xa9b43be8, inBuf=0xa039498 "SET @uuid2 = UUID()", length=19, found_semicolon=0xa9c8c270) at sql_parse.cc:5643
#15 0x082bc2b3 in dispatch_command (command=COM_QUERY, thd=0xa9b43be8, packet=0xa9b71039 "SET @uuid2 = UUID()", packet_length=19) at sql_parse.cc:1030
#16 0x082bd432 in do_command (thd=0xa9b43be8) at sql_parse.cc:722
#17 0x082aad46 in handle_one_connection (arg=0xa9b43be8) at sql_connect.cc:1122
#18 0x00bd750b in start_thread () from /lib/libpthread.so.0
#19 0x00b18b2e in clone () from /lib/libc.so.6

In the error log:

mysqld: item_strfunc.cc:3630: virtual String* Item_func_uuid::val_str(String*): Assertion `tv > uuid_time' failed.

How to repeat:
Test case will hopefully follow shortly.

Suggested fix:
(gdb) print tv
$1 = 12185947646947300
(gdb) print uuid_time
$2 = 12185947646947300

Maybe it is OK for those two variables to be equal. This test was conducted in a virtual machine, where clock speed and behavoir is basically unpredictable. Virtual machines should not break the server though.

Test case for bug 35514

Attachment: bug35514.test (application/octet-stream, text), 410 bytes.

A test case is now available - no concurrency is required, MyISAM is the only required engine.

Sergei, I see that this code segment was added to fix "UUID() bug that manifests itself on low-res timers only, does not result in duplicate values". If the assertion is hit, does it mean that a duplicate value is possible?

The VMWare Knowledge Base lists so many situations of clock drift in a virtual machine, I wonder how one can even reliably generate UUID() values in such environment.

no, duplicate UUID values should never be possible.

Assert was documenting the assumption that one can not call UUID() more often than 10 times per microsecond. In fact, one can, of course, an assert is wrong.

The fix should be to replace assert with if() and a delay/sleep to enforce the above limitation.

Based on Sergei's analysis, here is a simple one-line test that causes the crash, suitable as a regression test:

--disable_query_log
SELECT UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID(), UUID();
--enable_query_log

It turns out that if the assertion is commented out, duplicate UUID values will be generated.

FWIW, another option is to generate UUIDs based on pseudo-random numbers (RFC 4122). For example, the Mersenne Twister is a pretty fast PRNG and is BSD licensed.

Fixing along with Bug#35848: "UUID() returns UUIDs with the wrong time"

Updated combine-patchset over in Bug#35848 "UUID() returns UUIDs with the wrong time"

pushed to 5.0.68-bugteam, 5.1.28-bugteam, 6.0.7-bugteam, 1/3 in multi-CS Bug#35848, Bug#35514, Bug#38160

status of ticket was not auto-updated correctly
due to multi-patch.  see Bug#35848 for ChangeSet IDs.