View Issue Details

IDProjectCategoryView StatusLast Update
0000572MySQL v5 for OS/2 & eComStationBugpublic2022-05-24 18:38
Reporterasavage Assigned Topsmedley  
PriorityhighSeveritycrashReproducibilityalways
Status closedResolutionfixed 
Platformx86OSWSAOS Version3.0 with updates
Summary0000572: mysqld dies silently
Descriptionv5.1.72 (was v5.1.68)

After some period of uptime, varying from an hour to a day, mysqld dies with nothing logged to the console or error log.

Console replay:
=========================================================
[F:\mysql51]cd bin

[F:\mysql51\bin]MySQLd.exe --basedir=F:\MySQL51
--datadir=F:\MySQL51\data --log-error --default-storage-engine=MyISAM --skip-innodb
TlsAllocThreadLocalMemory error: init already done!

[F:\mysql51\bin]
=========================================================

Contents of error log after above:
=========================================================
130422 10:12:15 [Note] Plugin 'InnoDB' is disabled.
130422 10:12:15 [Note] Event Scheduler: Loaded 0 events
130422 10:12:15 [Note] MySQLd.exe: ready for connections.
Version: '5.1.68' socket: '\socket\MySQL' port: 3306 Source
distribution
UNIX Socket is \socket\MySQL
=========================================================
Steps To ReproduceSee above.
Additional InformationWith no more information coming from the module or log, I do not know how to proceed with this.

SUT is Warp Server Advanced with HPFS386, kernel is 14.104a_W4, processor is old Athlon 1Ghz, 1Mb RAM. It is not a generally highly-loaded system, but it is in production, FWIW. I can probably run mysqld on another box and point the server to the alternate box, if necessary.
TagsNo tags attached.
Attached Files
0087_04.TRP (129,851 bytes)
007A_06.TRP (130,360 bytes)
007A_06-shl-annotated.TRP (131,265 bytes)
PDUMP.001.txt (5,731 bytes)   
IBM OS/2 Dump Formatter for a retail or an hstrict UNI kernel.
Formatter is --> Internal revision 14.106_W4
Dump file is --> Internal revision 14.106_W4 (process dump)

Symbol (d:\devtools\pmdf\14_106_w4_slamain\os2krnlr.sym) linked

Current slot number: 00ca

 Slot  Pid  Ppid Csid Ord  Sta Pri  pTSD     pPTDA    pTCB     Disp SG Name
*00ca# 2320 231f 2320 0001 blk 0300 f995c000 f9d5d600 f9cb7ec0 0eb4 13 MYSQLD

eax=00000000 ebx=0000efc0 ecx=00eb0053 edx=00000000 esi=00e7f68c edi=297a0000
eip=1ffca259 esp=00ebeb38 ebp=00ebec64 iopl=2 -- -- -- nv up ei pl nz ac po cy
cs=005b ss=0053 ds=0053 es=0053 fs=150b gs=0000  cr2=00000000  cr3=00000000
005b:1ffca259 83c410         add       esp,+10


# .p
 Slot  Pid  Ppid Csid Ord  Sta Pri  pTSD     pPTDA    pTCB     Disp SG Name
*00ca# 2320 231f 2320 0001 blk 0300 f995c000 f9d5d600 f9cb7ec0 0eb4 13 MYSQLD
 0061  2320 231f 2320 0002 run 0300 f98f3000 f9d5d600 f9ca48ac 0af8 13 MYSQLD

Slot 61 (i.e. ord 2) should have exited by the time the main thread complained

#            Checking call gates for all slots
Slot MYSQLD     61:
 is in a call to:
%1ffc6eac DOSCALL1 DOS32DUMPPROCESS
Slot MYSQLD     ca:
 is in a call to:
%1ffc6f5c DOSCALL1 DOS32EXCEPTIONCALLBACK

