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@xxxxxxxxxx> --- 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 */