OS-6056

As part of the work in OS-3506#icft=OS-3506 I moved the dls_devnet_unset() call inside the MAC perim when called from dls_devnet_destroy(). I did this to fix a lock ordering issue – all consumers should use MAC -> DLS ordering but before this change it was DLS -> MAC, causing deadlocks.

However, moving dls_devnet_unset() inside the MAC perim and calling it with wait == B_TRUE creates a new, though harder to hit, deadlock. When wait == B_TRUE, dls_devnet_unset() will wait for all dd_tref holds to be released. After my change in OS-3506#icft=OS-3506 this wait is being done INSIDE the MAC perim. However, consumers of the dd_tref hold perform the following steps:

• Grab DLS lock

• Increment dd_tref

• Release DLS lock

• Enter MAC perim

• Do some work

• Release MAC perim

• Release dd_tref

This means that a dd_tref consumer can grab a ref but then stall on the MAC perim because another thread is in dls_devnet_unset() holding the MAC perim and waiting for all dd_tref holders to finish up. BOOM! Deadlock.

I attempted to fix this, under the same OS-3506#icft=OS-3506 ticket, by modifying drv_ioc_prop_common() and drv_ioc_attr() to use a different sequence for grabbing the tref:

@@ -671,11 +662,10 @@ drv_ioc_prop_common(dld_ioc_macprop_t *prop, intptr_t arg, boolean_t set,
                        goto done;
        }

-       if ((err = dls_devnet_hold_tmp(linkid, &dlh)) != 0)
-               goto done;
-       if ((err = mac_perim_enter_by_macname(dls_devnet_mac(dlh), &mph)) != 0)
+       if ((err = mac_perim_enter_by_linkid(linkid, &mph)) != 0)
                goto done;
-       if ((err = dls_link_hold(dls_devnet_mac(dlh), &dlp)) != 0)
+
+       if ((err = dls_devnet_hold_link(linkid, &dlh, &dlp)) != 0)
                goto done;

On the surface, this looks like it fixes the issue: it grabs the dd_tref from inside the MAC perim – but that's not actually what is happening here. If you look at the implemention of mac_perim_enter_by_linkid() you'll notice that it first has to call dls_devnet_hold_tmp() in order to get a dls_devnet_t reference. This makes sense because a) we only have the linkid but need to get its associate macname via the devnet structure, and b) if we are accessing a devnet we need to place a hold on it so we know accessing it is safe. So really this new code is like the old code but actually a little more work – I never should have made this change. To top it off, this change also introduced a new deadlock in the form of OS-5989 because we are now executing a dls_devnet_prop_task_wait().

The real solution is to move the dls_devnet_unset() back outside of the MAC perim (when wait == B_TRUE) and instead fix the dls_devnet_unset() function to not have the DLS -> MAC lock inversion. This can be done by moving the i_dls_devnet_setzid() call outside of the i_dls_devnet_lock.

Michael HIcks commented on 2017-04-13T15:10:43.000-0400 (edited 2017-04-13T16:33:01.000-0400):

[mhicks@MS941040 (us-east-1b) ~]$ thoth object /var/crash/volatile/vmdump.0 
d863ad49539df673a95c07bf245afaeb

thoth logs show this is now uploaded and I have ticketed it

[mhicks@headnode (us-east-1b) ~]$ MANTA_USER=thoth thoth ticket d863ad49539df673a95c07bf245afaeb OS-6056
thoth: using database at 165.225.169.53:28015 (configured from Manta)
thoth: adding key to job 497edde6-c671-c112-eed0-d354baec8826
thoth: processing job 497edde6-c671-c112-eed0-d354baec8826
thoth: waiting for completion of job 497edde6-c671-c112-eed0-d354baec8826
thoth: job 497edde6-c671-c112-eed0-d354baec8826 completed in 0h0m7s

Former user commented on 2017-04-13T17:16:16.000-0400:

The following is an analysis of the above dump to corroborate my bug report.

It was reported that a host had stuck zone resets and it looked like previous issues where dladm processes are all stuck. The first thing I did was login to the host and verify that dladm processes were stuck:

ps -e -o pid,ppid,etime,time,comm,args | less

This showed me tens of dladm processes which had been started 50 minutes prior but had logged no execution time – an indication that these processes are stuck. Next I turned to MDB to look for threads in the DLS module since that's what dladm calls into.