# %findsym esp l1000
Finding from 00ebeb38 to 00ebfb38
EBEC68: 1ffca692 = DOS32UNWINDEXCEPTION + 5a
EBECA4: 1ffca2aa = _xcptExecuteUserExceptionHandler + 46
EBECA8: 1ffc1b27 = DOS32UNSETEXCEPTIONHANDLER + 3b
EBECB0: 1ffca2c9 = _xcptExecuteUserExceptionHandler + 65
EBECC4: 1ffca2ec = _xcptR3ExceptionHandler
EBECE0: 1ffc9f56 = _xcptR3ExceptionDispatcher + 10e
EBED18: 1ffc9e26 = DOS32R3EXCEPTIONDISPATCHER + 12e
EBED30: 1ffc9e26 = DOS32R3EXCEPTIONDISPATCHER + 12e
EBED4C: 1fb965d2 = CharRect32 + 5be
EBED80: 1ffc1b27 = DOS32UNSETEXCEPTIONHANDLER + 3b
EBED84: 1cd49a5c = ulAvioFontMaxHeight + 40
EBED88: 1fc230f9 = PRF32QUERYPROFILESTRING + 1ad
EBED9C: 1fbacd30 = ShlExceptionHandler
EBEDB4: 1fc22f72 = PRF32QUERYPROFILESTRING + 26
EBEE80: fff52c04 = _vmFreeMemCtxtOd + 404
EBEEC0: fff53643 = _VMFreeMemOd + 2a3
EBEEC4: ffed0004 = _BufHashTable + 788
EBEEE8: fff6d314 = _VMFreeMem + 164
EBEF40: 1fb9ef4c = AlwaysSBCS
Invalid address type: 409 - 0053:00ebf000
Scan stopped at EBFB39 stopaddr EBFB38

# %k EBEC68-4

00ebec64: Frame 00ebed2c Ret DOS32UNWINDEXCEPTION + 5a
00ebed2c: Frame 00ebee4c Ret DOS32R3EXCEPTIONDISPATCHER + 12e
00ebee4c: Frame 00e7f67c Ret 00000000
00e7f67c: Frame 00e7f69c Ret __exit + 37
00e7f69c: Frame 00e7f6bc Ret _exit + f
00e7f6bc: Frame 00e7f71c Ret _handle_fatal_signal + 21e
00e7f71c: Frame 00e7f7fc Ret __libc_back_signalRaiseInternal + e0c
00e7f7fc: Frame 00e7f88c Ret __libc_Back_signalRaise + 147
00e7f88c: Frame 00e7f90c Ret _libc_Back_exceptionHandler + 103
00e7f90c: Frame 00e7f93c Ret _xcptExecuteUserExceptionHandler + 46
00e7f93c: Frame 00e7f99c Ret _xcptR3ExceptionDispatcher + 88
00e7f99c: Frame 00e7fab8 Ret DOS32R3EXCEPTIONDISPATCHER + 5c
00e7fab8: Frame 00e7fc48 Ret 00000000
00e7fc48: Frame 00e7fe78 Ret _my_end + 47
00e7fe78: Frame 00e7ff80 Ret main + 9d8
00e7ff80: Frame 00e7ffe0 Ret __text + 21
00e7ffe0: Frame 00000000 Ret __init_app + b
Can not access 0 - giving up

# %xcpt

Exception report record at 0328fbd8
ExceptNum c0010002 fHandlerFags 00000000
NestedExceptionReportRecord 00000000
ExceptionAddress 1d0eefa3 cParameters 00000001
P0 00000001

Context record at 0328fbfc
ctxflags 00000007
eax 0000005f ebx 0328fd40 ecx 00000000 edx 00010009 edi 00000000 esi 00007530
esp 0328fd2c ebp 0328fd54 ss  00000053 eip 1d0eefa3 cs  0000005b
gs  00000000 fs  0000150b es  00000053 ds  00000053 eflags 00002246

Exception registration record at 0328ff94
prev ffffffff handler 17441270

Found 1 report records on stack

# .s61 (thread that did not exit)

Current slot number: 0061

