Date: Sat, 25 May 2013 19:52:03 +0200 From: =?ISO-8859-1?Q?Roger_Pau_Monn=E9?= <roger.pau@citrix.com> To: John Baldwin <jhb@freebsd.org> Cc: Konstantin Belousov <kostikbel@gmail.com>, freebsd-current@freebsd.org, "current@freebsd.org" <current@freebsd.org> Subject: Re: FreeBSD-HEAD gets stuck on vnode operations Message-ID: <51A0FA43.2040503@citrix.com> In-Reply-To: <201305201434.55406.jhb@freebsd.org> References: <5190CBEC.5000704@citrix.com> <20130514163149.GS3047@kib.kiev.ua> <51927143.4080102@citrix.com> <201305201434.55406.jhb@freebsd.org>
next in thread | previous in thread | raw e-mail | index | archive | help
On 20/05/13 20:34, John Baldwin wrote:
> On Tuesday, May 14, 2013 1:15:47 pm Roger Pau Monné wrote:
>> On 14/05/13 18:31, Konstantin Belousov wrote:
>>> On Tue, May 14, 2013 at 06:08:45PM +0200, Roger Pau Monn? wrote:
>>>> On 13/05/13 17:00, Konstantin Belousov wrote:
>>>>> On Mon, May 13, 2013 at 04:33:04PM +0200, Roger Pau Monn? wrote:
>>>>>> On 13/05/13 13:18, Roger Pau Monn? wrote:
>>>>
>>>> Thanks for taking a look,
>>>>
>>>>>> I would like to explain this a little bit more, the syncer process
>>>>>> doesn't get blocked on the _mtx_trylock_flags_ call, it just continues
>>>>>> looping forever in what seems to be an endless loop around
>>>>>> mnt_vnode_next_active/ffs_sync. Also while in this state there is no
>>>>>> noticeable disk activity, so I'm unsure of what is happening.
>>>>> How many CPUs does your VM have ?
>>>>
>>>> 7 vCPUs, but I've also seen this issue with 4 and 16 vCPUs.
>>>>
>>>>>
>>>>> The loop you describing means that other thread owns the vnode
>>>>> interlock. Can you track what this thread does ? E.g. look at the
>>>>> vp->v_interlock.mtx_lock, which is basically a pointer to the struct
>>>>> thread owning the mutex, clear low bits as needed. Then you can
>>>>> inspect the thread and get a backtrace.
>>>>
>>>> There are no other threads running, only syncer is running on CPU 1 (see
>>>> ps in previous email). All other CPUs are idle, and as seen from the ps
>>>> quite a lot of threads are blocked in vnode related operations, either
>>>> "*Name Cac", "*vnode_fr" or "*vnode in". I've also attached the output
>>>> of alllocks in the previous email.
>>> This is not useful. You need to look at the mutex which fails the
>>> trylock operation in the mnt_vnode_next_active(), see who owns it,
>>> and then 'unwind' the locking dependencies from there.
>>
>> Sorry, now I get it, let's see if I can find the locked vnodes and the
>> thread that owns them...
>
> You can use 'show lock <address of vp->v_interlock>' to find an owning
> thread and then use 'show sleepchain <thread>'. If you are using kgdb on the
> live system (probably easier) then you can grab my scripts at
> www.freebsd.org/~jhb/gdb/ (do 'cd /path/to/scripts; source gdb6'). You can
> then find the offending thread and do 'mtx_owner &vp->v_interlock' and then
> 'sleepchain <tid>'
Hello,
Sorry for the delay in debugging this, but the fact that the issue
itself is hard to reproduce, and that I didn't have much time prevented
me from digging into this. It seems like the locked node is always the
same, or at least I haven't been able to see this loop with more than
one node locked (so far):
db> show lock 0xfffffe0030cdf448
class: sleep mutex
name: vnode interlock
flags: {DEF}
state: {OWNED}
owner: 0xfffffe008d1e9000 (tid 101020, pid 66630, "cc")
db> show sleepchain 0xfffffe008d1e9000
thread 101020 (pid 66630, cc) inhibited
db> tr 66630
Tracing pid 66630 tid 101020 td 0xfffffe008d1e9000
sched_switch() at sched_switch+0x482/frame 0xffffff8120ff3630
mi_switch() at mi_switch+0x179/frame 0xffffff8120ff3670
turnstile_wait() at turnstile_wait+0x3ac/frame 0xffffff8120ff36c0
__mtx_lock_sleep() at __mtx_lock_sleep+0x255/frame 0xffffff8120ff3740
__mtx_lock_flags() at __mtx_lock_flags+0xda/frame 0xffffff8120ff3780
vdropl() at vdropl+0x255/frame 0xffffff8120ff37b0
vputx() at vputx+0x27c/frame 0xffffff8120ff3810
namei() at namei+0x3dd/frame 0xffffff8120ff38c0
kern_statat_vnhook() at kern_statat_vnhook+0x99/frame 0xffffff8120ff3a40
sys_stat() at sys_stat+0x2d/frame 0xffffff8120ff3ae0
amd64_syscall() at amd64_syscall+0x265/frame 0xffffff8120ff3bf0
Xfast_syscall() at Xfast_syscall+0xfb/frame 0xffffff8120ff3bf0
--- syscall (188, FreeBSD ELF64, sys_stat), rip = 0x18280ea, rsp = 0x7fffffffa148, rbp = 0x7fffffffa170 ---
db> ps
pid ppid pgrp uid state wmesg wchan cmd
66630 66591 66588 0 L+ *vnode_fr 0xfffffe000bc9fa80 cc
66591 66590 66588 0 S+ wait 0xfffffe0030dbd4b8 cc
66590 66588 66588 0 S+ wait 0xfffffe008de20000 sh
66588 66572 66588 0 S+ wait 0xfffffe008d8a8970 sh
66572 49649 49649 0 S+ select 0xfffffe003029dac0 make
49649 49631 49649 0 S+ wait 0xfffffe000d801970 sh
49631 49629 49629 0 S+ select 0xfffffe00302b3cc0 make
49629 49614 49629 0 S+ wait 0xfffffe008dbfa970 sh
49614 45214 45214 0 S+ select 0xfffffe00303e3640 make
45214 45207 45214 0 S+ wait 0xfffffe008dbfa000 sh
45207 45205 45200 0 S+ select 0xfffffe000d66d3c0 make
45205 45200 45200 0 S+ wait 0xfffffe008da1b4b8 sh
45200 757 45200 0 S+ select 0xfffffe000d6093c0 make
30611 737 30611 0 S+ ttyin 0xfffffe000bd70ca8 bash
2325 756 2325 0 Ss+ ttyin 0xfffffe008dd6eca8 bash
757 756 757 0 Ss+ wait 0xfffffe000d7fd4b8 bash
756 755 756 0 Ss select 0xfffffe000d783a40 screen
755 744 755 0 S+ pause 0xfffffe000d9560a8 screen
744 743 744 0 S+ wait 0xfffffe000d4d6970 bash
743 742 743 1001 S+ wait 0xfffffe000d4d5000 su
742 741 742 1001 Ss+ wait 0xfffffe000d6674b8 sh
741 738 738 1001 S select 0xfffffe000d60a8c0 sshd
738 680 738 0 Ss select 0xfffffe000d60a940 sshd
737 1 737 0 Ss+ wait 0xfffffe000d605970 login
736 1 736 0 Ss+ ttyin 0xfffffe000bd718a8 getty
735 1 735 0 Ss+ ttyin 0xfffffe000bd71ca8 getty
734 1 734 0 Ss+ ttyin 0xfffffe000bfcc0a8 getty
733 1 733 0 Ss+ ttyin 0xfffffe000bfcc4a8 getty
732 1 732 0 Ss+ ttyin 0xfffffe000bfcc8a8 getty
731 1 731 0 Ss+ ttyin 0xfffffe000bd700a8 getty
730 1 730 0 Ss+ ttyin 0xfffffe000bd704a8 getty
729 1 729 0 Ss+ ttyin 0xfffffe000bd708a8 getty
690 1 690 0 Ss nanslp 0xffffffff81343734 cron
686 1 686 25 Ss pause 0xfffffe000d77a560 sendmail
683 1 683 0 Ss select 0xfffffe000d7834c0 sendmail
680 1 680 0 Ss select 0xfffffe000d4a5e40 sshd
580 1 580 0 Ss select 0xfffffe000d66d040 syslogd
486 1 486 0 Ss select 0xfffffe000d783540 devd
485 1 485 65 Ss select 0xfffffe000d962040 dhclient
445 1 445 0 Ss select 0xfffffe000d66d1c0 dhclient
18 0 0 0 DL sdflush 0xffffffff8153675c [softdepflush]
17 0 0 0 DL vlruwt 0xfffffe000d4d5970 [vnlru]
9 0 0 0 RL CPU 2 [syncer]
8 0 0 0 DL psleep 0xffffffff8152f72c [bufdaemon]
7 0 0 0 DL pgzero 0xffffffff81537e8c [pagezero]
6 0 0 0 DL psleep 0xffffffff815370d0 [vmdaemon]
5 0 0 0 DL psleep 0xffffffff815b3304 [pagedaemon]
4 0 0 0 DL ccb_scan 0xffffffff813038b0 [xpt_thrd]
3 0 0 0 DL waiting_ 0xffffffff815a73e0 [sctp_iterator]
2 0 0 0 DL balloon 0xffffffff8079d310 [balloon]
16 0 0 0 SL xbread 0xfffffe00feffc000 [xenstore_rcv]
15 0 0 0 SL waitev 0xffffffff81538098 [xenwatch]
14 0 0 0 DL - 0xffffffff8131f988 [yarrow]
13 0 0 0 DL (threaded) [geom]
100021 D - 0xffffffff8159bc70 [g_down]
100020 D - 0xffffffff8159bc68 [g_up]
100019 D - 0xffffffff8159bc60 [g_event]
12 0 0 0 WL (threaded) [intr]
100050 I [irq778: xn0]
100049 I [irq777: xbd1]
100048 I [irq776: xbd0]
100042 I [irq7: ppc0]
100041 I [swi0: uart]
100040 I [irq12: psm0]
100039 I [irq1: atkbd0]
100036 I [irq775: xenstore0]
100035 I [irq15: ata1]
100034 I [irq14: ata0]
100032 I [swi5: fast taskq]
100030 I [swi6: Giant taskq]
100029 I [swi6: task queue]
100024 I [swi2: cambio]
100018 I [swi3: vm]
100017 I [swi4: clock]
100016 I [swi4: clock]
100015 I [swi4: clock]
100014 I [swi4: clock]
100013 I [swi4: clock]
100012 I [swi4: clock]
100011 I [swi4: clock]
100010 I [swi1: netisr 0]
11 0 0 0 RL (threaded) [idle]
100009 Run CPU 6 [idle: cpu6]
100008 Run CPU 5 [idle: cpu5]
100007 Run CPU 4 [idle: cpu4]
100006 Run CPU 3 [idle: cpu3]
100005 CanRun [idle: cpu2]
100004 Run CPU 1 [idle: cpu1]
100003 Run CPU 0 [idle: cpu0]
1 0 1 0 SLs wait 0xfffffe000bc77970 [init]
10 0 0 0 DL audit_wo 0xffffffff815aaae0 [audit]
0 0 0 0 DLs (threaded) [kernel]
100044 D - 0xffffffff81342593 [deadlkres]
100043 D - 0xfffffe000bfc5300 [mca taskq]
100033 D - 0xfffffe000bcaa600 [kqueue taskq]
100031 D - 0xfffffe000bcaaa00 [thread taskq]
100028 D - 0xfffffe000be5c100 [ffs_trim taskq]
100027 D - 0xfffffe000bca1300 [acpi_task_2]
100026 D - 0xfffffe000bca1300 [acpi_task_1]
100025 D - 0xfffffe000bca1300 [acpi_task_0]
100022 D - 0xfffffe000bc6e300 [firmware taskq]
100000 D sched 0xffffffff8159bd68 [swapper]
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?51A0FA43.2040503>