Fwd: game "Knights and Merchants" deadlocks
On 2/4/06, Joris Huizer <jorishuizer(a)planet.nl> wrote:
Hello,
I have this question: I have a game called "Knights and Merchants" which I sometimes play; I find it deadlocks each time after playing for an hour or so it seems it isn't a complete deadlock, sometimes some of sound comes through between intervals of minutes or so; harddisk activity seems extreme - the light is burning constantly. I then usually decide to kill the program; as it opens fullscreen I can't get to the xterm that launched it, so I try to get to a console; The system is so slow that it takes some time to get to a console <ctrl-alt-f1>, and login in may time out a few times before finaly getting in (the cure to that one is simple: login before starting the game...) - then it takes another minute or so to run ps and kill the wine process
is there a way to find what is causing the deadlock? I can log the output wine gives using `script`, but as deadlocks only occur after a lot of time running the game with lots of logging active would be a pain
will log the output at least next time I play; for now, has somebody ideas how to log without getting major slowdown (otherwise there's no playing in it)?
thanks,
Joris
This really sounds like a memory leak to me. Usually I'd use valgrind ( http://valgrind.org/) to find memory leaks and such. Valgrind 3.1.0 works with wine, but it produces alot of output you'd have to look through and the program will run insanely slow. It might be worth a try.
James Trotter wrote:
On 2/4/06, *Joris Huizer* <jorishuizer(a)planet.nl <mailto:jorishuizer(a)planet.nl>> wrote:
Hello,
I have this question: I have a game called "Knights and Merchants" which I sometimes play; I find it deadlocks each time after playing for an hour or so it seems it isn't a complete deadlock, sometimes some of sound comes through between intervals of minutes or so; harddisk activity seems extreme - the light is burning constantly. I then usually decide to kill the program; as it opens fullscreen I can't get to the xterm that launched it, so I try to get to a console; The system is so slow that it takes some time to get to a console <ctrl-alt-f1>, and login in may time out a few times before finaly getting in (the cure to that one is simple: login before starting the game...) - then it takes another minute or so to run ps and kill the wine process
is there a way to find what is causing the deadlock? I can log the output wine gives using `script`, but as deadlocks only occur after a lot of time running the game with lots of logging active would be a pain
will log the output at least next time I play; for now, has somebody ideas how to log without getting major slowdown (otherwise there's no playing in it)?
thanks,
Joris
This really sounds like a memory leak to me. Usually I'd use valgrind (http://valgrind.org/) to find memory leaks and such. Valgrind 3.1.0 works with wine, but it produces alot of output you'd have to look through and the program will run insanely slow. It might be worth a try.
------------------------------------------------------------------------
I'm sort of familiar with valgrind too :-) will try if playing it is still possible when running with valgrind; I know it is doing direct-draw and direct-sound (as wine gives warnings and fixmes on some of the calls it does to those) just wondering... when it hangs, how should it be killed such that valgrind will still report where it broke? (kill -9 stops it too brutely, at least with valgrind 2.4.0) thanks, Joris
On 2/4/06, Joris Huizer <jorishuizer(a)planet.nl> wrote:
James Trotter wrote:
On 2/4/06, *Joris Huizer* <jorishuizer(a)planet.nl <mailto:jorishuizer(a)planet.nl>> wrote:
Hello,
I have this question: I have a game called "Knights and Merchants" which I sometimes play; I find it deadlocks each time after playing for an hour or so it seems it isn't a complete deadlock, sometimes some of sound comes through between intervals of minutes or so; harddisk activity seems extreme - the light is burning constantly. I then usually decide to kill the program; as it opens fullscreen I can't get to the xterm that launched it, so I try to get to a console; The system is so slow that it takes some time to get to a console <ctrl-alt-f1>, and login in may time out a few times before finaly getting in (the cure to that one is simple: login before starting the game...) - then it takes another minute or so to run ps and kill the wine process
is there a way to find what is causing the deadlock? I can log the output wine gives using `script`, but as deadlocks only occur after a lot of time running the game with lots of logging active would be a pain
will log the output at least next time I play; for now, has somebody ideas how to log without getting major slowdown (otherwise there's no playing in it)?
thanks,
Joris
This really sounds like a memory leak to me. Usually I'd use valgrind (http://valgrind.org/) to find memory leaks and such. Valgrind 3.1.0 works with wine, but it produces alot of output you'd have to look through and the program will run insanely slow. It might be worth a try.
------------------------------------------------------------------------
I'm sort of familiar with valgrind too :-) will try if playing it is still possible when running with valgrind; I know it is doing direct-draw and direct-sound (as wine gives warnings and fixmes on some of the calls it does to those) just wondering... when it hangs, how should it be killed such that valgrind will still report where it broke? (kill -9 stops it too brutely, at least with valgrind 2.4.0)
thanks,
Joris
If it really is a memory leak. you might not need to run the application until it hangs. The memory leak might be small which leads the program to crash after a long time. Try to run valgrind with something like this: valgrind --leak-check=full --trace-children=yes wine [name of the program] You might want to make valgrind output it to a log. The output is usually quite messy. Before you try valgrind, Robert Shearman said that you need to apply a patch against valgrind 3.1.0 so that it can generate useful stack traces when run with wine. I've attached the patch. Regards, James
I built valgrind 3.1.0 with the given patch, but for some reason valgrind fails to start the program correctly; I attached the log of a run; When I do not run with valgrind the program starts successfully. What is wrong? how should I get valgrind with the program running?
Hi, On Sat, Feb 04, 2006 at 01:47:42PM +0100, James Trotter wrote:
On 2/4/06, Joris Huizer <jorishuizer(a)planet.nl> wrote:
I have this question: I have a game called "Knights and Merchants" which I sometimes play; I find it deadlocks each time after playing for an hour or so it seems it isn't a complete deadlock, sometimes some of sound comes through between intervals of minutes or so; harddisk activity seems extreme - the light is burning constantly. I then usually decide to kill the program; as it opens fullscreen I can't get to the xterm that launched it, so I try to get to a console; The system is so slow that it takes some time to get to a console <ctrl-alt-f1>, and login in may time out a few times before finaly getting in (the cure to that one is simple: login before starting the game...) - then it takes another minute or so to run ps and kill the wine process
This really sounds like a memory leak to me. Usually I'd use valgrind ( http://valgrind.org/) to find memory leaks and such. Valgrind 3.1.0 works with wine, but it produces alot of output you'd have to look through and the program will run insanely slow. It might be worth a try.
I'd bet this isn't a "deadlock". Instead, your program is consuming massive amounts of memory that your system cannot cope with, thus quickly running into swap and tearing the whole system performance down due to excessive swap activity. No deadlock at all, simply massive overload. A normal memory leak sounds less plausible to me, too. May I suggest that this is caused by a memory "allocation" of a pointer variable instead of a memory size variable? Pointers (memory addresses) usually are in the 0x40XXXXXX or 0x08XXXXXX range, so if you take those values as amount of memory to allocate... IOW, perhaps there is a function parameter count mismatch in .spec files or some other random stack trashing that leads to such high memory allocation due to accessing the wrong variable. You should probably try a ulimit -S -m 128000000 , that will most likely kill the process then when everything goes haywire, thus supporting my theory at least halfway. Andreas Mohr
Andreas Mohr wrote:
Hi,
On Sat, Feb 04, 2006 at 01:47:42PM +0100, James Trotter wrote:
On 2/4/06, Joris Huizer <jorishuizer(a)planet.nl> wrote:
I have this question: I have a game called "Knights and Merchants" which I sometimes play; I find it deadlocks each time after playing for an hour or so it seems it isn't a complete deadlock, sometimes some of sound comes through between intervals of minutes or so; harddisk activity seems extreme - the light is burning constantly. I then usually decide to kill the program; as it opens fullscreen I can't get to the xterm that launched it, so I try to get to a console; The system is so slow that it takes some time to get to a console <ctrl-alt-f1>, and login in may time out a few times before finaly getting in (the cure to that one is simple: login before starting the game...) - then it takes another minute or so to run ps and kill the wine process
This really sounds like a memory leak to me. Usually I'd use valgrind ( http://valgrind.org/) to find memory leaks and such. Valgrind 3.1.0 works with wine, but it produces alot of output you'd have to look through and the program will run insanely slow. It might be worth a try.
I'd bet this isn't a "deadlock". Instead, your program is consuming massive amounts of memory that your system cannot cope with, thus quickly running into swap and tearing the whole system performance down due to excessive swap activity. No deadlock at all, simply massive overload.
A normal memory leak sounds less plausible to me, too.
May I suggest that this is caused by a memory "allocation" of a pointer variable instead of a memory size variable? Pointers (memory addresses) usually are in the 0x40XXXXXX or 0x08XXXXXX range, so if you take those values as amount of memory to allocate...
IOW, perhaps there is a function parameter count mismatch in .spec files or some other random stack trashing that leads to such high memory allocation due to accessing the wrong variable.
You should probably try a ulimit -S -m 128000000 , that will most likely kill the process then when everything goes haywire, thus supporting my theory at least halfway.
Andreas Mohr
indeed the program got killed... at least it's a memory problem (maybe it was not the best situation, but I was logged in at a console and some output on running out of memory was written there) I don't really know what to look for, but as far as I see there isn't much interesting in the log, just a few fixme's that are repeated lots of times, and then these critical section timeouts: err:ntdll:RtlpWaitForCriticalSection section 0x40a01560 "gdiobj.c: GDI_level" wait timed out in thread 0009, blocked by 0000, retrying (60 sec) .... err:ntdll:RtlpWaitForCriticalSection section 0x4110f380 "x11drv_main.c: X11DRV_CritSection" wait timed out in thread 0009, blocked by 000d, retrying (60 sec) ... err:ntdll:RtlpWaitForCriticalSection section 0x40a01560 "gdiobj.c: GDI_level" wait timed out in thread 0009, blocked by 000d, retrying (60 sec) There also a lot of error lines on dsound: err:dsound:DSOUND_MixInBuffer length not a multiple of block size, len = 3, block size = 2 with varying len values I put the complete log online at home.planet.nl/~huize784/kam.log.bz2 as I think it's too much to send as attachment (compressed, it is 107KB) regards, Joris end of the log (hopefully the relevant part) : fixme:ddraw:Main_DirectDraw_WaitForVerticalBlank (0x403d1a00)->(flags=0x00000001,handle=(nil)) fixme:ddraw:Main_DirectDraw_WaitForVerticalBlank (0x403d1a00)->(flags=0x00000001,handle=(nil)) fixme:wave:DSD_CreateSecondaryBuffer (0x403e5270,0x4084fc48,e2,0,0x5b09842c,0x571bf94c,0x5b098408): stub err:dsound:DSOUND_MixInBuffer length not a multiple of block size, len = 221, block size = 2 err:dsound:DSOUND_MixInBuffer length not a multiple of block size, len = 3, block size = 2 err:dsound:DSOUND_MixInBuffer length not a multiple of block size, len = 221, block size = 2 err:dsound:DSOUND_MixInBuffer length not a multiple of block size, len = 3, block size = 2 err:dsound:DSOUND_MixInBuffer length not a multiple of block size, len = 331, block size = 2 err:dsound:DSOUND_MixInBuffer length not a multiple of block size, len = 309, block size = 2 err:dsound:DSOUND_MixInBuffer length not a multiple of block size, len = 3, block size = 2 fixme:ddraw:Main_DirectDraw_WaitForVerticalBlank (0x403d1a00)->(flags=0x00000001,handle=(nil)) fixme:wave:DSD_CreateSecondaryBuffer (0x403e5270,0x4084fc48,e2,0,0x596bea7c,0x48629a7c,0x596bea58): stub fixme:wave:DSD_CreateSecondaryBuffer (0x403e5270,0x4084fc48,e2,0,0x5b0a0624,0x564301d4,0x5b0a0600): stub err:dsound:DSOUND_MixInBuffer length not a multiple of block size, len = 441, block size = 2 err:dsound:DSOUND_MixInBuffer length not a multiple of block size, len = 3, block size = 2 err:dsound:DSOUND_MixInBuffer length not a multiple of block size, len = 441, block size = 2 err:dsound:DSOUND_MixInBuffer length not a multiple of block size, len = 3, block size = 2 fixme:ddraw:Main_DirectDraw_WaitForVerticalBlank (0x403d1a00)->(flags=0x00000001,handle=(nil)) fixme:ddraw:Main_DirectDraw_WaitForVerticalBlank (0x403d1a00)->(flags=0x00000001,handle=(nil)) fixme:ddraw:Main_DirectDraw_WaitForVerticalBlank (0x403d1a00)->(flags=0x00000001,handle=(nil)) fixme:ddraw:Main_DirectDraw_WaitForVerticalBlank (0x403d1a00)->(flags=0x00000001,handle=(nil)) fixme:wave:DSD_CreateSecondaryBuffer (0x403e5270,0x4084fc48,e2,0,0x5b0a0624,0x47dfcb2c,0x5b0a0600): stub err:dsound:DSOUND_MixInBuffer length not a multiple of block size, len = 251, block size = 2 fixme:ddraw:Main_DirectDraw_WaitForVerticalBlank (0x403d1a00)->(flags=0x00000001,handle=(nil)) err:ntdll:RtlpWaitForCriticalSection section 0x40a01560 "gdiobj.c: GDI_level" wait timed out in thread 0009, blocked by 0000, retrying (60 sec) fixme:wave:DSD_CreateSecondaryBuffer (0x403e5270,0x4084fc48,e2,0,0x596bea7c,0x47d28d0c,0x596bea58): stub fixme:ddraw:Main_DirectDraw_WaitForVerticalBlank (0x403d1a00)->(flags=0x00000001,handle=(nil)) err:ntdll:RtlpWaitForCriticalSection section 0x4110f380 "x11drv_main.c: X11DRV_CritSection" wait timed out in thread 0009, blocked by 000d, retrying (60 sec) fixme:ddraw:Main_DirectDraw_WaitForVerticalBlank (0x403d1a00)->(flags=0x00000001,handle=(nil)) fixme:ddraw:Main_DirectDraw_WaitForVerticalBlank (0x403d1a00)->(flags=0x00000001,handle=(nil)) fixme:ddraw:Main_DirectDraw_WaitForVerticalBlank (0x403d1a00)->(flags=0x00000001,handle=(nil)) fixme:ddraw:Main_DirectDraw_WaitForVerticalBlank (0x403d1a00)->(flags=0x00000001,handle=(nil)) fixme:ddraw:Main_DirectDraw_WaitForVerticalBlank (0x403d1a00)->(flags=0x00000001,handle=(nil)) fixme:ddraw:Main_DirectDraw_WaitForVerticalBlank (0x403d1a00)->(flags=0x00000001,handle=(nil)) fixme:ddraw:Main_DirectDraw_WaitForVerticalBlank (0x403d1a00)->(flags=0x00000001,handle=(nil)) fixme:ddraw:Main_DirectDraw_WaitForVerticalBlank (0x403d1a00)->(flags=0x00000001,handle=(nil)) fixme:wave:DSD_CreateSecondaryBuffer (0x403e5270,0x4084fad8,e2,0,0x596bea7c,0x482523d4,0x596bea58): stub fixme:ddraw:Main_DirectDraw_WaitForVerticalBlank (0x403d1a00)->(flags=0x00000001,handle=(nil)) fixme:wave:DSD_CreateSecondaryBuffer (0x403e5270,0x4084fc48,e2,0,0x596bea7c,0x48629a7c,0x596bea58): stub fixme:ddraw:Main_DirectDraw_WaitForVerticalBlank (0x403d1a00)->(flags=0x00000001,handle=(nil)) fixme:wave:DSD_CreateSecondaryBuffer (0x403e5270,0x4084fc5c,e2,0,0x403caf6c,0x5b0a07bc,0x403caf48): stub fixme:ddraw:Main_DirectDraw_WaitForVerticalBlank (0x403d1a00)->(flags=0x00000001,handle=(nil)) fixme:ddraw:Main_DirectDraw_WaitForVerticalBlank (0x403d1a00)->(flags=0x00000001,handle=(nil)) fixme:wave:DSD_CreateSecondaryBuffer (0x403e5270,0x4084fc48,e2,0,0x596bea7c,0x564301d4,0x596bea58): stub fixme:ddraw:Main_DirectDraw_WaitForVerticalBlank (0x403d1a00)->(flags=0x00000001,handle=(nil)) fixme:wave:DSD_CreateSecondaryBuffer (0x403e5270,0x4084fc48,e2,0,0x562ab2c4,0x47dfcb2c,0x562ab2a0): stub fixme:ddraw:Main_DirectDraw_WaitForVerticalBlank (0x403d1a00)->(flags=0x00000001,handle=(nil)) fixme:wave:DSD_CreateSecondaryBuffer (0x403e5270,0x4084fc98,e2,0,0x5afc51d4,0x550fc284,0x5afc51b0): stub err:dsound:DSOUND_MixInBuffer length not a multiple of block size, len = 427, block size = 2 fixme:wave:DSD_CreateSecondaryBuffer (0x403e5270,0x4084fc98,e2,0,0x5bda5284,0x537f1314,0x5bda5260): stub fixme:ddraw:Main_DirectDraw_WaitForVerticalBlank (0x403d1a00)->(flags=0x00000001,handle=(nil)) err:ntdll:RtlpWaitForCriticalSection section 0x40a01560 "gdiobj.c: GDI_level" wait timed out in thread 0009, blocked by 000d, retrying (60 sec) fixme:wave:DSD_CreateSecondaryBuffer (0x403e5270,0x4084fc48,e2,0,0x403caf6c,0x48353294,0x403caf48): stub Killed
On Wed, Feb 08, 2006 at 09:41:47PM +0100, Joris Huizer wrote:
Andreas Mohr wrote:
May I suggest that this is caused by a memory "allocation" of a pointer variable instead of a memory size variable? Pointers (memory addresses) usually are in the 0x40XXXXXX or 0x08XXXXXX range, so if you take those values as amount of memory to allocate...
IOW, perhaps there is a function parameter count mismatch in .spec files or some other random stack trashing that leads to such high memory allocation due to accessing the wrong variable.
You should probably try a ulimit -S -m 128000000 , that will most likely kill the process then when everything goes haywire, thus supporting my theory at least halfway.
Andreas Mohr
indeed the program got killed... at least it's a memory problem (maybe it was not the best situation, but I was logged in at a console and some output on running out of memory was written there) I don't really know what to look for, but as far as I see there isn't much interesting in the log, just a few fixme's that are repeated lots of times, and then these critical section timeouts:
end of the log (hopefully the relevant part) :
[lots of stubby sound APIs] I'd thus do an educated strong guess that this is due to an issue in the sound parts. I think you should use additional tracing for all memory channels (WINEDEBUG=+local,+global,+virtual,+ntdll,+????) and check whether there's something grossly abnormal right before the program gets killed. If there is something, then it should be dead easy to figure out the remaining stuff with some further traces. But those locking issues certainly seem troublesome, too... Andreas
participants (3)
-
Andreas Mohr -
James Trotter -
Joris Huizer