> ::stacks -m dls
THREAD           STATE    SOBJ                COUNT
ffffd0c5852544e0 SLEEP    CV                      1
                 swtch+0x141
                 cv_wait+0x70
                 dls_devnet_unset+0x1a3
                 dls_devnet_destroy+0x52
                 vnic_dev_delete+0x96
                 vnic_ioc_delete+0x28
                 drv_ioctl+0x1e4
                 cdev_ioctl+0x39
                 spec_ioctl+0x60
                 fop_ioctl+0x55
                 ioctl+0x9b

ffffd0c8be769060 SLEEP    CV                      1
                 swtch+0x141
                 cv_wait+0x70
                 i_mac_perim_enter+0x63
                 mac_perim_enter_by_mh+0x23
                 aggr_m_stat+0x35
                 mac_stat_get+0x41
                 dls_stat_update+0x49
                 dls_devnet_stat_update+0xaf
                 read_kstat_data+0xd0
                 kstat_ioctl+0x83
                 cdev_ioctl+0x39
                 spec_ioctl+0x60
                 fop_ioctl+0x55
                 ioctl+0x9b
                 _sys_sysenter_post_swapgs+0x153

ffffd0c5747540e0 SLEEP    CV                      1
                 swtch+0x141
                 cv_wait+0x70
                 i_mac_perim_enter+0x63
                 mac_perim_enter_by_mh+0x23
                 aggr_m_stat+0x35
                 mac_stat_get+0x41
                 mac_client_ifspeed+0x24
                 mac_client_stat_get+0x29d
                 vnic_m_stat+0x75
                 mac_stat_get+0x41
                 dls_stat_update+0x49
                 dls_devnet_stat_update+0xaf
                 read_kstat_data+0xd0
                 kstat_ioctl+0x83
                 cdev_ioctl+0x39
                 spec_ioctl+0x60
                 fop_ioctl+0x55
                 ioctl+0x9b
                 _sys_sysenter_post_swapgs+0x153

ffffd0c8be186000 SLEEP    CV                      1
                 swtch+0x141
                 cv_wait+0x70
                 i_mac_perim_enter+0x63
                 mac_perim_enter_by_mh+0x23
                 mac_perim_enter_by_macname+0x33
                 dls_devnet_open_in_zone+0xb9
                 devnet_create_rvp+0x2b
                 devnet_lookup+0x258
                 fop_lookup+0xa3
                 lookuppnvp+0x230
                 lookuppnatcred+0x15e
                 lookupnameatcred+0xdd
                 lookupnameat+0x39
                 vn_openat+0x315
                 copen+0x1fc
                 openat32+0x27
                 open32+0x25
                 _sys_sysenter_post_swapgs+0x153

Several threads are waiting on the MAC perim; I picked one of them and looked at its function arguments so I could figure out who owns the MAC perim.

> ffffd0c5747540e0::findstack -v
stack pointer for thread ffffd0c5747540e0: ffffd003d5052750
[ ffffd003d5052750 _resume_from_idle+0x112() ]
  ffffd003d5052780 swtch+0x141()
  ffffd003d50527c0 cv_wait+0x70(ffffd0c572e6e67c, ffffd0c572e6e668)
  ffffd003d5052800 i_mac_perim_enter+0x63(ffffd0c572e6e590)
  ffffd003d5052830 mac_perim_enter_by_mh+0x23(ffffd0c572e6e590, ffffd003d5052848)
  ffffd003d5052890 aggr_m_stat+0x35(ffffd0c5869731b8, 3e8, ffffd003d50528a8)
  ffffd003d50528d0 mac_stat_get+0x41(ffffd0c572e6e590, 3e8)
  ffffd003d5052900 mac_client_ifspeed+0x24(ffffd1001000e698)
  ffffd003d5052920 mac_client_stat_get+0x29d(ffffd1001000e698, 3e8)
  ffffd003d5052960 vnic_m_stat+0x75(ffffd0c8b6efb500, 3e8, ffffd003d5052978)
  ffffd003d50529a0 mac_stat_get+0x41(ffffd0c8bf4fd020, 3e8)
  ffffd003d50529e0 dls_stat_update+0x49(ffffd34c63b43380, ffffd0d4630b19d8, 0)
  ffffd003d5052a40 dls_devnet_stat_update+0xaf(ffffd34c63b43380, 0)
  ffffd003d5052c30 read_kstat_data+0xd0(ffffd003d5052e58, 980c168, 100001)
  ffffd003d5052c70 kstat_ioctl+0x83(200000000, 4b02, 980c168, 100001, ffffd0c582af08b0, ffffd003d5052e58)
  ffffd003d5052cb0 cdev_ioctl+0x39(200000000, 4b02, 980c168, 100001, ffffd0c582af08b0, ffffd003d5052e58)
  ffffd003d5052d00 spec_ioctl+0x60(ffffd0c571a8b040, 4b02, 980c168, 100001, ffffd0c582af08b0, ffffd003d5052e58,
  0)
  ffffd003d5052d90 fop_ioctl+0x55(ffffd0c571a8b040, 4b02, 980c168, 100001, ffffd0c582af08b0, ffffd003d5052e58, 0
  )
  ffffd003d5052eb0 ioctl+0x9b(b, 4b02, 980c168)
  ffffd003d5052f10 _sys_sysenter_post_swapgs+0x153()

