LU-16615 utils: add messages in l_getidentity

Add time related messages in l_getidentity to help debug upon
timeout, which may cause -EACCES error in user applications.

Test-Parameters: trivial
Signed-off-by: Lai Siyao <lai.siyao@whamcloud.com>
Change-Id: I87ebfb85d05e19886d8becc6b14ed0233eaed42d
Reviewed-on: https://review.whamcloud.com/c/fs/lustre-release/+/50213
Tested-by: jenkins <devops@whamcloud.com>
Tested-by: Maloo <maloo@whamcloud.com>
Reviewed-by: Andreas Dilger <adilger@whamcloud.com>
Reviewed-by: Olaf Faaland <faaland1@llnl.gov>
Reviewed-by: Oleg Drokin <green@whamcloud.com>

diff --git a/lustre/utils/l_getidentity.c b/lustre/utils/l_getidentity.c
index 52fd150..ec57922 100644 (file)
--- a/lustre/utils/l_getidentity.c
+++ b/lustre/utils/l_getidentity.c
@@ -43,6 +43,7 @@
 #include <stddef.h>
 #include <libgen.h>
 #include <syslog.h>
+#include <sys/time.h>
 
 #include <libcfs/util/param.h>
 #include <linux/lnet/nidstr.h>
@@ -401,12 +402,17 @@ static void show_result(struct identity_downcall_data *data)
        printf("\n");
 }
 
+#define difftime(a, b)                                 \
+       ((a).tv_sec - (b).tv_sec +                      \
+        ((a).tv_usec - (b).tv_usec) / 1000000.0)
+
 int main(int argc, char **argv)
 {
        char *end;
        struct identity_downcall_data *data = NULL;
        glob_t path;
        unsigned long uid;
+       struct timeval start, idgot, fini;
        int fd, rc = -EINVAL, size, maxgroups;
        bool alreadyfailed = false;
 
@@ -421,6 +427,7 @@ int main(int argc, char **argv)
                errlog("%s: invalid uid '%s'\n", progname, argv[2]);
                goto out;
        }
+       gettimeofday(&start, NULL);
 
        maxgroups = sysconf(_SC_NGROUPS_MAX);
        if (maxgroups > NGROUPS_MAX)
@@ -456,6 +463,7 @@ retry:
        /* read permission database */
        rc = get_perms(data);
 
+       gettimeofday(&idgot, NULL);
 downcall:
        if (strcmp(argv[1], "-d") == 0 || getenv("L_GETIDENTITY_TEST")) {
                show_result(data);
@@ -478,6 +486,7 @@ downcall:
        }
 
        rc = write(fd, data, size);
+       gettimeofday(&fini, NULL);
        close(fd);
        if (rc != size) {
                errlog("partial write ret %d: %s\n", rc, strerror(errno));
@@ -492,6 +501,11 @@ downcall:
        } else {
                rc = 0;
        }
+       /* log if it takes more than 20 second to avoid rate limite */
+       if (rc || difftime(fini, start) > 20)
+               errlog("get identity for uid %lu start time %ld.%06ld got time %ld.%06ld end time %ld.%06ld: rc = %d\n",
+                      uid, start.tv_sec, start.tv_usec, idgot.tv_sec,
+                      idgot.tv_usec, fini.tv_sec, fini.tv_usec, rc);
 
 out_params:
        cfs_free_param_data(&path);