# %findsym esp l1000
Finding from 0328f9f0 to 032909f0
328FA1C: 1ffca2aa = _xcptExecuteUserExceptionHandler + 46
328FA3C: 1ffca2ec = _xcptR3ExceptionHandler
328FA4C: 1ffc9ed0 = _xcptR3ExceptionDispatcher + 88
328FA60: 1ffca2ec = _xcptR3ExceptionHandler
328FA88: 1d0cacf2 = _um_lump_alloc + 30a
328FA9C: 1ffc77c1 = HT32_Exit + 5
328FAAC: 1ffc9d54 = DOS32R3EXCEPTIONDISPATCHER + 5c
328FAF4: fff53643 = _VMFreeMemOd + 2a3
328FAF8: ffed0004 = _BufHashTable + 788
328FB1C: fff6d314 = _VMFreeMem + 164
328FB60: 1d0eefa3 = __libc_back_signalWait + be
328FB78: 1d0eab1a = __libc_Back_ioFileOpen + 356
328FBE4: 1d0eefa3 = __libc_back_signalWait + be
328FC2C: fff53643 = _VMFreeMemOd + 2a3
328FC30: ffed0004 = _BufHashTable + 788
328FC54: fff6d314 = _VMFreeMem + 164
328FC98: 1d0eefa3 = __libc_back_signalWait + be
328FCF8: 1d14e280 = __libc_Back_safesemMtxUnlock + 38
328FD28: 1d0eefa3 = __libc_back_signalWait + be
328FD58: 1d0f013e = __libc_Back_signalWait + 17e
328FE08: 1d11c5cd = _std_sigtimedwait + 1d
328FE18: 1d126cee = _um_free_maybe_lock + b2
328FE2C: 1ffc5df9 = DOS32WRITE + 29
328FE38: 1d14dcf4 = __libc_Back_safesemMtxLock + 54
328FE48: 1d14e280 = __libc_Back_safesemMtxUnlock + 38
328FE58: 1d0c8573 = __fmutex_release_internal_must_complete + 33
328FE78: 1d0ef254 = __libc_back_signalSemRelease + 10
328FE7C: 18fdcf68 = __libc_gSignalPending + 438
328FE98: 1d11c6d7 = _std_sigwait + 27
328FF98: 17441270 = MYHANDLER
328FFB8: 1d0f9dd3 = _endthread + 7f
328FFD8: 1d106550 = _libc_Back_exceptionHandler
Scan stopped at 3290A00 stopaddr 32909F0

# %k 328FB60-4
0328fb5c: Frame 0328fd54 Ret __libc_back_signalWait + be
0328fd54: Frame 0328fe04 Ret __libc_Back_signalWait + 17e
0328fe04: Frame 0328fe94 Ret _std_sigtimedwait + 1d
0328fe94: Frame 0328ff04 Ret _std_sigwait + 27
0328ff04: Frame 0328ff64 Ret _signal_hand + 197
0328ff64: Frame 0328ffb4 Ret _pthread_exit + 25b
0328ffb4: Frame 0328fff4 Ret _endthread + 7f
0328fff4: Frame 00000000 Ret 1ffec188
Can not access 0 - giving up

PDUMP.001.txt (5,731 bytes)   

Activities

psmedley

2013-10-10 23:03

administrator   ~0002544

I suspect the latest build may address this. I found a stack corruption bug in GCC which is addressed in GCC 4.7.3

psmedley

2013-10-11 11:03

administrator   ~0002559

Please provide feedback

emax

2014-01-24 20:04

updater   ~0002644

Last edited: 2014-01-24 20:04

i've the same issue, nothing in popupos2.log, nothing in syslog, no dump,
no exceptQ dump

apache 2.2.25 + php 5.3.27 + mysql 5.1.72

massimo

psmedley

2014-01-24 20:17

administrator   ~0002645

almost impossible to debug this without some kind of error

asavage

2014-01-29 02:29

reporter   ~0002648

Update: Testing with 5.1.72

https://dl.dropboxusercontent.com/u/76425158/mysql-5.1.72-os2-20130925.zip
overlayed with these:
http://www.os2site.com/sw/apps/database/mysql/mysqld-5.1.72-20131124.zip

The system trapped several times. I am attaching the last TRP file, error log, and general log.

httpd 1.3.41
PHP 4.3.10

emax

2014-01-29 10:05

updater   ~0002649

today it exited with no paricular error or no dump:




140129 2:29:01 [Warning] X:\mysql\bin\mysqld.exe: Forcing close of thread 216
user: 'edc'

140129 2:29:01 [Warning] X:\mysql\bin\mysqld.exe: Forcing close of thread 213
user: 'edc'

140129 2:29:01 [Warning] X:\mysql\bin\mysqld.exe: Forcing close of thread 211
user: 'edc'

140129 2:29:01 [Warning] X:\mysql\bin\mysqld.exe: Forcing close of thread 166
user: 'edc'

140129 2:29:01 [Warning] X:\mysql\bin\mysqld.exe: Forcing close of thread 53 u
ser: 'edc'

140129 2:29:01 [Warning] X:\mysql\bin\mysqld.exe: Forcing close of thread 44 u
ser: 'edc'

140129 2:29:02 InnoDB: Starting shutdown...
140129 2:29:07 InnoDB: Shutdown completed; log sequence number 0 501341152
140129 2:29:07 [Note] X:\mysql\bin\mysqld.exe: Shutdown complete

asavage

2014-01-31 02:28

reporter   ~0002653

5.1.68 died last night. Attaching TRP, gen log, err log. Now with Oct2013 version of exceptq.

Steven Levine

2014-01-31 04:05

manager   ~0002654

