maria-developers team mailing list archive

[Alex Budovski <abudovski@xxxxxxxxx>]

Re: my_thread_init

I tried reverting my change and looking at the code again -- perhaps
we have a different bug.

The function does indeed set 'id' to a non-zero value (tmp->id =
++thread_count), but then it is reset to 0 by someone else.

Let me show you:

First of all, we hit a verifier stop telling us a CS was already initialized:

=======================================
VERIFIER STOP 00000211: pid 0xEEC: Critical section is already initialized.

        03338FA0 : Critical section address.
        03DF2FE0 : Critical section debug info address.
        00000000 : First initialization stack trace. Use dps to dump
it if non-NULL
        00000000 : Not used.
=======================================

Let's look at the current call stack to see who is attempting to
re-initialize it:

0012f5e8 009ff49e 03338fa0 0012f62c 00cccccc
kernel32!InitializeCriticalSection+0xe
0012f608 0089670f cccccccc cccccccc cccccccc
mysqld!my_thread_init+0x6e  <-- here.
0012f624 008745f9 0012f654 00000001 00000000 mysqld!myxt_create_thread+0x1f
0012f648 004d46f5 04669f60 0012f6e4 0012f6ac mysqld!pbxt_init+0x3f9
<-- from PBXT
0012f6a0 00471f97 03ccbbc8 0012f86c 0012f784
mysqld!ha_initialize_handlerton+0xa5
0012f6e4 00471cf1 03ccbbc8 cccccccc 00000000 mysqld!plugin_initialize+0x67
0012f86c 00447d44 00eae4d8 03f15cf8 00000000 mysqld!plugin_init+0x541
0012fb7c 0044595c 0012ff6c 0012fd44 cccccccc mysqld!init_server_components+0x5c4
0012fd30 00448a08 0000000b 03cdae70 0012ff6c mysqld!win_main+0x1cc
0012fd40 00448d7a 00000000 00250178 00000000 mysqld!mysql_service+0x38
0012ff6c 00401137 0000000b 03cdae70 03cdce10 mysqld!main+0x35a
0012ffb8 0040100f 0012fff0 7c817077 00250178 mysqld!__tmainCRTStartup+0x117
0012ffc0 7c817077 00250178 00000000 7ffd4000 mysqld!mainCRTStartup+0xf
0012fff0 00000000 00401000 00000000 78746341 kernel32!BaseProcessStart+0x23

Now let's see who initialized it first:

0x7c809f9f: kernel32!InitializeCriticalSection+0xE
0x009ff49e: mysqld!my_thread_init+0x6E  <-- here
0x009ff077: mysqld!my_thread_global_init+0x77
0x009f4c9b: mysqld!my_init+0x9B
0x004457c7: mysqld!win_main+0x37
0x00448a08: mysqld!mysql_service+0x38
0x00448d7a: mysqld!main+0x35A
0x00401137: mysqld!__tmainCRTStartup+0x117
0x0040100f: mysqld!mainCRTStartup+0xF
0x7c817077: kernel32!BaseProcessStart+0x23

Looks like its called during process startup/initialization.

Let's look at *tmp at this point in time:

Local var @ 0x12f600 Type st_my_thread_var*
0x03338f70
   +0x000 thr_errno        : 13
   +0x004 suspend          : pthread_cond_t
   +0x030 mutex            : _RTL_CRITICAL_SECTION
   +0x048 current_mutex    : (null)
   +0x04c current_cond     : (null)
   +0x050 pthread_self     : (null)
   +0x054 id               : 0  <-- ID is zero!
   +0x058 cmp_length       : 0
   +0x05c abort            : 0
   +0x060 init             : 1 '' <-- but it is initialized!
   +0x064 next             : (null)
   +0x068 prev             : (null)
   +0x06c opt_info         : (null)
   +0x070 lock_type        : 0
   +0x074 stack_ends_here  : 0x000e7590
   +0x078 mutex_in_use     : (null)
   +0x07c dbug             : 0x03eecfc8
   +0x080 name             : [11]  "T@1"  <-- notice the name has @1,
so its ID _was_ set at some point.

So it was reset by someone else, after being initialized, causing the
"if (THR_KEY_mysys.id)" to fail and re-initialize the CSs (there's
more than one).

So let's see who is writing to it: (by setting a data breakpoint on
0x03338f70+0x054)

ChildEBP RetAddr
0012f608 008967fa mysqld!THD::store_globals+0xa4 <-- here
0012f624 008745f9 mysqld!myxt_create_thread+0x10a
0012f648 004d46f5 mysqld!pbxt_init+0x3f9
0012f6a0 00471f97 mysqld!ha_initialize_handlerton+0xa5
0012f6e4 00471cf1 mysqld!plugin_initialize+0x67
0012f86c 00447d44 mysqld!plugin_init+0x541
0012fb7c 0044595c mysqld!init_server_components+0x5c4
0012fd30 00448a08 mysqld!win_main+0x1cc
0012fd40 00448d7a mysqld!mysql_service+0x38
0012ff6c 00401137 mysqld!main+0x35a
0012ffb8 0040100f mysqld!__tmainCRTStartup+0x117
0012ffc0 7c817077 mysqld!mainCRTStartup+0xf
0012fff0 00000000 kernel32!BaseProcessStart+0x23

THD::store_globals() does the following:

  mysys_var=my_thread_var;
  mysys_var->id= thread_id;  // Let's see what this->thread_id is.

2:005> ?? this->thread_id
unsigned long 0

So here it gets set to 0, and hence our code fails.

Do you know why this might be?

- Alex

On Sat, Jan 30, 2010 at 9:40 AM, Alex Budovski <abudovski@xxxxxxxxx> wrote:
> Hi,
>
>> I looked at the original bug report and can't see how this bug fix
>> have anything to the with the real problem.
>>
>> I have now done a proper fix for this. Can you please test that things
>> reported in http://bugs.mysql.com/bug.php?id=31173 now works
>> on windows ?
>>
>
> Yes, looks like the change works. Thanks for fixing it!
>
>>
>>> === modified file 'mysys/my_thr_init.c'
>>> --- mysys/my_thr_init.c       2010-01-29 10:45:51 +0000
>>> +++ mysys/my_thr_init.c       2010-01-29 14:32:36 +0000
>>> @@ -317,7 +317,7 @@
>>>    /*
>>>      Skip initialization if the thread specific variable is already initialized
>>>    */
>>> -  if (THR_KEY_mysys.id)
>>> +  if (THR_KEY_mysys.init)
>>>      goto end;
>>>    tmp= &THR_KEY_mysys;
>>>  #endif
>>
>> I don't see checking the id would not work, as the id is guaranteed to
>> always be > 0
>
> Hmm.. If I recall correctly, id was in fact 0 when I ran it through a debugger.
>
> The reason I think the field was incorrect is because the function does
>
>  tmp->init= 1;
>
> to signify that the thread-local variable has been initialized. (Where
> tmp == &THR_KEY_mysys).
>
> But the check to prevent re-initialization checks a completely
> different field (id), and when I was debugging it, was 0 at the time,
> causing the code to be entered again.
>
>>
>> The only difference I see is that if you call my_thread_end() then
>> init will be reset so it will be safe to call my_thread_init() again.
>>
>> I will do the change based on this assumption.
>>
>> If there is another reason for this change, please let me know.
>>
>> <cut>
>>
>> All other things looked good.
>>
>> I am now applying all your changes except the above, as a diff but
>> with your comments, to MariaDB 5.1.  I will push it later today.
>>
>
> Thanks a lot!
>
> - Alex
>