I also linked this thread to it's process – the CMON agent.

> ffffd0c5747540e0::print kthread_t t_procp | ::print proc_t p_user.u_psargs
p_user.u_psargs = [ "/opt/smartdc/agents/lib/node_modules/cmon-agent/node/bin/node --abort_on_uncaug" ]

Who owns the MAC perim?

> ffffd0c572e6e590::print mac_impl_t mi_perim_owner | ::findstack -v
stack pointer for thread ffffd0c5852544e0: ffffd003d8a40a30
[ ffffd003d8a40a30 _resume_from_idle+0x112() ]
  ffffd003d8a40a60 swtch+0x141()
  ffffd003d8a40aa0 cv_wait+0x70(ffffd0c8e8fbd180, ffffd0c8e8fbd178)
  ffffd003d8a40b00 dls_devnet_unset+0x1a3(ffffd0c8bf4fd038, ffffd003d8a40b9c, 1)
  ffffd003d8a40b70 dls_devnet_destroy+0x52(ffffd0c8bf4fd020, ffffd003d8a40b9c, 1)
  ffffd003d8a40be0 vnic_dev_delete+0x96(1565, 0, ffffd13fb455bed8)
  ffffd003d8a40c20 vnic_ioc_delete+0x28(ffffd0c91cfee710, ffffbf7ffe2cc6d0, 202003, ffffd13fb455bed8,
  ffffd003d8a40ea8)
  ffffd003d8a40cc0 drv_ioctl+0x1e4(1200000000, 1710002, ffffbf7ffe2cc6d0, 202003, ffffd13fb455bed8,
  ffffd003d8a40ea8)
  ffffd003d8a40d00 cdev_ioctl+0x39(1200000000, 1710002, ffffbf7ffe2cc6d0, 202003, ffffd13fb455bed8,
  ffffd003d8a40ea8)
  ffffd003d8a40d50 spec_ioctl+0x60(ffffd0c56fee2500, 1710002, ffffbf7ffe2cc6d0, 202003, ffffd13fb455bed8,
  ffffd003d8a40ea8, 0)
  ffffd003d8a40de0 fop_ioctl+0x55(ffffd0c56fee2500, 1710002, ffffbf7ffe2cc6d0, 202003, ffffd13fb455bed8,
  ffffd003d8a40ea8, 0)
  ffffd003d8a40f00 ioctl+0x9b(3, 1710002, ffffbf7ffe2cc6d0)
  ffffd003d8a40f10 sys_syscall+0x1a2()

So there's a thread trying to delete a VNIC and is waiting in dls_devnet_unset() for dd_tref or the prop task to finish. Let's look at the devnet structure and find out what exactly it's waiting for.

> ::print -at dls_devnet_t
0 dls_devnet_t {
    0 datalink_id_t dd_linkid
    4 char [32] dd_linkname
    24 char [256] dd_mac
    128 kstat_t *dd_ksp
    130 kstat_t *dd_zone_ksp
    138 uint32_t dd_ref
    140 kmutex_t dd_mutex {
        140 void *[1] _opaque
    }
    148 kcondvar_t dd_cv {
        148 ushort_t _opaque
    }
    14c uint32_t dd_tref
    150 uint_t dd_flags
    154 zoneid_t dd_owner_zid
    158 zoneid_t dd_zid
    15c boolean_t dd_prop_loaded
    160 taskqid_t dd_prop_taskid
    168 boolean_t dd_transient
}
> ffffd0c8e8fbd180 - 148::print dls_devnet_t
{
    dd_linkid = 0x1565
    dd_linkname = [ "net0" ]
    dd_mac = [ "vnic6776" ]
    dd_ksp = 0xffffd34c63b43380
    dd_zone_ksp = 0
    dd_ref = 0
    dd_mutex = {
        _opaque = [ 0 ]
    }
    dd_cv = {
        _opaque = 0x1
    }
    dd_tref = 0x1
    dd_flags = 0x1
    dd_owner_zid = 0
    dd_zid = 0
    dd_prop_loaded = 0x1 (B_TRUE)
    dd_prop_taskid = 0
    dd_transient = 0 (0)
}