I have annotated the .trp file and uploaded it as http://mantis.smedley.id.au/file_download.php?file_id=319&type=bug.

To see the code flow that caused the shutdown, scan the Stack Contents dump and find the "frame" references.

It appears that something occurred on the browser side that caused the the socket connection between mysql.dll, the PHP mysql extension, and mysqld.exe to close. This caused kLIBC to raise the SOCPIPE signal. However, mysqld does not define a handler for this signal, so kLIBC kills mysqld with a DosExit.

The mysqld code says

  my_sigset(SIGPIPE,SIG_IGN);

so something must be making it revert to its default setting.

psmedley

2014-01-31 08:46

administrator   ~0002655

yup, like the fact that init_signals had an os2 specific implementation in the code I got from Yuri some years ago.

Rebuilding now using the *nix code

psmedley

2014-01-31 08:58

administrator   ~0002656

http://smedley.id.au/tmp/mysqld-5.1.72-20140131.zip

Uses the unix code for init_signals.

One (current) side effect of this is that ctrl-c won't kill mysqld

asavage

2014-01-31 20:46

reporter   ~0002657

Can I get a .map (or better, an .xqs) for this drop?

psmedley

2014-01-31 21:41

administrator   ~0002658

zip updated with the xqs file

emax

2014-02-02 15:38

updater   ~0002661

it exit unexpectly even with this latest build

http://smedley.id.au/tmp/mysqld-5.1.72-20140131.zip

