s3: Modify the warning time_audit warning message
authorVolker Lendecke <vl@samba.org>
Wed, 28 Jul 2010 09:21:50 +0000 (11:21 +0200)
committerVolker Lendecke <vl@samba.org>
Wed, 28 Jul 2010 09:24:01 +0000 (11:24 +0200)
Now we have

System call "disk_free" took unexpectedly long (0.01 seconds) -- check your file system and disks!

source3/modules/vfs_time_audit.c

index fb22c19d3428a9d332255a7b2ea954cef0ab893d..3a471d6d4de6b288344f94d06c3c16a1d83459ce 100644 (file)
 
 static double audit_timeout;
 
+static void smb_time_audit_log(const char *syscall, double elapsed)
+{
+       DEBUG(0, ("System call \"%s\" took unexpectedly long (%.2f seconds) "
+                 "-- check your file system and disks!\n", syscall,
+                 elapsed));
+}
+
 static int smb_time_audit_connect(vfs_handle_struct *handle,
                                  const char *svc, const char *user)
 {
@@ -47,7 +54,7 @@ static int smb_time_audit_connect(vfs_handle_struct *handle,
        result = SMB_VFS_NEXT_CONNECT(handle, svc, user);
        timediff = timeval_elapsed(&tv);
        if (timediff > audit_timeout) {
-               DEBUG(0, ("connect: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("connect", timediff);
        }
        return result;
 }
@@ -62,7 +69,7 @@ static void smb_time_audit_disconnect(vfs_handle_struct *handle)
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("disconnect: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("disconnect", timediff);
        }
 
        return;
@@ -84,7 +91,7 @@ static uint64_t smb_time_audit_disk_free(vfs_handle_struct *handle,
 
        /* Don't have a reasonable notion of failure here */
        if (timediff > audit_timeout) {
-               DEBUG(0, ("disk_free: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("disk_free", timediff);
        }
 
        return result;
@@ -103,7 +110,7 @@ static int smb_time_audit_get_quota(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("get_quota: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("get_quota", timediff);
        }
        return result;
 }
@@ -121,7 +128,7 @@ static int smb_time_audit_set_quota(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("set_quota: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("set_quota", timediff);
        }
 
        return result;
@@ -142,8 +149,7 @@ static int smb_time_audit_get_shadow_copy_data(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("get_shadow_copy_data: Took %.2f seconds\n",
-                         timediff));
+               smb_time_audit_log("get_shadow_copy_data", timediff);
        }
 
        return result;
@@ -162,7 +168,7 @@ static int smb_time_audit_statvfs(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("statvfs: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("statvfs", timediff);
        }
 
        return result;
@@ -179,8 +185,7 @@ static int smb_time_audit_fs_capabilities(struct vfs_handle_struct *handle)
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("fs_capabilities: Took %.2f seconds\n",
-                         timediff));
+               smb_time_audit_log("fs_capabilities", timediff);
        }
 
        return result;
@@ -199,7 +204,7 @@ static SMB_STRUCT_DIR *smb_time_audit_opendir(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("opendir: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("opendir", timediff);
        }
 
        return result;
@@ -218,7 +223,7 @@ static SMB_STRUCT_DIRENT *smb_time_audit_readdir(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("readdir: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("readdir", timediff);
        }
 
        return result;
@@ -235,7 +240,7 @@ static void smb_time_audit_seekdir(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("seekdir: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("seekdir", timediff);
        }
 
        return;
@@ -253,7 +258,7 @@ static long smb_time_audit_telldir(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("telldir: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("telldir", timediff);
        }
 
        return result;
@@ -270,7 +275,7 @@ static void smb_time_audit_rewinddir(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("rewinddir: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("rewinddir", timediff);
        }
 
        return;
@@ -288,7 +293,7 @@ static int smb_time_audit_mkdir(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("mkdir: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("mkdir", timediff);
        }
 
        return result;
@@ -306,7 +311,7 @@ static int smb_time_audit_rmdir(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("rmdir: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("rmdir", timediff);
        }
 
        return result;
@@ -324,7 +329,7 @@ static int smb_time_audit_closedir(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("closedir: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("closedir", timediff);
        }
 
        return result;
@@ -341,7 +346,7 @@ static void smb_time_audit_init_search_op(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("init_search_op: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("init_search_op", timediff);
        }
        return;
 }
@@ -359,7 +364,7 @@ static int smb_time_audit_open(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("open: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("open", timediff);
        }
 
        return result;
@@ -409,7 +414,7 @@ static NTSTATUS smb_time_audit_create_file(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("create_file: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("create_file", timediff);
        }
 
        return result;
@@ -426,7 +431,7 @@ static int smb_time_audit_close(vfs_handle_struct *handle, files_struct *fsp)
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("close: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("close", timediff);
        }
 
        return result;
@@ -444,7 +449,7 @@ static ssize_t smb_time_audit_read(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("read: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("read", timediff);
        }
 
        return result;
@@ -463,7 +468,7 @@ static ssize_t smb_time_audit_pread(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("pread: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("pread", timediff);
        }
 
        return result;
@@ -482,7 +487,7 @@ static ssize_t smb_time_audit_write(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("write: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("write", timediff);
        }
 
        return result;
@@ -502,7 +507,7 @@ static ssize_t smb_time_audit_pwrite(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("pwrite: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("pwrite", timediff);
        }
 
        return result;
@@ -521,7 +526,7 @@ static SMB_OFF_T smb_time_audit_lseek(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("lseek: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("lseek", timediff);
        }
 
        return result;
@@ -541,7 +546,7 @@ static ssize_t smb_time_audit_sendfile(vfs_handle_struct *handle, int tofd,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("sendfile: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("sendfile", timediff);
        }
 
        return result;
@@ -561,7 +566,7 @@ static ssize_t smb_time_audit_recvfile(vfs_handle_struct *handle, int fromfd,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("recvfile: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("recvfile", timediff);
        }
 
        return result;
@@ -579,7 +584,7 @@ static int smb_time_audit_rename(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("rename: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("rename", timediff);
        }
 
        return result;
@@ -596,7 +601,7 @@ static int smb_time_audit_fsync(vfs_handle_struct *handle, files_struct *fsp)
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("fsync: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("fsync", timediff);
        }
 
        return result;
@@ -614,7 +619,7 @@ static int smb_time_audit_stat(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("stat: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("stat", timediff);
        }
 
        return result;
@@ -632,7 +637,7 @@ static int smb_time_audit_fstat(vfs_handle_struct *handle, files_struct *fsp,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("fstat: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("fstat", timediff);
        }
 
        return result;
@@ -650,7 +655,7 @@ static int smb_time_audit_lstat(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("lstat: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("lstat", timediff);
        }
 
        return result;
@@ -669,7 +674,7 @@ static int smb_time_audit_get_alloc_size(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("get_alloc_size: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("get_alloc_size", timediff);
        }
 
        return result;
@@ -687,7 +692,7 @@ static int smb_time_audit_unlink(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("unlink: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("unlink", timediff);
        }
 
        return result;
@@ -705,7 +710,7 @@ static int smb_time_audit_chmod(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("chmod: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("chmod", timediff);
        }
 
        return result;
@@ -723,7 +728,7 @@ static int smb_time_audit_fchmod(vfs_handle_struct *handle, files_struct *fsp,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("fchmod: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("fchmod", timediff);
        }
 
        return result;
@@ -741,7 +746,7 @@ static int smb_time_audit_chown(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("chown: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("chown", timediff);
        }
 
        return result;
@@ -759,7 +764,7 @@ static int smb_time_audit_fchown(vfs_handle_struct *handle, files_struct *fsp,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("fchown: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("fchown", timediff);
        }
 
        return result;
@@ -777,7 +782,7 @@ static int smb_time_audit_lchown(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("lchown: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("lchown", timediff);
        }
 
        return result;
@@ -794,7 +799,7 @@ static int smb_time_audit_chdir(vfs_handle_struct *handle, const char *path)
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("chdir: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("chdir", timediff);
        }
 
        return result;
@@ -811,7 +816,7 @@ static char *smb_time_audit_getwd(vfs_handle_struct *handle, char *path)
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("getwd: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("getwd", timediff);
        }
 
        return result;
@@ -829,7 +834,7 @@ static int smb_time_audit_ntimes(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("ntimes: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("ntimes", timediff);
        }
 
        return result;
@@ -848,7 +853,7 @@ static int smb_time_audit_ftruncate(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("ftruncate: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("ftruncate", timediff);
        }
 
        return result;
@@ -867,7 +872,7 @@ static bool smb_time_audit_lock(vfs_handle_struct *handle, files_struct *fsp,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("lock: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("lock", timediff);
        }
 
        return result;
@@ -887,7 +892,7 @@ static int smb_time_audit_kernel_flock(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("kernel_flock: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("kernel_flock", timediff);
        }
 
        return result;
@@ -906,7 +911,7 @@ static int smb_time_audit_linux_setlease(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("linux_setlease: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("linux_setlease", timediff);
        }
 
        return result;
@@ -927,7 +932,7 @@ static bool smb_time_audit_getlock(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("getlock: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("getlock", timediff);
        }
 
        return result;
@@ -945,7 +950,7 @@ static int smb_time_audit_symlink(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("symlink: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("symlink", timediff);
        }
 
        return result;
@@ -963,7 +968,7 @@ static int smb_time_audit_readlink(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("readlink: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("readlink", timediff);
        }
 
        return result;
@@ -981,7 +986,7 @@ static int smb_time_audit_link(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("link: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("link", timediff);
        }
 
        return result;
@@ -1000,7 +1005,7 @@ static int smb_time_audit_mknod(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("mknod: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("mknod", timediff);
        }
 
        return result;
@@ -1018,7 +1023,7 @@ static char *smb_time_audit_realpath(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("realpath: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("realpath", timediff);
        }
 
        return result;
@@ -1042,7 +1047,7 @@ static NTSTATUS smb_time_audit_notify_watch(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("notify_watch: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("notify_watch", timediff);
        }
 
        return result;
@@ -1060,7 +1065,7 @@ static int smb_time_audit_chflags(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("chflags: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("chflags", timediff);
        }
 
        return result;
@@ -1081,7 +1086,7 @@ static struct file_id smb_time_audit_file_id_create(struct vfs_handle_struct *ha
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("file_id_create: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("file_id_create", timediff);
        }
 
        return result;
@@ -1104,7 +1109,7 @@ static NTSTATUS smb_time_audit_streaminfo(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("streaminfo: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("streaminfo", timediff);
        }
 
        return result;
@@ -1126,8 +1131,7 @@ static int smb_time_audit_get_real_filename(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("get_real_filename: Took %.2f seconds\n",
-                       timediff));
+               smb_time_audit_log("get_real_filename", timediff);
        }
 
        return result;
@@ -1145,7 +1149,7 @@ static const char *smb_time_audit_connectpath(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("connectpath: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("connectpath", timediff);
        }
 
        return result;
@@ -1167,8 +1171,7 @@ static NTSTATUS smb_time_audit_brl_lock_windows(struct vfs_handle_struct *handle
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("brl_lock_windows: Took %.2f seconds\n",
-                         timediff));
+               smb_time_audit_log("brl_lock_windows", timediff);
        }
 
        return result;
@@ -1189,7 +1192,7 @@ static bool smb_time_audit_brl_unlock_windows(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("brl_unlock_windows: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("brl_unlock_windows", timediff);
        }
 
        return result;
@@ -1209,8 +1212,7 @@ static bool smb_time_audit_brl_cancel_windows(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("brl_cancel_windows: Took %.2f seconds\n",
-                         timediff));
+               smb_time_audit_log("brl_cancel_windows", timediff);
        }
 
        return result;
@@ -1229,7 +1231,7 @@ static bool smb_time_audit_strict_lock(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("strict_lock: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("strict_lock", timediff);
        }
 
        return result;
@@ -1247,7 +1249,7 @@ static void smb_time_audit_strict_unlock(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("strict_unlock: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("strict_unlock", timediff);
        }
 
        return;
@@ -1267,7 +1269,7 @@ static NTSTATUS smb_time_audit_fget_nt_acl(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("fget_nt_acl: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("fget_nt_acl", timediff);
        }
 
        return result;
@@ -1287,7 +1289,7 @@ static NTSTATUS smb_time_audit_get_nt_acl(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("get_nt_acl: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("get_nt_acl", timediff);
        }
 
        return result;
@@ -1308,7 +1310,7 @@ static NTSTATUS smb_time_audit_fset_nt_acl(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("fset_nt_acl: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("fset_nt_acl", timediff);
        }
 
        return result;
@@ -1326,7 +1328,7 @@ static int smb_time_audit_chmod_acl(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("chmod_acl: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("chmod_acl", timediff);
        }
 
        return result;
@@ -1344,7 +1346,7 @@ static int smb_time_audit_fchmod_acl(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("fchmod_acl: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("fchmod_acl", timediff);
        }
 
        return result;
@@ -1364,8 +1366,7 @@ static int smb_time_audit_sys_acl_get_entry(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("sys_acl_get_entry: Took %.2f seconds\n",
-                         timediff));
+               smb_time_audit_log("sys_acl_get_entry", timediff);
        }
 
        return result;
@@ -1385,8 +1386,7 @@ static int smb_time_audit_sys_acl_get_tag_type(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("sys_acl_get_tag_type: Took %.2f seconds\n",
-                         timediff));
+               smb_time_audit_log("sys_acl_get_tag_type", timediff);
        }
 
        return result;
@@ -1406,8 +1406,7 @@ static int smb_time_audit_sys_acl_get_permset(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("sys_acl_get_permset: Took %.2f seconds\n",
-                         timediff));
+               smb_time_audit_log("sys_acl_get_permset", timediff);
        }
 
        return result;
@@ -1425,8 +1424,7 @@ static void * smb_time_audit_sys_acl_get_qualifier(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("sys_acl_get_qualifier: Took %.2f seconds\n",
-                         timediff));
+               smb_time_audit_log("sys_acl_get_qualifier", timediff);
        }
 
        return result;
@@ -1445,8 +1443,7 @@ static SMB_ACL_T smb_time_audit_sys_acl_get_file(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("sys_acl_get_file: Took %.2f seconds\n",
-                         timediff));
+               smb_time_audit_log("sys_acl_get_file", timediff);
        }
 
        return result;
@@ -1464,8 +1461,7 @@ static SMB_ACL_T smb_time_audit_sys_acl_get_fd(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("sys_acl_get_fd: Took %.2f seconds\n",
-                         timediff));
+               smb_time_audit_log("sys_acl_get_fd", timediff);
        }
 
        return result;
@@ -1483,8 +1479,7 @@ static int smb_time_audit_sys_acl_clear_perms(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("sys_acl_clear_perms: Took %.2f seconds\n",
-                         timediff));
+               smb_time_audit_log("sys_acl_clear_perms", timediff);
        }
 
        return result;
@@ -1503,8 +1498,7 @@ static int smb_time_audit_sys_acl_add_perm(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("sys_acl_add_perm: Took %.2f seconds\n",
-                         timediff));
+               smb_time_audit_log("sys_acl_add_perm", timediff);
        }
 
        return result;
@@ -1523,8 +1517,7 @@ static char * smb_time_audit_sys_acl_to_text(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("sys_acl_to_text: Took %.2f seconds\n",
-                         timediff));
+               smb_time_audit_log("sys_acl_to_text", timediff);
        }
 
        return result;
@@ -1542,7 +1535,7 @@ static SMB_ACL_T smb_time_audit_sys_acl_init(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("sys_acl_init: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("sys_acl_init", timediff);
        }
 
        return result;
@@ -1561,8 +1554,7 @@ static int smb_time_audit_sys_acl_create_entry(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("sys_acl_create_entry: Took %.2f seconds\n",
-                         timediff));
+               smb_time_audit_log("sys_acl_create_entry", timediff);
        }
 
        return result;
@@ -1582,8 +1574,7 @@ static int smb_time_audit_sys_acl_set_tag_type(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("sys_acl_set_tag_type: Took %.2f seconds\n",
-                         timediff));
+               smb_time_audit_log("sys_acl_set_tag_type", timediff);
        }
 
        return result;
@@ -1602,8 +1593,7 @@ static int smb_time_audit_sys_acl_set_qualifier(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("sys_acl_set_qualifier: Took %.2f seconds\n",
-                         timediff));
+               smb_time_audit_log("sys_acl_set_qualifier", timediff);
        }
 
        return result;
@@ -1622,8 +1612,7 @@ static int smb_time_audit_sys_acl_set_permset(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("sys_acl_set_permset: Took %.2f seconds\n",
-                         timediff));
+               smb_time_audit_log("sys_acl_set_permset", timediff);
        }
 
        return result;
@@ -1641,8 +1630,7 @@ static int smb_time_audit_sys_acl_valid(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("sys_acl_valid: Took %.2f seconds\n",
-                         timediff));
+               smb_time_audit_log("sys_acl_valid", timediff);
        }
 
        return result;
@@ -1663,8 +1651,7 @@ static int smb_time_audit_sys_acl_set_file(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("sys_acl_set_file: Took %.2f seconds\n",
-                         timediff));
+               smb_time_audit_log("sys_acl_set_file", timediff);
        }
 
        return result;
@@ -1683,8 +1670,7 @@ static int smb_time_audit_sys_acl_set_fd(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("sys_acl_set_fd: Took %.2f seconds\n",
-                         timediff));
+               smb_time_audit_log("sys_acl_set_fd", timediff);
        }
 
        return result;
@@ -1702,8 +1688,7 @@ static int smb_time_audit_sys_acl_delete_def_file(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("sys_acl_delete_def_file: Took %.2f seconds\n",
-                         timediff));
+               smb_time_audit_log("sys_acl_delete_def_file", timediff);
        }
 
        return result;
@@ -1722,8 +1707,7 @@ static int smb_time_audit_sys_acl_get_perm(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("sys_acl_get_perm: Took %.2f seconds\n",
-                         timediff));
+               smb_time_audit_log("sys_acl_get_perm", timediff);
        }
 
        return result;
@@ -1741,8 +1725,7 @@ static int smb_time_audit_sys_acl_free_text(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("sys_acl_free_text: Took %.2f seconds\n",
-                         timediff));
+               smb_time_audit_log("sys_acl_free_text", timediff);
        }
 
        return result;
@@ -1760,8 +1743,7 @@ static int smb_time_audit_sys_acl_free_acl(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("sys_acl_free_acl: Took %.2f seconds\n",
-                         timediff));
+               smb_time_audit_log("sys_acl_free_acl", timediff);
        }
 
        return result;
@@ -1781,8 +1763,7 @@ static int smb_time_audit_sys_acl_free_qualifier(vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("sys_acl_free_qualifier: Took %.2f seconds\n",
-                         timediff));
+               smb_time_audit_log("sys_acl_free_qualifier", timediff);
        }
 
        return result;
@@ -1801,7 +1782,7 @@ static ssize_t smb_time_audit_getxattr(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("getxattr: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("getxattr", timediff);
        }
 
        return result;
@@ -1820,7 +1801,7 @@ static ssize_t smb_time_audit_lgetxattr(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("lgetxattr: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("lgetxattr", timediff);
        }
 
        return result;
@@ -1840,7 +1821,7 @@ static ssize_t smb_time_audit_fgetxattr(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("fgetxattr: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("fgetxattr", timediff);
        }
 
        return result;
@@ -1859,7 +1840,7 @@ static ssize_t smb_time_audit_listxattr(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("listxattr: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("listxattr", timediff);
        }
 
        return result;
@@ -1878,7 +1859,7 @@ static ssize_t smb_time_audit_llistxattr(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("llistxattr: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("llistxattr", timediff);
        }
 
        return result;
@@ -1897,7 +1878,7 @@ static ssize_t smb_time_audit_flistxattr(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("flistxattr: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("flistxattr", timediff);
        }
 
        return result;
@@ -1915,7 +1896,7 @@ static int smb_time_audit_removexattr(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("removexattr: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("removexattr", timediff);
        }
 
        return result;
@@ -1933,7 +1914,7 @@ static int smb_time_audit_lremovexattr(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("lremovexattr: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("lremovexattr", timediff);
        }
 
        return result;
@@ -1952,7 +1933,7 @@ static int smb_time_audit_fremovexattr(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("fremovexattr: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("fremovexattr", timediff);
        }
 
        return result;
@@ -1973,7 +1954,7 @@ static int smb_time_audit_setxattr(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("setxattr: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("setxattr", timediff);
        }
 
        return result;
@@ -1994,7 +1975,7 @@ static int smb_time_audit_lsetxattr(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("lsetxattr: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("lsetxattr", timediff);
        }
 
        return result;
@@ -2013,7 +1994,7 @@ static int smb_time_audit_fsetxattr(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("fsetxattr: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("fsetxattr", timediff);
        }
 
        return result;
@@ -2032,7 +2013,7 @@ static int smb_time_audit_aio_read(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("aio_read: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("aio_read", timediff);
        }
 
        return result;
@@ -2051,7 +2032,7 @@ static int smb_time_audit_aio_write(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("aio_write: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("aio_write", timediff);
        }
 
        return result;
@@ -2070,7 +2051,7 @@ static ssize_t smb_time_audit_aio_return(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("aio_return: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("aio_return", timediff);
        }
 
        return result;
@@ -2089,7 +2070,7 @@ static int smb_time_audit_aio_cancel(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("aio_cancel: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("aio_cancel", timediff);
        }
 
        return result;
@@ -2108,7 +2089,7 @@ static int smb_time_audit_aio_error(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("aio_error: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("aio_error", timediff);
        }
 
        return result;
@@ -2127,7 +2108,7 @@ static int smb_time_audit_aio_fsync(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("aio_fsync: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("aio_fsync", timediff);
        }
 
        return result;
@@ -2147,7 +2128,7 @@ static int smb_time_audit_aio_suspend(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("aio_suspend: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("aio_suspend", timediff);
        }
 
        return result;
@@ -2165,7 +2146,7 @@ static bool smb_time_audit_aio_force(struct vfs_handle_struct *handle,
        timediff = timeval_elapsed(&tv);
 
        if (timediff > audit_timeout) {
-               DEBUG(0, ("aio_force: Took %.2f seconds\n", timediff));
+               smb_time_audit_log("aio_force", timediff);
        }
 
        return result;