[PATCH 65/67] cachefiles: Add tracepoints to log errors from ops on the backing fs

David Howells
2021-10-18T15:09:24Z

Add a couple of tracepoints to log errors that cachefiles gets from making
calls to manipulate the backing filesystem. These calls are divided into
two categories - VFS manipulation (eg. mkdir) and data I/O - with a
separate tracepoint for each.

Signed-off-by: David Howells <dhowells@redhat.com>
---

fs/cachefiles/daemon.c | 2 +
fs/cachefiles/interface.c | 11 ++++
fs/cachefiles/internal.h | 1
fs/cachefiles/io.c | 22 ++++++++-
fs/cachefiles/namei.c | 59 ++++++++++++++++++++---
fs/cachefiles/xattr.c | 8 +++
include/trace/events/cachefiles.h | 94 +++++++++++++++++++++++++++++++++++++
7 files changed, 187 insertions(+), 10 deletions(-)

diff --git a/fs/cachefiles/daemon.c b/fs/cachefiles/daemon.c
index 6d31fba31ce9..2b926af39f43 100644
--- a/fs/cachefiles/daemon.c
+++ b/fs/cachefiles/daemon.c
@@ -692,6 +692,8 @@ int cachefiles_has_space(struct cachefiles_cache *cache,

ret = vfs_statfs(&path, &stats);
if (ret < 0) {
+ trace_cachefiles_vfs_error(NULL, d_inode(cache->store), ret,
+ cachefiles_trace_statfs_error);
if (ret == -EIO)
cachefiles_io_error(cache, "statfs failed");
_leave(" = %d", ret);
diff --git a/fs/cachefiles/interface.c b/fs/cachefiles/interface.c
index 96f30eba585a..115be503b23a 100644
--- a/fs/cachefiles/interface.c
+++ b/fs/cachefiles/interface.c
@@ -153,8 +153,10 @@ static bool cachefiles_shorten_object(struct cachefiles_object *object,
cachefiles_trunc_shrink);
ret = vfs_truncate(&file->f_path, dio_size);
if (ret < 0) {
+ trace_cachefiles_io_error(object, file_inode(file), ret,
+ cachefiles_trace_trunc_error);
cachefiles_io_error_obj(object, "Trunc-to-size failed %d", ret);
- cachefiles_remove_object_xattr(cache, file->f_path.dentry);
+ cachefiles_remove_object_xattr(cache, object, file->f_path.dentry);
return false;
}

@@ -164,8 +166,10 @@ static bool cachefiles_shorten_object(struct cachefiles_object *object,
ret = vfs_fallocate(file, FALLOC_FL_ZERO_RANGE,
new_size, dio_size);
if (ret < 0) {
+ trace_cachefiles_io_error(object, file_inode(file), ret,
+ cachefiles_trace_fallocate_error);
cachefiles_io_error_obj(object, "Trunc-to-dio-size failed %d", ret);
- cachefiles_remove_object_xattr(cache, file->f_path.dentry);
+ cachefiles_remove_object_xattr(cache, object, file->f_path.dentry);
return false;
}
}
@@ -384,6 +388,9 @@ static int cachefiles_attr_changed(struct cachefiles_object *object)
inode_unlock(file_inode(file));
cachefiles_end_secure(cache, saved_cred);

+ if (ret < 0)
+ trace_cachefiles_io_error(NULL, file_inode(file), ret,
+ cachefiles_trace_notify_change_error);
if (ret == -EIO) {
cachefiles_io_error_obj(object, "Size set failed");
ret = -ENOBUFS;
diff --git a/fs/cachefiles/internal.h b/fs/cachefiles/internal.h
index 83cf2ca3a763..3dd3e13989d6 100644
--- a/fs/cachefiles/internal.h
+++ b/fs/cachefiles/internal.h
@@ -238,6 +238,7 @@ extern int cachefiles_set_object_xattr(struct cachefiles_object *object);
extern int cachefiles_check_auxdata(struct cachefiles_object *object,
struct file *file);
extern int cachefiles_remove_object_xattr(struct cachefiles_cache *cache,
+ struct cachefiles_object *object,
struct dentry *dentry);
extern void cachefiles_prepare_to_write(struct fscache_cookie *cookie);

diff --git a/fs/cachefiles/io.c b/fs/cachefiles/io.c
index 5e3579800689..136d0ea0a7c9 100644
--- a/fs/cachefiles/io.c
+++ b/fs/cachefiles/io.c
@@ -44,9 +44,14 @@ static inline void cachefiles_put_kiocb(struct cachefiles_kiocb *ki)
static void cachefiles_read_complete(struct kiocb *iocb, long ret, long ret2)
{
struct cachefiles_kiocb *ki = container_of(iocb, struct cachefiles_kiocb, iocb);
+ struct inode *inode = file_inode(ki->iocb.ki_filp);

_enter("%ld,%ld", ret, ret2);

+ if (ret < 0)
+ trace_cachefiles_io_error(ki->object, inode, ret,
+ cachefiles_trace_read_error);
+
if (ki->term_func) {
if (ret >= 0) {
if (ki->object->cookie->inval_counter == ki->inval_counter)
@@ -195,6 +200,10 @@ static void cachefiles_write_complete(struct kiocb *iocb, long ret, long ret2)
__sb_writers_acquired(inode->i_sb, SB_FREEZE_WRITE);
__sb_end_write(inode->i_sb, SB_FREEZE_WRITE);

+ if (ret < 0)
+ trace_cachefiles_io_error(ki->object, inode, ret,
+ cachefiles_trace_write_error);
+
set_bit(FSCACHE_COOKIE_HAVE_DATA, &ki->object->cookie->flags);
if (ki->term_func)
ki->term_func(ki->term_func_priv, ret, ki->was_async);
@@ -352,6 +361,8 @@ static enum netfs_read_source cachefiles_prepare_read(struct netfs_read_subreque
why = cachefiles_trace_read_seek_nxio;
goto download_and_store;
}
+ trace_cachefiles_io_error(object, file_inode(file), off,
+ cachefiles_trace_seek_error);
why = cachefiles_trace_read_seek_error;
goto out;
}
@@ -370,6 +381,8 @@ static enum netfs_read_source cachefiles_prepare_read(struct netfs_read_subreque

to = vfs_llseek(file, subreq->start, SEEK_HOLE);
if (to < 0 && to >= (loff_t)-MAX_ERRNO) {
+ trace_cachefiles_io_error(object, file_inode(file), to,
+ cachefiles_trace_seek_error);
why = cachefiles_trace_read_seek_error;
goto out;
}
@@ -425,6 +438,8 @@ static int __cachefiles_prepare_write(struct netfs_cache_resources *cres,
if (pos < 0 && pos >= (loff_t)-MAX_ERRNO) {
if (pos == -ENXIO)
goto check_space; /* Unallocated tail */
+ trace_cachefiles_io_error(object, file_inode(file), pos,
+ cachefiles_trace_seek_error);
return pos;
}
if ((u64)pos >= (u64)*_start + *_len)
@@ -438,8 +453,11 @@ static int __cachefiles_prepare_write(struct netfs_cache_resources *cres,
return 0; /* Enough space to simply overwrite the whole block */

pos = vfs_llseek(file, *_start, SEEK_HOLE);
- if (pos < 0 && pos >= (loff_t)-MAX_ERRNO)
+ if (pos < 0 && pos >= (loff_t)-MAX_ERRNO) {
+ trace_cachefiles_io_error(object, file_inode(file), pos,
+ cachefiles_trace_seek_error);
return pos;
+ }
if ((u64)pos >= (u64)*_start + *_len)
return 0; /* Fully allocated */

@@ -447,6 +465,8 @@ static int __cachefiles_prepare_write(struct netfs_cache_resources *cres,
ret = vfs_fallocate(file, FALLOC_FL_PUNCH_HOLE | FALLOC_FL_KEEP_SIZE,
*_start, *_len);
if (ret < 0) {
+ trace_cachefiles_io_error(object, file_inode(file), ret,
+ cachefiles_trace_fallocate_error);
cachefiles_io_error_obj(object,
"CacheFiles: fallocate failed (%d)\n", ret);
ret = -EIO;
diff --git a/fs/cachefiles/namei.c b/fs/cachefiles/namei.c
index 989df918570b..12266c90e5f8 100644
--- a/fs/cachefiles/namei.c
+++ b/fs/cachefiles/namei.c
@@ -122,8 +122,12 @@ int cachefiles_bury_object(struct cachefiles_cache *cache,

inode_unlock(d_inode(dir));

- if (ret == -EIO)
- cachefiles_io_error(cache, "Unlink failed");
+ if (ret < 0) {
+ trace_cachefiles_vfs_error(object, d_inode(dir), ret,
+ cachefiles_trace_unlink_error);
+ if (ret == -EIO)
+ cachefiles_io_error(cache, "Unlink failed");
+ }

_leave(" = %d", ret);
return ret;
@@ -172,6 +176,9 @@ int cachefiles_bury_object(struct cachefiles_cache *cache,
grave = lookup_one_len(nbuffer, cache->graveyard, strlen(nbuffer));
if (IS_ERR(grave)) {
unlock_rename(cache->graveyard, dir);
+ trace_cachefiles_vfs_error(object, d_inode(cache->graveyard),
+ PTR_ERR(grave),
+ cachefiles_trace_lookup_error);

if (PTR_ERR(grave) == -ENOMEM) {
_leave(" = -ENOMEM");
@@ -224,6 +231,10 @@ int cachefiles_bury_object(struct cachefiles_cache *cache,
};
trace_cachefiles_rename(object, rep, grave, why);
ret = vfs_rename(&rd);
+ if (ret != 0)
+ trace_cachefiles_vfs_error(object, d_inode(dir),
+ PTR_ERR(grave),
+ cachefiles_trace_rename_error);
if (ret != 0 && ret != -ENOMEM)
cachefiles_io_error(cache,
"Rename failed with error %d", ret);
@@ -249,6 +260,9 @@ static int cachefiles_unlink(struct cachefiles_object *object,
ret = security_path_unlink(&path, dentry);
if (ret == 0)
ret = vfs_unlink(&init_user_ns, d_backing_inode(fan), dentry, NULL);
+ if (ret != 0)
+ trace_cachefiles_vfs_error(object, d_backing_inode(fan), ret,
+ cachefiles_trace_unlink_error);
return ret;
}

@@ -273,6 +287,9 @@ int cachefiles_delete_object(struct cachefiles_object *object,
inode_unlock(d_backing_inode(fan));
dput(dentry);

+ if (ret < 0)
+ trace_cachefiles_vfs_error(object, d_backing_inode(fan), ret,
+ cachefiles_trace_unlink_error);
if (ret < 0 && ret != -ENOENT)
cachefiles_io_error(volume->cache, "Unlink failed");
return ret;
@@ -326,8 +343,12 @@ static bool cachefiles_open_file(struct cachefiles_object *object,
path.dentry = dentry;
file = open_with_fake_path(&path, O_RDWR | O_LARGEFILE | O_DIRECT,
d_backing_inode(dentry), cache->cache_cred);
- if (IS_ERR(file))
+ if (IS_ERR(file)) {
+ trace_cachefiles_vfs_error(object, d_backing_inode(dentry),
+ PTR_ERR(file),
+ cachefiles_trace_open_error);
goto error;
+ }

if (unlikely(!file->f_op->read_iter) ||
unlikely(!file->f_op->write_iter)) {
@@ -430,6 +451,9 @@ struct dentry *cachefiles_get_directory(struct cachefiles_cache *cache,
retry:
subdir = lookup_one_len(dirname, dir, strlen(dirname));
if (IS_ERR(subdir)) {
+ trace_cachefiles_vfs_error(NULL, d_backing_inode(dir),
+ PTR_ERR(subdir),
+ cachefiles_trace_lookup_error);
if (PTR_ERR(subdir) == -ENOMEM)
goto nomem_d_alloc;
goto lookup_error;
@@ -454,8 +478,11 @@ struct dentry *cachefiles_get_directory(struct cachefiles_cache *cache,
if (ret < 0)
goto mkdir_error;
ret = vfs_mkdir(&init_user_ns, d_inode(dir), subdir, 0700);
- if (ret < 0)
+ if (ret < 0) {
+ trace_cachefiles_vfs_error(NULL, d_inode(dir), ret,
+ cachefiles_trace_mkdir_error);
goto mkdir_error;
+ }

if (unlikely(d_unhashed(subdir))) {
dput(subdir);
@@ -610,7 +637,7 @@ int cachefiles_cull(struct cachefiles_cache *cache, struct dentry *dir,
*/
_debug("victim is cullable");

- ret = cachefiles_remove_object_xattr(cache, victim);
+ ret = cachefiles_remove_object_xattr(cache, NULL, victim);
if (ret < 0)
goto error_unlock;

@@ -693,6 +720,8 @@ struct file *cachefiles_create_tmpfile(struct cachefiles_object *object)
path.mnt = cache->mnt,
path.dentry = vfs_tmpfile(&init_user_ns, fan, S_IFREG, O_RDWR);
if (IS_ERR(path.dentry)) {
+ trace_cachefiles_vfs_error(object, d_inode(fan), PTR_ERR(path.dentry),
+ cachefiles_trace_tmpfile_error);
if (PTR_ERR(path.dentry) == -EIO)
cachefiles_io_error_obj(object, "Failed to create tmpfile");
file = ERR_CAST(path.dentry);
@@ -711,6 +740,9 @@ struct file *cachefiles_create_tmpfile(struct cachefiles_object *object)
cachefiles_trunc_expand_tmpfile);
ret = vfs_truncate(&path, ni_size);
if (ret < 0) {
+ trace_cachefiles_vfs_error(
+ object, d_backing_inode(path.dentry), ret,
+ cachefiles_trace_trunc_error);
file = ERR_PTR(ret);
goto out_dput;
}
@@ -718,8 +750,12 @@ struct file *cachefiles_create_tmpfile(struct cachefiles_object *object)

file = open_with_fake_path(&path, O_RDWR | O_LARGEFILE | O_DIRECT,
d_backing_inode(path.dentry), cache->cache_cred);
- if (IS_ERR(file))
+ if (IS_ERR(file)) {
+ trace_cachefiles_vfs_error(object, d_backing_inode(path.dentry),
+ PTR_ERR(file),
+ cachefiles_trace_open_error);
goto out_dput;
+ }
if (unlikely(!file->f_op->read_iter) ||
unlikely(!file->f_op->write_iter)) {
fput(file);
@@ -750,6 +786,8 @@ bool cachefiles_commit_tmpfile(struct cachefiles_cache *cache,
inode_lock_nested(d_inode(fan), I_MUTEX_PARENT);
dentry = lookup_one_len(object->d_name, fan, object->d_name_len);
if (IS_ERR(dentry)) {
+ trace_cachefiles_vfs_error(object, d_inode(fan), PTR_ERR(dentry),
+ cachefiles_trace_lookup_error);
_debug("lookup fail %ld", PTR_ERR(dentry));
goto out_unlock;
}
@@ -761,12 +799,17 @@ bool cachefiles_commit_tmpfile(struct cachefiles_cache *cache,
}

ret = cachefiles_unlink(object, fan, dentry, FSCACHE_OBJECT_IS_STALE);
- if (ret < 0)
+ if (ret < 0) {
+ trace_cachefiles_vfs_error(object, d_inode(fan), ret,
+ cachefiles_trace_unlink_error);
goto out_dput;
+ }

dput(dentry);
dentry = lookup_one_len(object->d_name, fan, object->d_name_len);
if (IS_ERR(dentry)) {
+ trace_cachefiles_vfs_error(object, d_inode(fan), PTR_ERR(dentry),
+ cachefiles_trace_lookup_error);
_debug("lookup fail %ld", PTR_ERR(dentry));
goto out_unlock;
}
@@ -775,6 +818,8 @@ bool cachefiles_commit_tmpfile(struct cachefiles_cache *cache,
ret = vfs_link(object->file->f_path.dentry, &init_user_ns,
d_inode(fan), dentry, NULL);
if (ret < 0) {
+ trace_cachefiles_vfs_error(object, d_inode(fan), PTR_ERR(dentry),
+ cachefiles_trace_link_error);
_debug("link fail %d", ret);
} else {
trace_cachefiles_link(object, file_inode(object->file));
diff --git a/fs/cachefiles/xattr.c b/fs/cachefiles/xattr.c
index 30adca42883b..e0f77329c3ec 100644
--- a/fs/cachefiles/xattr.c
+++ b/fs/cachefiles/xattr.c
@@ -61,6 +61,8 @@ int cachefiles_set_object_xattr(struct cachefiles_object *object)
ret = vfs_setxattr(&init_user_ns, dentry, cachefiles_xattr_cache,
buf, sizeof(struct cachefiles_xattr) + len, 0);
if (ret < 0) {
+ trace_cachefiles_vfs_error(object, file_inode(file), ret,
+ cachefiles_trace_setxattr_error);
trace_cachefiles_coherency(object, file_inode(file)->i_ino,
buf->content,
cachefiles_coherency_set_fail);
@@ -99,6 +101,9 @@ int cachefiles_check_auxdata(struct cachefiles_object *object, struct file *file

xlen = vfs_getxattr(&init_user_ns, dentry, cachefiles_xattr_cache, buf, tlen);
if (xlen != tlen) {
+ if (xlen < 0)
+ trace_cachefiles_vfs_error(object, file_inode(file), xlen,
+ cachefiles_trace_getxattr_error);
if (xlen == -EIO)
cachefiles_io_error_obj(
object,
@@ -129,12 +134,15 @@ int cachefiles_check_auxdata(struct cachefiles_object *object, struct file *file
* remove the object's xattr to mark it stale
*/
int cachefiles_remove_object_xattr(struct cachefiles_cache *cache,
+ struct cachefiles_object *object,
struct dentry *dentry)
{
int ret;

ret = vfs_removexattr(&init_user_ns, dentry, cachefiles_xattr_cache);
if (ret < 0) {
+ trace_cachefiles_vfs_error(object, d_inode(dentry), ret,
+ cachefiles_trace_remxattr_error);
if (ret == -ENOENT || ret == -ENODATA)
ret = 0;
else if (ret != -ENOMEM)
diff --git a/include/trace/events/cachefiles.h b/include/trace/events/cachefiles.h
index 11447b20fc83..6a41a36ce581 100644
--- a/include/trace/events/cachefiles.h
+++ b/include/trace/events/cachefiles.h
@@ -72,6 +72,26 @@ enum cachefiles_prepare_read_trace {
cachefiles_trace_read_seek_nxio,
};

+enum cachefiles_error_trace {
+ cachefiles_trace_fallocate_error,
+ cachefiles_trace_getxattr_error,
+ cachefiles_trace_link_error,
+ cachefiles_trace_lookup_error,
+ cachefiles_trace_mkdir_error,
+ cachefiles_trace_notify_change_error,
+ cachefiles_trace_open_error,
+ cachefiles_trace_read_error,
+ cachefiles_trace_remxattr_error,
+ cachefiles_trace_rename_error,
+ cachefiles_trace_seek_error,
+ cachefiles_trace_setxattr_error,
+ cachefiles_trace_statfs_error,
+ cachefiles_trace_tmpfile_error,
+ cachefiles_trace_trunc_error,
+ cachefiles_trace_unlink_error,
+ cachefiles_trace_write_error,
+};
+
#endif

/*
@@ -126,6 +146,25 @@ enum cachefiles_prepare_read_trace {
EM(cachefiles_trace_read_seek_error, "seek-error") \
E_(cachefiles_trace_read_seek_nxio, "seek-enxio")

+#define cachefiles_error_traces \
+ EM(cachefiles_trace_fallocate_error, "fallocate") \
+ EM(cachefiles_trace_getxattr_error, "getxattr") \
+ EM(cachefiles_trace_link_error, "link") \
+ EM(cachefiles_trace_lookup_error, "lookup") \
+ EM(cachefiles_trace_mkdir_error, "mkdir") \
+ EM(cachefiles_trace_notify_change_error, "notify_change") \
+ EM(cachefiles_trace_open_error, "open") \
+ EM(cachefiles_trace_read_error, "read") \
+ EM(cachefiles_trace_remxattr_error, "remxattr") \
+ EM(cachefiles_trace_rename_error, "rename") \
+ EM(cachefiles_trace_seek_error, "seek") \
+ EM(cachefiles_trace_setxattr_error, "setxattr") \
+ EM(cachefiles_trace_statfs_error, "statfs") \
+ EM(cachefiles_trace_tmpfile_error, "tmpfile") \
+ EM(cachefiles_trace_trunc_error, "trunc") \
+ EM(cachefiles_trace_unlink_error, "unlink") \
+ E_(cachefiles_trace_write_error, "write")
+

/*
* Export enum symbols via userspace.
@@ -140,6 +179,7 @@ cachefiles_obj_ref_traces;
cachefiles_coherency_traces;
cachefiles_trunc_traces;
cachefiles_prepare_read_traces;
+cachefiles_error_traces;

/*
* Now redefine the EM() and E_() macros to map the enums to the strings that
@@ -496,6 +536,60 @@ TRACE_EVENT(cachefiles_trunc,
__entry->to)
);

+TRACE_EVENT(cachefiles_vfs_error,
+ TP_PROTO(struct cachefiles_object *obj, struct inode *backer,
+ int error, enum cachefiles_error_trace where),
+
+ TP_ARGS(obj, backer, error, where),
+
+ TP_STRUCT__entry(
+ __field(unsigned int, obj )
+ __field(unsigned int, backer )
+ __field(enum cachefiles_error_trace, where )
+ __field(short, error )
+ ),
+
+ TP_fast_assign(
+ __entry->obj = obj ? obj->debug_id : 0;
+ __entry->backer = backer->i_ino;
+ __entry->error = error;
+ __entry->where = where;
+ ),
+
+ TP_printk("o=%08x b=%08x %s e=%d",
+ __entry->obj,
+ __entry->backer,
+ __print_symbolic(__entry->where, cachefiles_error_traces),
+ __entry->error)
+ );
+
+TRACE_EVENT(cachefiles_io_error,
+ TP_PROTO(struct cachefiles_object *obj, struct inode *backer,
+ int error, enum cachefiles_error_trace where),
+
+ TP_ARGS(obj, backer, error, where),
+
+ TP_STRUCT__entry(
+ __field(unsigned int, obj )
+ __field(unsigned int, backer )
+ __field(enum cachefiles_error_trace, where )
+ __field(short, error )
+ ),
+
+ TP_fast_assign(
+ __entry->obj = obj ? obj->debug_id : 0;
+ __entry->backer = backer->i_ino;
+ __entry->error = error;
+ __entry->where = where;
+ ),
+
+ TP_printk("o=%08x b=%08x %s e=%d",
+ __entry->obj,
+ __entry->backer,
+ __print_symbolic(__entry->where, cachefiles_error_traces),
+ __entry->error)
+ );
+
#endif /* _TRACE_CACHEFILES_H */

/* This part must be outside protection */