From 6d85d05f7847defcd972b1702ab9b14f22e60d4e Mon Sep 17 00:00:00 2001
From: Eric Harney <eharney@redhat.com>
Date: Fri, 11 Dec 2020 09:51:00 -0500
Subject: [PATCH] Add warning message about slow volume backend

If a volume driver takes an excessively long amount
of time to return volume stats info, the only indication
if this is a generic "Function outlasted interval" message
that doesn't really explain what is going on.

Introduce a specific log message when this happens so
that this situation is more clear for someone looking
at cinder-volume logs.

The message is set to trigger if the driver takes more
than half of the stats polling interval to complete.

Change-Id: Id6b27eb7b90c8a8c91fb46de69aa94b8210da18d
---
 cinder/volume/manager.py                          | 15 ++++++++++++++-
 .../slow-get-volume-stats-91b84c6e661dc605.yaml   |  7 +++++++
 2 files changed, 21 insertions(+), 1 deletion(-)
 create mode 100644 releasenotes/notes/slow-get-volume-stats-91b84c6e661dc605.yaml

diff --git a/cinder/volume/manager.py b/cinder/volume/manager.py
index a5248a50336..aae000dd2ab 100644
--- a/cinder/volume/manager.py
+++ b/cinder/volume/manager.py
@@ -2646,7 +2646,20 @@ class VolumeManager(manager.CleanableManager,
                         resource={'type': 'driver',
                                   'id': self.driver.__class__.__name__})
         else:
-            volume_stats = self.driver.get_volume_stats(refresh=True)
+            slowmsg = "The " + self.driver.__class__.__name__ + " volume " \
+                      "driver's get_volume_stats operation ran for " \
+                      "%(seconds).1f seconds.  This may indicate a " \
+                      "performance problem with the backend which can lead " \
+                      "to instability."
+
+            @timeutils.time_it(
+                LOG, log_level=logging.WARN, message=slowmsg,
+                min_duration=CONF.backend_stats_polling_interval / 2)
+            def get_stats():
+                return self.driver.get_volume_stats(refresh=True)
+
+            volume_stats = get_stats()
+
             if self.extra_capabilities:
                 volume_stats.update(self.extra_capabilities)
             if volume_stats:
diff --git a/releasenotes/notes/slow-get-volume-stats-91b84c6e661dc605.yaml b/releasenotes/notes/slow-get-volume-stats-91b84c6e661dc605.yaml
new file mode 100644
index 00000000000..4d0c82b4d67
--- /dev/null
+++ b/releasenotes/notes/slow-get-volume-stats-91b84c6e661dc605.yaml
@@ -0,0 +1,7 @@
+---
+features:
+  - |
+    Log a warning from the volume service when a volume driver's
+    get_volume_stats() call takes a long time to return.  This can help
+    deployers troubleshoot a cinder-volume service misbehaving due to a
+    driver/backend performance issue.