Drivers unbind hangs forever because of incorrect reference count.

[tholin]

I use 595.99.02 NVIDIA Linux Open GPU Kernel drivers and sometimes need to unbind the nvidia drivers to load another driver. This usually works fine but if any process uses the GPU at unbind time then the unbind stalls. It is expected behavior according to the comment in nv-pci.c (https://github.com/NVIDIA/open-gpu-kernel-modules/blob/595.99.02/kernel-open/nvidia/nv-pci.c#L2339-L2340). The problem is that even if I kill all processes using the GPU the unbind still stalls indefinitely because of an incorrect nvl->usage_count reference count.

Here are the steps to reproduce and verify:

I use this patch to get a debug printout of the state of the reference count.

diff --git a/kernel-open/nvidia/nv-pci.c b/kernel-open/nvidia/nv-pci.c
index 619e57a3..d3c66fc1 100644
--- a/kernel-open/nvidia/nv-pci.c
+++ b/kernel-open/nvidia/nv-pci.c
@@ -2330,17 +2330,18 @@ static void nv_pci_remove_helper(struct pci_dev *pci_dev, bool block_if_gpu_in_u
      */
     if ((atomic64_read(&nvl->usage_count) != 0) && !(nv->is_external_gpu))
     {
-        nv_printf(NV_DBG_ERRORS,
-                  "NVRM: Attempting to remove device %04x:%02x:%02x.%x with non-zero usage count!\n",
-                  NV_PCI_DOMAIN_NUMBER(pci_dev), NV_PCI_BUS_NUMBER(pci_dev),
-                  NV_PCI_SLOT_NUMBER(pci_dev), PCI_FUNC(pci_dev->devfn));
-
         /*
          * We can't return from this function without corrupting state, so we wait for
          * the usage count to go to zero.
          */
         while (atomic64_read(&nvl->usage_count) != 0)
         {
+            /* Move the print inside the loop */
+            nv_printf(NV_DBG_ERRORS,
+                "NVRM: Attempting to remove device %04x:%02x:%02x.%x with non-zero usage count = %lld\n",
+                NV_PCI_DOMAIN_NUMBER(pci_dev), NV_PCI_BUS_NUMBER(pci_dev),
+                NV_PCI_SLOT_NUMBER(pci_dev), PCI_FUNC(pci_dev->devfn), (long long)atomic64_read(&nvl->usage_count));
+
             /*
              * While waiting, release the locks so that other threads can make
              * forward progress.
@@ -2348,7 +2349,7 @@ static void nv_pci_remove_helper(struct pci_dev *pci_dev, bool block_if_gpu_in_u
             up(&nvl->ldata_lock);
             UNLOCK_NV_LINUX_DEVICES();
 
-            os_delay(500);
+            os_delay(5000); /* Don't spam so often */
 
             /* Re-acquire the locks before checking again */
             LOCK_NV_LINUX_DEVICES();
diff --git a/kernel-open/nvidia/nv.c b/kernel-open/nvidia/nv.c
index 1bea50a5..42514554 100644
--- a/kernel-open/nvidia/nv.c
+++ b/kernel-open/nvidia/nv.c
@@ -111,6 +111,13 @@
 #include <soc/tegra/bpmp-abi.h>
 #endif
 
+#define NVREFDBG(op)                                                           \
+    pr_info("NVRM: NVREFDBG " op " %s:%d usage_count@%px = %lld pid=%d"        \
+            " comm=%s caller=%pS\n", __func__, __LINE__,                       \
+            nvl ? (void *)&nvl->usage_count : NULL,                            \
+            nvl ? (long long)atomic64_read(&nvl->usage_count) : -1LL,          \
+            current->pid, current->comm, __builtin_return_address(0))
+
 #define RM_THRESHOLD_TOTAL_IRQ_COUNT     100000
 #define RM_THRESHOLD_UNAHNDLED_IRQ_COUNT 99900
 #define RM_UNHANDLED_TIMEOUT_US          100000
@@ -1720,6 +1727,7 @@ static int nv_open_device(nv_state_t *nv, nvidia_stack_t *sp)
     nv_assert_not_in_gpu_exclusion_list(sp, nv);
 
     atomic64_inc(&nvl->usage_count);
+    NVREFDBG("INC");
 
     return 0;
 }
@@ -2149,6 +2157,7 @@ static void nv_close_device(nv_state_t *nv, nvidia_stack_t *sp)
         if (!nvl->init_on_probe)
             nv_stop_device(nv, sp);
     }
+    NVREFDBG("DEC");
 }
 
 /*
@@ -5379,7 +5388,10 @@ void nvidia_dev_put(NvU32 gpu_id, nvidia_stack_t *sp, NvBool reset_aware)
     /* Takes nvl->ldata_lock */
     nvl = find_gpu_id(gpu_id);
     if (!nvl)
+    {
+        NVREFDBG("DEC SKIPPED? find_gpu_id() returned nothing");
         return;
+    }
 
     nv_close_device(NV_STATE_PTR(nvl), sp);
 
@@ -5458,7 +5470,10 @@ void nvidia_dev_put_uuid(const NvU8 *uuid, nvidia_stack_t *sp)
     /* Takes nvl->ldata_lock */
     nvl = find_uuid(uuid);
     if (!nvl)
+    {
+        NVREFDBG("DEC SKIPPED? find_uuid() returned nothing");
         return;
+    }
 
     nv_close_device(NV_STATE_PTR(nvl), sp);

If I start and then kill a CUDA workload, I get this print:

NVRM: NVREFDBG INC nv_open_device:1730 usage_count@ffff8ec0d0ea83a0 = 1 pid=284637 comm=llama-server caller=nv_start_device+0xc3e/0x1000 [nvidia]
NVRM: NVREFDBG INC nv_open_device:1730 usage_count@ffff8ec0d0ea83a0 = 2 pid=284637 comm=llama-server caller=nv_start_device+0xc3e/0x1000 [nvidia]
NVRM: NVREFDBG INC nv_open_device:1730 usage_count@ffff8ec0d0ea83a0 = 3 pid=284637 comm=llama-server caller=nv_start_device+0xc3e/0x1000 [nvidia]
NVRM: NVREFDBG INC nv_open_device:1730 usage_count@ffff8ec0d0ea83a0 = 4 pid=284637 comm=llama-server caller=nv_start_device+0xc3e/0x1000 [nvidia]
NVRM: NVREFDBG INC nv_open_device:1730 usage_count@ffff8ec0d0ea83a0 = 5 pid=284637 comm=llama-server caller=nv_start_device+0xc3e/0x1000 [nvidia]
NVRM: NVREFDBG INC nv_open_device:1730 usage_count@ffff8ec0d0ea83a0 = 6 pid=284637 comm=llama-server caller=nv_start_device+0xc3e/0x1000 [nvidia]
NVRM: NVREFDBG INC nv_open_device:1730 usage_count@ffff8ec0d0ea83a0 = 7 pid=284637 comm=llama-server caller=nvidia_dev_get_uuid+0x5f/0xc0 [nvidia]
NVRM: NVREFDBG DEC nv_close_device:2160 usage_count@ffff8ec0d0ea83a0 = 6 pid=284639 comm=llama-server caller=nv_stop_device+0x243/0x370 [nvidia]
NVRM: NVREFDBG DEC nv_close_device:2160 usage_count@ffff8ec0d0ea83a0 = 5 pid=284639 comm=llama-server caller=nv_stop_device+0x243/0x370 [nvidia]
NVRM: NVREFDBG DEC nv_close_device:2160 usage_count@ffff8ec0d0ea83a0 = 4 pid=284639 comm=llama-server caller=nv_stop_device+0x243/0x370 [nvidia]
NVRM: NVREFDBG DEC nv_close_device:2160 usage_count@ffff8ec0d0ea83a0 = 3 pid=284639 comm=llama-server caller=nv_stop_device+0x243/0x370 [nvidia]
NVRM: NVREFDBG DEC nv_close_device:2160 usage_count@ffff8ec0d0ea83a0 = 2 pid=284639 comm=llama-server caller=nvidia_dev_put_uuid+0x22/0x90 [nvidia]
NVRM: NVREFDBG DEC nv_close_device:2160 usage_count@ffff8ec0d0ea83a0 = 1 pid=284639 comm=llama-server caller=nv_stop_device+0x243/0x370 [nvidia]
NVRM: NVREFDBG DEC nv_close_device:2160 usage_count@ffff8ec0d0ea83a0 = 0 pid=284639 comm=llama-server caller=nv_stop_device+0x243/0x370 [nvidia]

There are 6 increases from nv_start_device and 6 corresponding decreases from nv_stop_device. There is 1 increase from nvidia_dev_get_uuid and a corresponding decrease from nvidia_dev_put_uuid. All the references are accounted for in this example.

If I instead try to start a CUDA workload, then unbind the drivers with echo 0000:01:00.0 > /sys/bus/pci/drivers/nvidia/unbind followed by killing the CUDA workload I get this:

NVRM: NVREFDBG INC nv_open_device:1730 usage_count@ffff8ec0d0ea83a0 = 1 pid=284913 comm=llama-server caller=nv_start_device+0xc3e/0x1000 [nvidia]
NVRM: NVREFDBG INC nv_open_device:1730 usage_count@ffff8ec0d0ea83a0 = 2 pid=284913 comm=llama-server caller=nv_start_device+0xc3e/0x1000 [nvidia]
NVRM: NVREFDBG INC nv_open_device:1730 usage_count@ffff8ec0d0ea83a0 = 3 pid=284913 comm=llama-server caller=nv_start_device+0xc3e/0x1000 [nvidia]
NVRM: NVREFDBG INC nv_open_device:1730 usage_count@ffff8ec0d0ea83a0 = 4 pid=284913 comm=llama-server caller=nv_start_device+0xc3e/0x1000 [nvidia]
NVRM: NVREFDBG INC nv_open_device:1730 usage_count@ffff8ec0d0ea83a0 = 5 pid=284913 comm=llama-server caller=nv_start_device+0xc3e/0x1000 [nvidia]
NVRM: NVREFDBG INC nv_open_device:1730 usage_count@ffff8ec0d0ea83a0 = 6 pid=284913 comm=llama-server caller=nv_start_device+0xc3e/0x1000 [nvidia]
NVRM: NVREFDBG INC nv_open_device:1730 usage_count@ffff8ec0d0ea83a0 = 7 pid=284913 comm=llama-server caller=nvidia_dev_get_uuid+0x5f/0xc0 [nvidia]
(running echo 0000:01:00.0 > /sys/bus/pci/drivers/nvidia/unbind)
NVRM: Attempting to remove device 0000:01:00.0 with non-zero usage count = 7
NVRM: Attempting to remove device 0000:01:00.0 with non-zero usage count = 7
NVRM: NVREFDBG DEC nv_close_device:2160 usage_count@ffff8ec0d0ea83a0 = 6 pid=284915 comm=llama-server caller=nv_stop_device+0x243/0x370 [nvidia]
NVRM: NVREFDBG DEC nv_close_device:2160 usage_count@ffff8ec0d0ea83a0 = 5 pid=284915 comm=llama-server caller=nv_stop_device+0x243/0x370 [nvidia]
NVRM: NVREFDBG DEC nv_close_device:2160 usage_count@ffff8ec0d0ea83a0 = 4 pid=284915 comm=llama-server caller=nv_stop_device+0x243/0x370 [nvidia]
NVRM: NVREFDBG DEC nv_close_device:2160 usage_count@ffff8ec0d0ea83a0 = 3 pid=284915 comm=llama-server caller=nv_stop_device+0x243/0x370 [nvidia]
NVRM: NVREFDBG DEC SKIPPED? find_uuid() returned nothing nvidia_dev_put_uuid:5474 usage_count@0000000000000000 = -1 pid=284915 comm=llama-server caller=nvUvmInterfaceUnregisterGpu+0x28/0x70 [nvidia]
NVRM: NVREFDBG DEC nv_close_device:2160 usage_count@ffff8ec0d0ea83a0 = 2 pid=284915 comm=llama-server caller=nv_stop_device+0x243/0x370 [nvidia]
NVRM: NVREFDBG DEC nv_close_device:2160 usage_count@ffff8ec0d0ea83a0 = 1 pid=284915 comm=llama-server caller=nv_stop_device+0x243/0x370 [nvidia]
NVRM: Attempting to remove device 0000:01:00.0 with non-zero usage count = 1
NVRM: Attempting to remove device 0000:01:00.0 with non-zero usage count = 1
NVRM: Attempting to remove device 0000:01:00.0 with non-zero usage count = 1
NVRM: Attempting to remove device 0000:01:00.0 with non-zero usage count = 1

This time the nvidia_dev_put_uuid decrease didn't fire and the usage_count is stuck at 1 indefinitely. The call to find_uuid in nvidia_dev_put_uuid failed and the function returned early without decreasing the refcount.

find_uuid() searches the global list of nv devices (nv_linux_devices) for the one with the given UUID and will return NULL if the UUID is not found. In this case the relevant device is not in nv_linux_devices because it was already removed by nv_linux_remove_device_locked here: https://github.com/NVIDIA/open-gpu-kernel-modules/blob/595.99.02/kernel-open/nvidia/nv-pci.c#L2322 just before the waiting began.

So the chain of events is:

• The device is removed from nv_linux_devices at nv-pci.c:2322
• If nvl->usage_count != 0 then wait for all users to exit
• nvidia_dev_put_uuid now fails to find the device and returns without stopping the device or decreasing the refcount.
• The wait turns into an infinite loop.

I have only observed this happening for nvidia_dev_put_uuid but it can probably also happen in nvidia_dev_put since find_gpu_id also searches the global list.

I also wish that the dmesg warning "Attempting to remove device 0000:01:00.0 with non-zero usage count!" could be more informative and indicate that the kernel is actively waiting for the user to kill processes to make the usage count drop. I had to read the code to realize that.

595.99.02 is not the latest driver but the relevant code looks the same in the latest release.