venus: print warnings when stuck in busy waits

The first warning is printed after stuck in vn_relax for at least about
3.5s.  The actual time can be much longer depending on the
kernel/load/hw.

Signed-off-by: Chia-I Wu <olvaffe@gmail.com>
Reviewed-by: Yiwei Zhang <zzyiwei@chromium.org>
Reviewed-by: Ryan Neph <ryanneph@google.com>
Part-of: <https://gitlab.freedesktop.org/mesa/mesa/-/merge_requests/12115>

src/virtio/vulkan/vn_common.c

@@ -62,10 +62,15 @@ vn_log_result(struct vn_instance *instance,
 }
 
 void
-vn_relax(uint32_t *iter)
+vn_relax(uint32_t *iter, const char *reason)
 {
+   /* Yield for the first 2^busy_wait_order times and then sleep for
+    * base_sleep_us microseconds for the same number of times.  After that,
+    * keep doubling both sleep length and count.
+    */
    const uint32_t busy_wait_order = 4;
    const uint32_t base_sleep_us = 10;
+   const uint32_t warn_order = 12;
 
    (*iter)++;
    if (*iter < (1 << busy_wait_order)) {
@@ -73,6 +78,12 @@ vn_relax(uint32_t *iter)
       return;
    }
 
+   /* warn occasionally if we have slept at least 1.28ms for 2048 times (plus
+    * another 2047 shorter sleeps)
+    */
+   if (unlikely(*iter % (1 << warn_order) == 0))
+      vn_log(NULL, "stuck in %s wait with iter at %d", reason, *iter);
+
    const uint32_t shift = util_last_bit(*iter) - busy_wait_order - 1;
    os_time_sleep(base_sleep_us << shift);
 }

src/virtio/vulkan/vn_common.h

@@ -133,7 +133,7 @@ vn_log_result(struct vn_instance *instance,
               const char *where);
 
 void
-vn_relax(uint32_t *iter);
+vn_relax(uint32_t *iter, const char *reason);
 
 static_assert(sizeof(vn_object_id) >= sizeof(uintptr_t), "");
 

src/virtio/vulkan/vn_device.c

@@ -303,7 +303,7 @@ vn_instance_wait_roundtrip(struct vn_instance *instance,
       const uint32_t cur = atomic_load_explicit(ptr, memory_order_acquire);
       if (cur >= roundtrip_seqno || roundtrip_seqno - cur >= INT32_MAX)
          break;
-      vn_relax(&iter);
+      vn_relax(&iter, "roundtrip");
    } while (true);
 }
 

src/virtio/vulkan/vn_queue.c

@@ -613,7 +613,7 @@ vn_update_sync_result(VkResult result, int64_t abs_timeout, uint32_t *iter)
           os_time_get_nano() >= abs_timeout)
          result = VK_TIMEOUT;
       else
-         vn_relax(iter);
+         vn_relax(iter, "client");
       break;
    default:
       assert(result == VK_SUCCESS || result < 0);

src/virtio/vulkan/vn_ring.c

@@ -100,7 +100,7 @@ vn_ring_wait_seqno(const struct vn_ring *ring, uint32_t seqno)
       const uint32_t head = vn_ring_load_head(ring);
       if (vn_ring_ge_seqno(ring, head, seqno))
          return head;
-      vn_relax(&iter);
+      vn_relax(&iter, "ring seqno");
    } while (true);
 }
 
@@ -115,7 +115,7 @@ vn_ring_wait_space(const struct vn_ring *ring, uint32_t size)
       const uint32_t head = vn_ring_load_head(ring);
       if (ring->cur + size - head <= VN_RING_BUFFER_SIZE)
          return head;
-      vn_relax(&iter);
+      vn_relax(&iter, "ring space");
    } while (true);
 }