what i get to the window output
(of course i don't get the first page since it scroll down):




140202 2:28:26 [Warning] X:\mysql\bin\mysqld.exe: Forcing close of thread 756
user: 'edc'

140202 2:28:26 [Warning] X:\mysql\bin\mysqld.exe: Forcing close of thread 676
user: 'edc'

140202 2:28:27 [Warning] X:\mysql\bin\mysqld.exe: Forcing close of thread 669
user: 'edc'

140202 2:28:27 [Warning] X:\mysql\bin\mysqld.exe: Forcing close of thread 661
user: 'edc'

140202 2:28:27 [Warning] X:\mysql\bin\mysqld.exe: Forcing close of thread 612
user: 'edc'

140202 2:28:27 [Warning] X:\mysql\bin\mysqld.exe: Forcing close of thread 578
user: 'edc'

140202 2:28:27 InnoDB: Starting shutdown...
140202 2:28:28 InnoDB: Shutdown completed; log sequence number 0 501344971
140202 2:28:28 [Note] X:\mysql\bin\mysqld.exe: Shutdown complete

Error in my_thread_global_end(): 2 threads didn't exit

[X:\mysql\bin]




massimo

Steven Levine

2014-02-05 01:10

manager   ~0002663

Massimo,

Where is the .trp file? Recall that you need to use the "Z" so that Process Termination Notices generate .trp files.

The messages look like typical warnings.

Steven Levine

2014-02-05 01:47

manager   ~0002664

On an otherwise idle system, I see

  Error in my_thread_global_end(): 1 threads didn't exit

It might be useful to know which thread(s) is/are not dieing. The easiest way to see what's going on is probably by forcing an exception after printing the message near mysys\my_thr_init.c:200 if an env variable exists. Something like

  if (getenv("DIEDIEDIE"))
    *(char *)0 = 0;

should be sufficient.

psmedley

2014-02-05 08:51

administrator   ~0002665

http://smedley.id.au/tmp/mysqld-20140205.zip has this change

Steven Levine

2014-02-05 23:31

manager   ~0002666

Looking at the process dump, we have thread 2 stuck at

# %k 328FB60-4
0328fb5c: Frame 0328fd54 Ret __libc_back_signalWait + be
0328fd54: Frame 0328fe04 Ret __libc_Back_signalWait + 17e
0328fe04: Frame 0328fe94 Ret _std_sigtimedwait + 1d
0328fe94: Frame 0328ff04 Ret _std_sigwait + 27
0328ff04: Frame 0328ff64 Ret _signal_hand + 197
0328ff64: Frame 0328ffb4 Ret _pthread_exit + 25b
0328ffb4: Frame 0328fff4 Ret _endthread + 7f
0328fff4: Frame 00000000 Ret 1ffec188
Can not access 0 - giving up

It appears that signal_hand() is waiting for a signal that never comes or possibly the signal came before cleanup_done was set.

psmedley

2014-02-06 08:53

administrator   ~0002667

Error in my_thread_global_end(): 1 threads didn't exit goes away using the standard unix code in mysqld.cc - however with that, mysqladmin -u username shutdown fails

Will try do some more digging on the weekend

psmedley

2014-02-08 23:51

administrator   ~0002668

http://smedley.id.au/tmp/mysqld-20140209.zip

Back to using the os2 branch for init_signals, but added:
my_sigset(SIGPIPE,SIG_IGN);

from the unix version of init_signals

asavage

2014-02-09 02:31

reporter   ~0002669

I've got it installed, and will monitor the logs to see if aberrant stuff happens.

Steven Levine

2014-02-09 07:45

manager   ~0002670

http://smedley.id.au/tmp/mysqld-20140209.zip allow mysqladmin to do a clean shutdown.

A Ctrl-C shutdown still results in

  Error in my_thread_global_end(): 1 threads didn't exit

here, but I believe the error is mostly cosmetic.

asavage

2014-03-09 00:07

reporter   ~0002683

Running that last drop (20140209), it's run nine days uninterrupted without dying, which is a lot better than I'd seen previously. Due to other issues (EVFS), I've had to reboot the box a few times, but when left alone mysqld seems to be working well.

emax

2014-03-10 08:27

updater   ~0002686

when i close mysql (i restart it each night) i allways see a high number of threads even if i've no connections in that moment

i suspect mysql do not close correctly some connection from PHP (call to the db via mysql php module)

this happens with all versions of mysqlD this one and previous ones


massimo

asavage

2014-03-10 14:29

reporter   ~0002688

Max, that issue should be reported in a separate bug report.

Is mysqld unexpectedly stopping for you?

emax

2014-03-10 14:32

updater   ~0002689

with latest version i've no more strange/unexpected exit

Issue History

Date Modified Username Field Change
2013-04-23 00:13 asavage New Issue
2013-10-10 23:03 psmedley Note Added: 0002544
2013-10-11 11:03 psmedley Note Added: 0002559
2013-10-11 11:03 psmedley Assigned To => psmedley
2013-10-11 11:03 psmedley Status new => feedback
2014-01-24 20:04 emax Note Added: 0002644
2014-01-24 20:04 emax Note Edited: 0002644
2014-01-24 20:17 psmedley Note Added: 0002645
2014-01-29 02:29 asavage Note Added: 0002648
2014-01-29 02:29 asavage Status feedback => assigned
2014-01-29 02:31 asavage File Added: 0087_04.TRP
2014-01-29 02:32 asavage File Added: Joni2-err-20140125-1830.log
2014-01-29 02:38 asavage File Added: Joni2-gen-20140125-1830-snipped.log
2014-01-29 10:05 emax Note Added: 0002649
2014-01-31 02:28 asavage Note Added: 0002653
2014-01-31 02:33 asavage File Added: Joni2-gen-20140126-1651-snipped.log
2014-01-31 02:34 asavage File Added: Joni2-err-20140126-1651.log
2014-01-31 02:35 asavage File Added: 007A_06.TRP
2014-01-31 03:42 Steven Levine File Added: 007A_06-shl-annotated.TRP
2014-01-31 04:05 Steven Levine Note Added: 0002654
2014-01-31 08:46 psmedley Note Added: 0002655
2014-01-31 08:58 psmedley Note Added: 0002656
2014-01-31 20:46 asavage Note Added: 0002657
2014-01-31 21:41 psmedley Note Added: 0002658
2014-02-02 15:38 emax Note Added: 0002661
2014-02-05 01:07 Steven Levine Description Updated
2014-02-05 01:10 Steven Levine Note Added: 0002663
2014-02-05 01:10 Steven Levine Status assigned => feedback
2014-02-05 01:47 Steven Levine Note Added: 0002664
2014-02-05 08:51 psmedley Note Added: 0002665
2014-02-05 23:31 Steven Levine Note Added: 0002666
2014-02-05 23:32 Steven Levine File Added: PDUMP.001.txt
2014-02-06 08:53 psmedley Note Added: 0002667
2014-02-08 23:51 psmedley Note Added: 0002668
2014-02-09 02:31 asavage Note Added: 0002669
2014-02-09 02:31 asavage Status feedback => assigned
2014-02-09 07:45 Steven Levine Note Added: 0002670
2014-03-09 00:07 asavage Note Added: 0002683
2014-03-10 08:27 emax Note Added: 0002686
2014-03-10 14:29 asavage Note Added: 0002688
2014-03-10 14:32 emax Note Added: 0002689
2014-04-03 06:46 psmedley Status assigned => resolved
2014-04-03 06:46 psmedley Resolution open => fixed
2020-08-24 03:09 psmedley Status resolved => closed