Opened 10 years ago
Closed 10 years ago
#11344 closed bug (duplicate)
KDL while running PHP testsuite: "failed to acquire spinlock %p for a long time"
| Reported by: | pulkomandy | Owned by: | pdziepak |
|---|---|---|---|
| Priority: | normal | Milestone: | R1 |
| Component: | System/Kernel | Version: | R1/Development |
| Keywords: | Cc: | ||
| Blocked By: | #11032 | Blocking: | |
| Platform: | All |
Description
A recipe for php 5.6.2 is available at haikuports. Building it and running the testsuite results in a repeatable KDL. the error happens in _php_stream_fopen_from_pipe which calls _user_unmap_memory and ens up in a reschedule.
I tried to debug this as requested in #11032, but results are strange. running shows that the 3 other cores in my CPU are running idle threads. This looks correct, the machine freezes for a short time before it panics, but it is unexpected.
Trying to analyze the spinlock results in locked from 0x0000000. So it looks something went wrong with the spinlock.
Change History (7)
comment:1 by , 10 years ago
comment:2 by , 10 years ago
Replying to pulkomandy:
Trying to analyze the spinlock results in
locked from 0x0000000. So it looks something went wrong with the spinlock.
Not really. The spinlock itself is just stores an integer. The ownership info for debugging purposes is stored in separate ring buffer, which may just be too small in this case, and thus the entry may be clobbered. We generally don't want a large buffer for performance reasons, but you can increase the value for debugging purposes.
comment:3 by , 10 years ago
I found another way to reproduce this:
- Install the php package
- run php-cgi
- interrupt it with ctrl+C
- wait for a few seconds
I increased NUM_LAST_CALLERS from 32 to 4096, and I do this:
kdebug> message PANIC: acquire_spinlock(): Failed to acquire spinlock 0xd3326dc0 for a long time! kdebug> spinlock 0xd3326dc0 spinlock 0xd3326dc0: locked from 0x00000000
Should I try increasing it even more?
comment:4 by , 10 years ago
Well, you can certainly try to increase it even more. If it's a rarely used spinlock that someone forgot to release a long time before, a lot of other spinlocks may have been used in the meantime. I consider this unlikely, but anyway. Other than that, a stack trace would be nice. Also do a dw <spinlock address - 4> to see, if the object the spinlock resides in has been deleted or not yet initialized.
comment:5 by , 10 years ago
KDL session log:
To reduce noise this was done on a system with deskbar and tracker stopped. Only php-cgi was running, in a terminal.
KERN: PANIC: acquire_spinlock(): Failed to acquire spinlock 0x82a001d0 for a long time! KERN: Welcome to Kernel Debugging Land... KERN: Thread 752 "php-cgi" running on CPU 1 KERN: stack trace for thread 752 "php-cgi" KERN: kernel stack: 0xdefb3000 to 0xdefb7000 KERN: user stack: 0x712f4000 to 0x722f4000 KERN: frame caller <image>:function + offset KERN: 0 defb6848 (+ 32) 801423a6 <kernel_x86> arch_debug_stack_trace + 0x12 KERN: 1 defb6868 (+ 16) 800a229f <kernel_x86> stack_trace_trampoline(NULL) + 0x0b KERN: 2 defb6878 (+ 12) 8013416e <kernel_x86> arch_debug_call_with_fault_handler + 0x1b KERN: 3 defb6884 (+ 48) 800a3e0a <kernel_x86> debug_call_with_fault_handler + 0x5a KERN: 4 defb68b4 (+ 64) 800a24bb <kernel_x86> kernel_debugger_loop(0x80185d57 "PANIC: ", 0x80167520 "acquire_spinlock(): Failed to acquire spinlock %p for a long time!", 0xdefb6960 "iP>", int32: 1) + 0x217 KERN: 5 defb68f4 (+ 48) 800a2837 <kernel_x86> kernel_debugger_internal(0x80185d57 "PANIC: ", 0x80167520 "acquire_spinlock(): Failed to acquire spinlock %p for a long time!", 0xdefb6960 "iP>", int32: 1) + 0x53 KERN: 6 defb6924 (+ 48) 800a4192 <kernel_x86> panic + 0x3a KERN: 7 defb6954 (+ 48) 80073e73 <kernel_x86> acquire_spinlock + 0x57 KERN: 8 defb6984 (+ 64) 80078f7e <kernel_x86> BKernel::Team<0xdf02b408>::CPUTime(BKernel::Team: 0xb400, true) + 0x6e KERN: 9 defb69c4 (+ 80) 8008b5c8 <kernel_x86> BKernel::TeamTimeUserTimer<0xd3f61e88>::_Update(false) + 0x7c KERN: 10 defb6a14 (+ 48) 8008b373 <kernel_x86> BKernel::TeamTimeUserTimer<0xd3f61e88>::Update(BKernel::Thread*: NULL) + 0x67 KERN: 11 defb6a44 (+ 48) 8008d7c6 <kernel_x86> user_timer_continue_cpu_timers + 0x52 KERN: 12 defb6a74 (+ 64) 80093b3e <kernel_x86> thread_resumes(BKernel::Thread*: 0x82a00000) + 0xa6 KERN: 13 defb6ab4 (+ 240) 80094c26 <kernel_x86> reschedule(int32: 6) + 0x1016 KERN: 14 defb6ba4 (+ 48) 80094cc1 <kernel_x86> scheduler_reschedule + 0x61 KERN: 15 defb6bd4 (+ 96) 80086da2 <kernel_x86> thread_block_with_timeout + 0x1ae KERN: 16 defb6c34 (+ 64) 8005595b <kernel_x86> ConditionVariableEntry<0xdefb6ca4>::Wait(uint32: 0x9 (9), int64: 9223372036854775807) + 0x11f KERN: 17 defb6c74 (+ 96) 81596030 </boot/system/add-ons/kernel/drivers/dev/tty> RequestOwner<0xdefb6d6c>::Wait(true, int64: 9223372036854775807) + 0xd8 KERN: 18 defb6cd4 (+ 48) 81596973 </boot/system/add-ons/kernel/drivers/dev/tty> ReaderLocker<0xdefb6d60>::AcquireReader(int64: 9223372036854775807, uint32: 0x1 (1)) + 0xc7 KERN: 19 defb6d04 (+ 192) 81599607 </boot/system/add-ons/kernel/drivers/dev/tty> tty_input_read(tty_cookie*: 0xd3f25940, 0x1899a788, 0xdefb6f2c) + 0x21f KERN: 20 defb6dc4 (+ 48) 8159ab3b </boot/system/add-ons/kernel/drivers/dev/tty> slave_read(0xd3f25940, int64: 167828, 0x1899a788, 0xdefb6f2c) + 0x27 KERN: 21 defb6df4 (+ 64) 800b465a <kernel_x86> BPrivate::AbstractModuleDevice<0xd35c8ec0>::Read(0xd3f25940, int64: 167828, int64: -2379185742953207928, 0xdefb6e94) + 0x2a KERN: 22 defb6e34 (+ 80) 800b97aa <kernel_x86> devfs_read(fs_volume*: 0x82a91790, fs_vnode*: 0xd3f40570, 0xd3f35950, int64: 167828, 0x1899a788, 0xdefb6f2c) + 0x126 KERN: 23 defb6e84 (+ 64) 800f0077 <kernel_x86> file_read(file_descriptor*: 0xd3f1ef60, int64: 167828, 0x1899a788, 0xdefb6f2c) + 0x67 KERN: 24 defb6ec4 (+ 80) 800dc101 <kernel_x86> common_user_io(int32: 0, int64: -1, 0x1899a788, uint32: 0x0 (0), false) + 0x185 KERN: 25 defb6f14 (+ 48) 800dc5cc <kernel_x86> _user_read + 0x28 KERN: 26 defb6f44 (+ 100) 80136d2f <kernel_x86> handle_syscall + 0xdc KERN: user iframe at 0xdefb6fa8 (end = 0xdefb7000) KERN: eax 0x8c ebx 0x1939ea8 ecx 0x722f1d4c edx 0x61549114 KERN: esi 0x193e920 edi 0x193e920 ebp 0x722f1d88 esp 0xdefb6fdc KERN: eip 0x61549114 eflags 0x3202 user esp 0x722f1d4c KERN: vector: 0x63, error code: 0x0 KERN: 27 defb6fa8 (+ 0) 61549114 <commpage> commpage_syscall + 0x04 KERN: 28 722f1d88 (+ 48) 018bb49a <libroot.so> _IO_file_read + 0x2a KERN: 29 722f1db8 (+ 64) 018bacdf <libroot.so> _IO_new_file_underflow + 0x107 KERN: 30 722f1df8 (+ 48) 018bc971 <libroot.so> __underflow + 0xc9 KERN: 31 722f1e28 (+ 64) 018bb7f2 <libroot.so> _IO_file_xsgetn + 0xe2 KERN: 32 722f1e68 (+ 48) 018bcc6a <libroot.so> _IO_sgetn + 0x2e KERN: 33 722f1e98 (+ 48) 018be692 <libroot.so> fread + 0x4a KERN: 34 722f1ec8 (+ 48) 010f536e <php-cgi> zend_ts_hash_rehash (nearest) + 0x6a KERN: 35 722f1ef8 (+ 48) 010f55e8 <php-cgi> zend_stream_open (nearest) + 0xb0 KERN: 36 722f1f28 (+ 48) 010f5641 <php-cgi> zend_stream_open (nearest) + 0x109 KERN: 37 722f1f58 (+ 64) 010f590f <php-cgi> zend_stream_fixup + 0x28f KERN: 38 722f1f98 (+ 64) 010a80fe <php-cgi> open_file_for_scanning + 0x66 KERN: 39 722f1fd8 (+ 192) 010a8340 <php-cgi> compile_file + 0x90 KERN: 40 722f2098 (+ 128) 00fb36e2 <php-cgi> phar_flush (nearest) + 0x1d02 KERN: 41 722f2118 (+ 96) 010e0ef2 <php-cgi> zend_execute_scripts + 0xae KERN: 42 722f2178 (+5360) 0108028a <php-cgi> php_execute_script + 0x23e KERN: 43 722f3668 (+ 288) 0117e09c <php-cgi> main + 0x174c KERN: 44 722f3788 (+ 48) 00e5cc07 <php-cgi> _start + 0x5b KERN: 45 722f37b8 (+ 48) 0260e8ee </boot/system/runtime_loader@0x025fd000> <unknown> + 0x118ee KERN: 46 722f37e8 (+ 0) 61549250 <commpage> commpage_thread_exit + 0x00 KERN: kdebug> spinlock 0x82a001d0 KERN: spinlock 0x82a001d0: KERN: locked from 0x00000000 KERN: kdebug> running KERN: thread id state wait for object cpu pri stack team name KERN: 0x801cef40 1 running - 0 0 0x81001000 1 idle thread 1 KERN: 0x82a00000 752 running - 1 10 0xdefb3000 752 php-cgi KERN: kdebug>dw 0x82a001c c[0x82a001cc] ........(4...... 00000000 00000001 00003428 00000000
comment:6 by , 10 years ago
| Status: | new → assigned |
|---|
comment:7 by , 10 years ago
| Blocked By: | 11032 added |
|---|---|
| Resolution: | → duplicate |
| Status: | assigned → closed |
This is the same as #11032.
Like in #11314, this also happens with SMP disabled, in that case the message is "attempt to acquire lock twice on non-SMP system". The spinlock is still "locked from 0x0000000".