From d644d7f2164022eec1a156761187488861dde056 Mon Sep 17 00:00:00 2001 From: wangjufeng 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 --- lib/device/dev-cache.c | 40 +++++++++++++++++++++++++++++++++++----- lib/device/dev-io.c | 17 +++++++++++++++++ 2 files changed, 52 insertions(+), 5 deletions(-) diff --git a/lib/device/dev-cache.c b/lib/device/dev-cache.c index 8af1de9..da8b9d0 100644 --- a/lib/device/dev-cache.c +++ b/lib/device/dev-cache.c @@ -57,6 +57,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); @@ -1062,12 +1063,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; } @@ -1099,14 +1111,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); diff --git a/lib/device/dev-io.c b/lib/device/dev-io.c index 8bf1847..af273a2 100644 --- a/lib/device/dev-io.c +++ b/lib/device/dev-io.c @@ -52,6 +52,8 @@ # endif #endif +static long dev_io_maxtime = 50000; // macroseconds + static unsigned _dev_size_seqno = 1; static const char *_reasons[] = { @@ -81,6 +83,9 @@ static int _io(struct device_area *where, char *buffer, int should_write, dev_io int fd = dev_fd(where->dev); ssize_t n = 0; size_t total = 0; + int ret = -1; + struct timeval start, end; + long time_use = 0; if (fd < 0) { log_error("Attempt to read an unopened device (%s).", @@ -111,6 +116,7 @@ static int _io(struct device_area *where, char *buffer, int should_write, dev_io return 0; } + ret = gettimeofday(&start,NULL); while (total < (size_t) where->size) { do n = should_write ? @@ -132,6 +138,17 @@ static int _io(struct device_area *where, char *buffer, int should_write, dev_io total += n; buffer += n; } + if (!ret && !gettimeofday(&end,NULL)) { + time_use = (end.tv_sec - start.tv_sec) * 1000000 + (end.tv_usec - start.tv_usec); + if (time_use > dev_io_maxtime) { + log_print_unless_silent("%s %s:%8" PRIu64 " bytes (sync) at %" PRIu64 "%s (for %s)," + " spend %ld usec", + should_write ? "Write" : "Read ", dev_name(where->dev), + where->size, (uint64_t) where->start, + (should_write && test_mode()) ? " (test mode - suppressed)" : "", + _reason_text(reason), time_use); + } + } return (total == (size_t) where->size); } -- 2.19.1