Sometimes it helps to run winedbg from another window and get the stacks of all running processes with the command bt all With luck, you can then see which two code paths are competing for the lock.
On 1/1/11 7:10 PM, Dan Kegel wrote:
Sometimes it helps to run winedbg from another window and get the stacks of all running processes with the command bt all With luck, you can then see which two code paths are competing for the lock.
Dan:
I've also been getting random 'locks' and this is only running 'make test' and that resulted in an update to the Wine Configuration. This looks like a regression of the problem that was fixed a long time ago, where interprocess locking happened constantly. Maybe Wylda can find it, if the problem is constant on his system.
James McKenzie
...get the stacks of all running processes with the command
bt all
With luck, you can then see which two code paths are competing for the lock.
Thanks for tip! Are the following traces from problematic threads useful or will i have to post all the thread traces? (Just repeat: happens in case of load/save of savegame):
fixme:thread:SetThreadIdealProcessor (0x764): stub
err:ntdll:RtlpWaitForCriticalSection section 0x7de77580 "x11drv_main.c: X11DRV_CritSection" wait timed out in thread 001c, blocked by 0041, retrying (60 sec)
err:ntdll:RtlpWaitForCriticalSection section 0x41f24e4 "?" wait timed out in thread 0045, blocked by 0044, retrying (60 sec)
Selected/affected threads from "bt all": ========================================
Backtracing for thread 001c in process 001b (C:\Program Files\2K Games\BioShock\Builds\Release\Bioshock.exe): Backtrace:
=>0 0xb77dc422 __kernel_vsyscall+0xe() in [vdso].so (0x0073f918)
1 0x7bc7fbbe NTDLL_wait_for_multiple_objects+0x1f0(count=0x73fafc, handles=0x73f9fc, flags=0x4, timeout=0x7bc8c082, signal_object=0x73fa58) [/build/wine-git_build/dlls/ntdll/sync.c:1124] in ntdll (0x0073fb28)
2 0x7bc7fbbe NTDLL_wait_for_multiple_objects+0x1f0(count=0x1, handles=0x73fbb0, flags=0x4, timeout=(nil), signal_object=0x0(nil)) [/build/wine-git_build/dlls/ntdll/sync.c:1124] in ntdll (0x0073fb78)
3 0x7bc7fcae NtWaitForMultipleObjects+0x73(count=0x1, handles=0x73fbb0, wait_all=0, alertable=0, timeout=(nil)) [/build/wine-git_build/dlls/ntdll/sync.c:1162] in ntdll (0x0073fcc8)
4 0x7b86e395 WaitForMultipleObjectsEx+0x138(count=0x1, handles=0x73fd00, wait_all=0, timeout=0xffffffff, alertable=0) [/build/wine-git_build/dlls/kernel32/sync.c:188] in kernel32 (0x0073fcf8)
5 0x7b86e1c9 WaitForSingleObject+0x3b(handle=0x7f4, timeout=0xffffffff) [/build/wine-git_build/dlls/kernel32/sync.c:128] in kernel32 (0x0073fd10)
6 0x1145ffd1 in bioshock (+0xb5ffd0) (0x0073fd44)
7 0x1171bac7 in bioshock (+0xe1bac6) (0x0073fd7c)
8 0x1171bc3d in bioshock (+0xe1bc3c) (0x0073fe60)
9 0x7b85d54c call_process_entry+0xb() in kernel32 (0x0073fe78)
10 0x7b85d54c call_process_entry+0xb() in kernel32 (0x0073fec8)
11 0x7b85d692 start_process+0x143(peb=0x7ffdf000) [/build/wine-git_build/dlls/kernel32/process.c:1086] in kernel32 (0x0073fed8)
12 0x7bc7be90 call_thread_func+0xb() in ntdll (0x0073ffb8)
13 0x7bc7bece call_thread_entry_point+0x33(entry=0x7b85d54e, arg=0x7ffdf000) [/build/wine-git_build/dlls/ntdll/signal_i386.c:2473] in ntdll (0x0073ffe8)
14 0x7bc53fdc start_process+0x2f(kernel_start=0x7b85d54e) [/build/wine-git_build/dlls/ntdll/loader.c:2606] in ntdll (0x00000000)
Backtracing for thread 0041 in process 001b (C:\Program Files\2K Games\BioShock\Builds\Release\Bioshock.exe): Backtrace:
=>0 0xb77dc422 __kernel_vsyscall+0xe() in [vdso].so (0x1283de88)
1 0x7d847231 in libgl.so.1 (+0x7b230) (0x1283df58)
2 0x7e4314fa context_apply_fbo_entry+0x29(context=0x121ba5b8, target=0x8d40, entry=0x182e98) [/build/wine-git_build/dlls/wined3d/context.c:440] in wined3d (0x1283df98)
3 0x7e4314fa context_apply_fbo_entry+0x29(context=0x121ba5b8, target=0x8d40, entry=0x182e80) [/build/wine-git_build/dlls/wined3d/context.c:440] in wined3d (0x1283dfd8)
4 0x7e431703 context_apply_fbo_state+0xd5(context=0x121ba5b8, target=0x8d40, render_targets=0x14113658, depth_stencil=0x1a13a8, location=0x40) [/build/wine-git_build/dlls/wined3d/context.c:492] in wined3d (0x1283e038)
5 0x7e43b83c context_apply_clear_state+0xec(context=0x121ba5b8, device=0x18a008, rt_count=0x8, rts=0x182b80, depth_stencil=0x1a13a8) [/build/wine-git_build/dlls/wined3d/context.c:2148] in wined3d (0x1283e178)
6 0x7e440306 device_clear_render_targets+0x1a2(device=0x18a008, rt_count=0x8, rts=0x182b80, rect_count=0, rects=(nil), draw_rect=0x1283e1cc, flags=0x7, color=0x1283e1dc, depth=1.000000, stencil=0) [/build/wine-git_build/dlls/wined3d/device.c:689] in wined3d (0x1283e208)
7 0x7e4512fa IWineD3DDeviceImpl_Clear+0x1ef(iface=0x18a008, rect_count=0, rects=(nil), flags=0x7, color=0, depth=1.000000, stencil=0) [/build/wine-git_build/dlls/wined3d/device.c:4744] in wined3d (0x1283e258)
8 0x7e5743c1 IDirect3DDevice9Impl_Clear+0xda(iface=0x181f90, Count=0, pRects=(nil), Flags=0x7, Color=0, Z=1.000000, Stencil=0) [/build/wine-git_build/dlls/d3d9/device.c:1273] in d3d9 (0x1283e2a0)
9 0x10b8f39d in bioshock (+0x28f39c) (0x1283e324)
10 0x10ae934e in bioshock (+0x1e934d) (0x1c268008)
11 0x00000003 (0x11015464)
12 0x10aff710 in bioshock (+0x1ff70f) (0x10a578a0)
13 0x0001088e (0x8df18b56)
14 0x00000000 (0x00000000)
Backtracing for thread 0045 in process 001b (C:\Program Files\2K Games\BioShock\Builds\Release\Bioshock.exe):
Backtrace:
=>0 0xb77dc424 __kernel_vsyscall+0x10() in [vdso].so (0x00000000)
Backtracing for thread 0044 in process 001b (C:\Program Files\2K Games\BioShock\Builds\Release\Bioshock.exe): Backtrace:
=>0 0xb77dc422 __kernel_vsyscall+0xe() in [vdso].so (0x7f4fe5fc)
1 0x7bc7fbbe NTDLL_wait_for_multiple_objects+0x1f0(count=0x7f4fe7e0, handles=0x7f4fe6e0, flags=0x4, timeout=0x7bc768d2, signal_object=0x7bcb15a0) [/build/wine-git_build/dlls/ntdll/sync.c:1124] in ntdll (0x7f4fe80c)
2 0x7bc7fbbe NTDLL_wait_for_multiple_objects+0x1f0(count=0x1, handles=0x7f4fe894, flags=0x4, timeout=(nil), signal_object=0x0(nil)) [/build/wine-git_build/dlls/ntdll/sync.c:1124] in ntdll (0x7f4fe85c)
3 0x7bc7fcae NtWaitForMultipleObjects+0x73(count=0x1, handles=0x7f4fe894, wait_all=0, alertable=0, timeout=(nil)) [/build/wine-git_build/dlls/ntdll/sync.c:1162] in ntdll (0x7f4fe9ac)
4 0x7b86e395 WaitForMultipleObjectsEx+0x138(count=0x1, handles=0x7f4fe9e4, wait_all=0, timeout=0xffffffff, alertable=0) [/build/wine-git_build/dlls/kernel32/sync.c:188] in kernel32 (0x7f4fe9dc)
5 0x7b86e1c9 WaitForSingleObject+0x3b(handle=0x6f0, timeout=0xffffffff) [/build/wine-git_build/dlls/kernel32/sync.c:128] in kernel32 (0x00000000)
On 2 January 2011 13:59, wylda@volny.cz wrote:
err:ntdll:RtlpWaitForCriticalSection section 0x7de77580 "x11drv_main.c: X11DRV_CritSection" wait timed out in thread 001c, blocked by 0041, retrying (60 sec)
...
Backtracing for thread 001c in process 001b (C:\Program Files\2K Games\BioShock\Builds\Release\Bioshock.exe): Backtrace:
=>0 0xb77dc422 __kernel_vsyscall+0xe() in [vdso].so (0x0073f918)
1 0x7bc7fbbe NTDLL_wait_for_multiple_objects+0x1f0(count=0x73fafc, handles=0x73f9fc, flags=0x4, timeout=0x7bc8c082, signal_object=0x73fa58) [/build/wine-git_build/dlls/ntdll/sync.c:1124] in ntdll (0x0073fb28)
2 0x7bc7fbbe NTDLL_wait_for_multiple_objects+0x1f0(count=0x1, handles=0x73fbb0, flags=0x4, timeout=(nil), signal_object=0x0(nil)) [/build/wine-git_build/dlls/ntdll/sync.c:1124] in ntdll (0x0073fb78)
3 0x7bc7fcae NtWaitForMultipleObjects+0x73(count=0x1, handles=0x73fbb0, wait_all=0, alertable=0, timeout=(nil)) [/build/wine-git_build/dlls/ntdll/sync.c:1162] in ntdll (0x0073fcc8)
4 0x7b86e395 WaitForMultipleObjectsEx+0x138(count=0x1, handles=0x73fd00, wait_all=0, timeout=0xffffffff, alertable=0) [/build/wine-git_build/dlls/kernel32/sync.c:188] in kernel32 (0x0073fcf8)
5 0x7b86e1c9 WaitForSingleObject+0x3b(handle=0x7f4, timeout=0xffffffff) [/build/wine-git_build/dlls/kernel32/sync.c:128] in kernel32 (0x0073fd10)
From that backtrace, it doesn't look like 001c is waiting for a
critical section at all.
Hi Henri,
thank you for analysis, it's first time when i'm trying to help with this kind of problem...
From that backtrace, it doesn't look like 001c is waiting for a critical section at all.
The truth is, that wine outputs the first line ("...wait timed out in thread 001c, blocked by 0041...") only once and after that only the 2nd line repeats every 60sec ("...wait timed out in thread 0045, blocked by 0044..."). Don't know if that's normal in these cases or both lines should repeated.
So what should i do now to be more helpful? I think that kernel has some infrastructure for logging of locks or detecting deadlock or whatever... Is there an equivalent in wine??
Thanks for support. W.
On 2 January 2011 17:43, wylda@volny.cz wrote:
The truth is, that wine outputs the first line ("...wait timed out in thread 001c, blocked by 0041...") only once and after that only the 2nd line repeats every 60sec ("...wait timed out in thread 0045, blocked by 0044..."). Don't know if that's normal in these cases or both lines should repeated.
Thread 0041 is probably just a bit slow at some point then, but it does sound like it eventually releases the lock. It would be interesting to figure out what's taking so long, but it's probably not the main problem.
For a proper deadlock you'd have at least two threads waiting for each other, that doesn't seem to be the case here. It looks more like 0044 is either busy doing something expensive or dead. The backtraces for those threads aren't very helpful unfortunately, the stacks for both of them look damaged / altered. You may have more luck with something like a +relay,+seh,+tid log.
So what should i do now to be more helpful? I think that kernel has some infrastructure for logging of locks or detecting deadlock or whatever... Is there an equivalent in wine??
I guess you're referring to lockdep. AFAIK there's no such thing in Wine, but it would probably be a useful tool on occasion. For the reasons mentioned above, I don't think it would have been much help for this specific bug though.
On Sun, Jan 2, 2011 at 7:36 PM, Henri Verbeet hverbeet@gmail.com wrote:
On 2 January 2011 17:43, wylda@volny.cz wrote:
The truth is, that wine outputs the first line ("...wait timed out in thread 001c, blocked by 0041...") only once and after that only the 2nd line repeats every 60sec ("...wait timed out in thread 0045, blocked by 0044..."). Don't know if that's normal in these cases or both lines should repeated.
Thread 0041 is probably just a bit slow at some point then, but it does sound like it eventually releases the lock. It would be interesting to figure out what's taking so long, but it's probably not the main problem.
For a proper deadlock you'd have at least two threads waiting for each other,
No, a sufficient condition for a deadlock is that a thread waits for something that will never happen. It could be waiting for a lock to be released, but that thread itself already holds the lock. Or another thread took the lock but died before releasing it.
-
Damjan Jovanovic -
Dan Kegel -
Henri Verbeet -
James McKenzie -
wylda＠volny.cz