Opened 5 years ago

Closed 5 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:
Has a Patch: no 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 pulkomandy, 5 years ago

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".

in reply to:  description comment:2 by bonefish, 5 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 pulkomandy, 5 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 bonefish, 5 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 pulkomandy, 5 years ago

KDL session log:

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
Version 1, edited 5 years ago by pulkomandy (previous) (next) (diff)

comment:6 by bonefish, 5 years ago

Status: newassigned

comment:7 by mmlr, 5 years ago

Blocked By: 11032 added
Resolution: duplicate
Status: assignedclosed

This is the same as #11032.

Note: See TracTickets for help on using tickets.