kmod: add inode lifetime and lock tracepoints

kmod/dir.c

@@ -516,6 +516,7 @@ static int ternfs_dir_close(struct inode* inode, struct file* filp) {
 static loff_t ternfs_dir_seek(struct file* file, loff_t offset, int whence) {
     struct inode* inode = file_inode(file);
 
+    trace_eggsfs_inode_lock(inode, TERNFS_INODE_LOCK, "readdir");
     inode_lock(inode);
 
     switch (whence) {
@@ -543,6 +544,7 @@ static loff_t ternfs_dir_seek(struct file* file, loff_t offset, int whence) {
 
 out_err:
     inode_unlock(inode);
+    trace_eggsfs_inode_lock(inode, TERNFS_INODE_UNLOCK, "readdir");
     return offset;
 }
 

kmod/file.c

@@ -72,6 +72,7 @@ static_assert(sizeof(struct ternfs_transient_span) < (2<<10));
 // open_mutex held here
 // really want atomic open for this
 static int file_open(struct inode* inode, struct file* filp) {
+    trace_eggsfs_inode_lock(inode, TERNFS_INODE_LOCK, "file_open");
     inode_lock(inode); // for the .status modification below
 
     struct ternfs_inode* enode = TERNFS_I(inode);
@@ -132,6 +133,7 @@ static int file_open(struct inode* inode, struct file* filp) {
     }
 out:
     inode_unlock(inode);
+    trace_eggsfs_inode_lock(inode, TERNFS_INODE_UNLOCK, "file_open");
     return err;
 }
 
@@ -891,18 +893,24 @@ static ssize_t file_write_iter(struct kiocb* iocb, struct iov_iter* from) {
     struct ternfs_inode* enode = TERNFS_I(inode);
 
     if (!inode_trylock(inode)) {
+        trace_eggsfs_inode_lock(inode, TERNFS_INODE_LOCK_TRYLOCK_FAIL, "write_iter");
         if (iocb->ki_flags & IOCB_NOWAIT) {
             return -EAGAIN;
         }
+        trace_eggsfs_inode_lock(inode, TERNFS_INODE_LOCK, "write_iter");
         inode_lock(inode);
+    } else {
+        trace_eggsfs_inode_lock(inode, TERNFS_INODE_LOCK_TRYLOCK, "write_iter");
     }
     ssize_t res = ternfs_file_write(enode, iocb->ki_flags, &iocb->ki_pos, from);
     inode_unlock(inode);
+    trace_eggsfs_inode_lock(inode, TERNFS_INODE_UNLOCK, "write_iter");
 
     return res;
 }
 
 int ternfs_file_flush(struct ternfs_inode* enode, struct dentry* dentry) {
+    trace_eggsfs_inode_lock(&enode->inode, TERNFS_INODE_LOCK, "flush");
     inode_lock(&enode->inode);
 
     int err = 0;
@@ -1003,10 +1011,12 @@ out:
     }
     enode->file.mm = NULL;
     inode_unlock(&enode->inode);
+    trace_eggsfs_inode_lock(&enode->inode, TERNFS_INODE_UNLOCK, "flush");
     return err;
 
 out_early:
     inode_unlock(&enode->inode);
+    trace_eggsfs_inode_lock(&enode->inode, TERNFS_INODE_UNLOCK, "flush");
     return err;
 }
 
@@ -1117,6 +1127,7 @@ static loff_t file_lseek(struct file *file, loff_t offset, int whence) {
         return generic_file_llseek(file, offset, whence);
     }
 
+    trace_eggsfs_inode_lock(inode, TERNFS_INODE_LOCK, "lseek");
     inode_lock(inode);
 
     loff_t ppos = file->f_pos;
@@ -1153,6 +1164,7 @@ static loff_t file_lseek(struct file *file, loff_t offset, int whence) {
 
 out:
     inode_unlock(inode);
+    trace_eggsfs_inode_lock(inode, TERNFS_INODE_UNLOCK, "lseek");
     return offset;
 
 out_err:

kmod/inode.c

@@ -51,11 +51,13 @@ struct inode* ternfs_inode_alloc(struct super_block* sb) {
     INIT_DELAYED_WORK(&enode->getattr_async_work, &getattr_async_complete);
 
     ternfs_debug("done enode=%p", enode);
+    trace_eggsfs_inode_alloc(&enode->inode);
     return &enode->inode;
 }
 
 void ternfs_inode_evict(struct inode* inode) {
     struct ternfs_inode* enode = TERNFS_I(inode);
+    trace_eggsfs_inode_evict(inode);
     ternfs_debug("evict enode=%p", enode);
     if (S_ISDIR(inode->i_mode)) {
         ternfs_dir_drop_cache(enode);
@@ -69,6 +71,7 @@ void ternfs_inode_evict(struct inode* inode) {
 void ternfs_inode_free(struct inode* inode) {
 
     struct ternfs_inode* enode = TERNFS_I(inode);
+    trace_eggsfs_inode_free(inode);
     ternfs_debug("enode=%p", enode);
     kmem_cache_free(ternfs_inode_cachep, enode);
 }
@@ -592,9 +595,11 @@ static int COMPAT_FUNC_UNS_IMP(ternfs_symlink, struct inode* dir, struct dentry*
     vec.iov_base = (void*)path;
     vec.iov_len = len;
     iov_iter_kvec(&from, WRITE, &vec, 1, vec.iov_len);
+    trace_eggsfs_inode_lock(&enode->inode, TERNFS_INODE_LOCK, "symlink");
     inode_lock(&enode->inode);
     int err = ternfs_file_write(enode, 0, &ppos, &from);
     inode_unlock(&enode->inode);
+    trace_eggsfs_inode_lock(&enode->inode, TERNFS_INODE_UNLOCK, "symlink");
     if (err < 0) { return err; }
     // ...and flush them
     err = ternfs_file_flush(enode, dentry);

kmod/trace.h

@@ -183,10 +183,42 @@ TERNFS_TRACE_EVENT_dir_dentry_inode(dcache_delete_entry);
 TERNFS_TRACE_EVENT_dir_dentry_inode(dcache_invalidate_entry);
 
 // inode.c
+TERNFS_TRACE_EVENT_inode(inode_alloc);
+TERNFS_TRACE_EVENT_inode(inode_evict);
+TERNFS_TRACE_EVENT_inode(inode_free);
+
 TERNFS_TRACE_EVENT_inode(vfs_getattr_enter);
 TERNFS_TRACE_EVENT_inode(vfs_getattr_lock);
 TERNFS_TRACE_EVENT_inode_ret(vfs_getattr_exit);
 
+#define TERNFS_INODE_LOCK 0
+#define TERNFS_INODE_LOCK_TRYLOCK 1
+#define TERNFS_INODE_LOCK_TRYLOCK_FAIL 2
+#define TERNFS_INODE_UNLOCK 3
+
+TRACE_EVENT(eggsfs_inode_lock,
+    TP_PROTO(struct inode* inode, u8 event, const char* caller),
+    TP_ARGS(inode, event, caller),
+    TP_STRUCT__entry(
+        __field(u64, ino)
+        __field(u8, event)
+        __string(caller, caller)
+    ),
+    TP_fast_assign(
+        __entry->ino = inode->i_ino;
+        __entry->event = event;
+        __assign_str_impl(caller, caller);
+    ),
+    TP_printk("enode=%#llx event=%s caller=%s",
+        __entry->ino,
+        __print_symbolic(__entry->event,
+            { 0, "lock" },
+            { 1, "trylock" },
+            { 2, "trylock_fail" },
+            { 3, "unlock" }),
+        __get_str(caller))
+);
+
 // dir.c
 TERNFS_TRACE_EVENT_inode(vfs_opendir_enter);
 TERNFS_TRACE_EVENT_inode_ret(vfs_opendir_exit);