From e4c231700bd3f7f14dad8fe87cfc7b1179e4f3c0 Mon Sep 17 00:00:00 2001
From: wangjufeng <wangjufeng@huawei.com>
Date: Sat, 16 Nov 2019 17:47:19 +0800
Subject: [PATCH] log it when disk slow

This patch help to log it when read or write disk take too much time.

Signed-off-by: wangjufeng<wangjufeng@huawei.com>
---
 lib/device/dev-cache.c | 40 +++++++++++++++++++++++++++++++++++-----
 1 file changed, 35 insertions(+), 5 deletions(-)

diff --git a/lib/device/dev-cache.c b/lib/device/dev-cache.c
index 6af559c..7c144d6 100644
--- a/lib/device/dev-cache.c
+++ b/lib/device/dev-cache.c
@@ -58,6 +58,7 @@ static struct {
 #define _free(x) dm_pool_free(_cache.mem, (x))
 #define _strdup(x) dm_pool_strdup(_cache.mem, (x))
 
+static long udev_getdev_timemax = 500000; // macroseconds
 static int _insert(const char *path, const struct stat *info,
 		   int rec, int check_with_udev_db);
 
@@ -1025,12 +1026,23 @@ static int _device_in_udev_db(const dev_t d)
 static int _insert_udev_dir(struct udev *udev, const char *dir)
 {
 	struct udev_enumerate *udev_enum = NULL;
-	struct udev_list_entry *device_entry, *symlink_entry;
+	struct udev_list_entry *device_entry, *symlink_entry, *first_entry;
 	const char *entry_name, *node_name, *symlink_name;
 	struct udev_device *device;
 	int r = 1;
-
-	if (!(udev_enum = udev_enumerate_new(udev))) {
+	int ret = -1;
+	struct timeval start, end;
+	long time_use = 0;
+
+	ret = gettimeofday(&start,NULL);
+	udev_enum = udev_enumerate_new(udev);
+	if (!ret && !gettimeofday(&end,NULL)) {
+		time_use = (end.tv_sec - start.tv_sec) * 1000000 + (end.tv_usec - start.tv_usec);
+		if (time_use > udev_getdev_timemax) {
+			log_print_unless_silent("Call udev_enumerate_new use %ld usec", time_use);
+		}
+	}
+	if (!udev_enum) {
 		log_error("Failed to udev_enumerate_new.");
 		return 0;
 	}
@@ -1062,14 +1074,32 @@ static int _insert_udev_dir(struct udev *udev, const char *dir)
 					 entry_name);
 			continue;
 		}
+		ret = gettimeofday(&start,NULL);
+		node_name = udev_device_get_devnode(device);
+		if (!ret && !gettimeofday(&end,NULL)) {
+			time_use = (end.tv_sec - start.tv_sec) * 1000000 + (end.tv_usec - start.tv_usec);
+			if (time_use > udev_getdev_timemax) {
+				log_print_unless_silent("Call udev_device_get_devnode use %ld usec, device:%s",
+							time_use, entry_name);
+			}
+		}
 
-		if (!(node_name = udev_device_get_devnode(device)))
+		if (!node_name)
 			log_very_verbose("udev failed to return a device node for entry %s.",
 					 entry_name);
 		else
 			r &= _insert(node_name, NULL, 0, 0);
 
-		udev_list_entry_foreach(symlink_entry, udev_device_get_devlinks_list_entry(device)) {
+		ret = gettimeofday(&start,NULL);
+		first_entry = udev_device_get_devlinks_list_entry(device);
+		if (!ret && !gettimeofday(&end,NULL)) {
+			time_use = (end.tv_sec - start.tv_sec) * 1000000 + (end.tv_usec - start.tv_usec);
+			if (time_use > udev_getdev_timemax) {
+				log_print_unless_silent("Call udev_device_get_devlinks_list_entry use %ld usec, dev:%s",
+							time_use, entry_name);
+			}
+		}
+		udev_list_entry_foreach(symlink_entry, first_entry) {
 			if (!(symlink_name = udev_list_entry_get_name(symlink_entry)))
 				log_very_verbose("udev failed to return a symlink name for entry %s.",
 						 entry_name);
-- 
1.8.3.1