Since dd_prop_taskid is NULL and dd_tref = 1 we know that dls_devnet_unset() is waiting on the dd_tref to reach 0. So who's holding onto the tref? To answer this you need to be familiar with the DLD/DLS/MAC code. I knew that more than likely it was drv_ioc_prop_common() or drv_ioc_attr().

> ::stacks -c drv_ioc_prop_common
> ::stacks -c drv_ioc_attr
THREAD           STATE    SOBJ                COUNT
ffffd0c8a25f5760 SLEEP    CV                      1
                 swtch+0x141
                 cv_wait+0x70
                 i_mac_perim_enter+0x63
                 mac_perim_enter_by_mh+0x23
                 mac_perim_enter_by_linkid+0x33
                 drv_ioc_attr+0x53
                 drv_ioctl+0x1e4
                 cdev_ioctl+0x39
                 spec_ioctl+0x60
                 fop_ioctl+0x55
                 ioctl+0x9b
                 _sys_sysenter_post_swapgs+0x153

> ffffd0c8a25f5760::findstack -v
stack pointer for thread ffffd0c8a25f5760: ffffd003d3776a20
[ ffffd003d3776a20 _resume_from_idle+0x112() ]
  ffffd003d3776a50 swtch+0x141()
  ffffd003d3776a90 cv_wait+0x70(ffffd0c572e6e67c, ffffd0c572e6e668)
  ffffd003d3776ad0 i_mac_perim_enter+0x63(ffffd0c572e6e590)
  ffffd003d3776b00 mac_perim_enter_by_mh+0x23(ffffd0c572e6e590, ffffd003d3776b70)
  ffffd003d3776b50 mac_perim_enter_by_linkid+0x33(7, ffffd003d3776b70)
  ffffd003d3776bd0 drv_ioc_attr+0x53(ffffd0c8ae2d4830, 80411f8, 100003, ffffd0c92193fe20, ffffd003d3776e58)
  ffffd003d3776c70 drv_ioctl+0x1e4(1200000000, d1d0003, 80411f8, 100003, ffffd0c92193fe20, ffffd003d3776e58)
  ffffd003d3776cb0 cdev_ioctl+0x39(1200000000, d1d0003, 80411f8, 100003, ffffd0c92193fe20, ffffd003d3776e58)
  ffffd003d3776d00 spec_ioctl+0x60(ffffd0c56fee2500, d1d0003, 80411f8, 100003, ffffd0c92193fe20,
  ffffd003d3776e58, 0)
  ffffd003d3776d90 fop_ioctl+0x55(ffffd0c56fee2500, d1d0003, 80411f8, 100003, ffffd0c92193fe20, ffffd003d3776e58
  , 0)
  ffffd003d3776eb0 ioctl+0x9b(3, d1d0003, 80411f8)
  ffffd003d3776f10 _sys_sysenter_post_swapgs+0x153()

And sure enough this thread calling into drv_ioc_attr() holds the dd_tref but is also waiting on the same MAC perim (ffffd0c572e6e590) that dls_devnet_unset() already holds – deadlock.

Former user commented on 2017-04-13T17:24:48.000-0400:

The changes in OS-3506#icft=OS-3506 introduced this deadlock.

Former user commented on 2017-05-04T01:29:52.000-0400:

I tested this by running the same tests I ran for OS-3506. This testing has reliably produced deadlocks in the past.

• Create 121 zones and concurrently start half and stop half: repeat this in a while loop.

• Put load on dladm by running many commands concurrently (sometimes I'll have 3000+ dladm processes running): such as show-link, show-phys, show-vnic, and show-linkprop.

• Use dtrace chill action on MAC perim entry and i_dls_devnet_hold acquisition.

• Enable all dtrace probes on dlmgmtd a.out, DLS, and MAC in an attempt to tease out various interleaving.

• Run tests on both 12 CPU home workstation and 1 CPU and 2 CPU VMWare instance.

• Run on DEBUG and non-DEBUG.

• Run test for hours.

Former user commented on 2017-05-19T15:53:27.000-0400: