From b70890b1386f973df95454ba605cc8ad5b79c55f Mon Sep 17 00:00:00 2001 From: Pawel Dziepak Date: Thu, 1 Nov 2012 01:03:20 +0100 Subject: [PATCH] nfs4: Add basic tracing of nfs4 module calls --- .../file_systems/nfs4/kernel_interface.cpp | 122 +++++++++++++++++- 1 file changed, 121 insertions(+), 1 deletion(-) diff --git a/src/add-ons/kernel/file_systems/nfs4/kernel_interface.cpp b/src/add-ons/kernel/file_systems/nfs4/kernel_interface.cpp index 11ef428715..498d1e5f2c 100644 --- a/src/add-ons/kernel/file_systems/nfs4/kernel_interface.cpp +++ b/src/add-ons/kernel/file_systems/nfs4/kernel_interface.cpp @@ -14,7 +14,6 @@ #include #include "Connection.h" -#include "Debug.h" #include "FileSystem.h" #include "IdMap.h" #include "Inode.h" @@ -26,6 +25,22 @@ #include "RPCServer.h" #include "WorkQueue.h" +#define TRACE_NFS4 + +#ifdef TRACE_NFS4 +static mutex gTraceLock = MUTEX_INITIALIZER(NULL); + +#define TRACE(x...) \ + { \ + mutex_lock(&gTraceLock); \ + dprintf("%s(): ", __FUNCTION__); \ + dprintf(x); \ + dprintf("\n"); \ + mutex_unlock(&gTraceLock); \ + } +#else +#define TRACE(x...) (void)0 +#endif extern fs_volume_ops gNFSv4VolumeOps; extern fs_vnode_ops gNFSv4VnodeOps; @@ -123,6 +138,9 @@ static status_t nfs4_mount(fs_volume* volume, const char* device, uint32 flags, const char* args, ino_t* _rootVnodeID) { + TRACE("volume = %p, device = %s, flags = %lu, args = %s", volume, device, + flags, args); + status_t result; /* prepare idmapper server */ @@ -177,6 +195,8 @@ nfs4_mount(fs_volume* volume, const char* device, uint32 flags, *_rootVnodeID = inode->ID(); + TRACE("*_rootVnodeID = %llu", inode->ID()); + return B_OK; } @@ -185,6 +205,8 @@ static status_t nfs4_get_vnode(fs_volume* volume, ino_t id, fs_vnode* vnode, int* _type, uint32* _flags, bool reenter) { + TRACE("volume = %p, id = %llu", volume, id); + FileSystem* fs = reinterpret_cast(volume->private_volume); Inode* inode; status_t result = fs->GetInode(id, &inode); @@ -204,6 +226,7 @@ nfs4_get_vnode(fs_volume* volume, ino_t id, fs_vnode* vnode, int* _type, static status_t nfs4_unmount(fs_volume* volume) { + TRACE("volume = %p", volume); FileSystem* fs = reinterpret_cast(volume->private_volume); RPC::Server* server = fs->Server(); @@ -217,6 +240,8 @@ nfs4_unmount(fs_volume* volume) static status_t nfs4_read_fs_info(fs_volume* volume, struct fs_info* info) { + TRACE("volume = %p", volume); + FileSystem* fs = reinterpret_cast(volume->private_volume); RootInode* inode = reinterpret_cast(fs->Root()); return inode->ReadInfo(info); @@ -227,11 +252,16 @@ static status_t nfs4_lookup(fs_volume* volume, fs_vnode* dir, const char* name, ino_t* _id) { Inode* inode = reinterpret_cast(dir->private_node); + + TRACE("volume = %p, dir = %llu, name = %s", volume, inode->ID(), name); + status_t result = inode->LookUp(name, _id); if (result != B_OK) return result; void* ptr; + + TRACE("*_id = %llu", *_id); return get_vnode(volume, *_id, &ptr); } @@ -241,6 +271,9 @@ nfs4_get_vnode_name(fs_volume* volume, fs_vnode* vnode, char* buffer, size_t bufferSize) { Inode* inode = reinterpret_cast(vnode->private_node); + + TRACE("volume = %p, vnode = %llu", volume, inode->ID()); + strncpy(buffer, inode->Name(), bufferSize); return B_OK; } @@ -251,6 +284,9 @@ nfs4_put_vnode(fs_volume* volume, fs_vnode* vnode, bool reenter) { FileSystem* fs = reinterpret_cast(volume->private_volume); Inode* inode = reinterpret_cast(vnode->private_node); + + TRACE("volume = %p, vnode = %llu", volume, inode->ID()); + if (fs->Root() == inode) return B_OK; @@ -270,6 +306,9 @@ nfs4_remove_vnode(fs_volume* volume, fs_vnode* vnode, bool reenter) FileSystem* fs = reinterpret_cast(volume->private_volume); Inode* inode = reinterpret_cast(vnode->private_node); + + TRACE("volume = %p, vnode = %llu", volume, inode->ID()); + if (fs->Root() == inode) return B_OK; @@ -285,6 +324,11 @@ nfs4_read_pages(fs_volume* _volume, fs_vnode* vnode, void* _cookie, off_t pos, const iovec* vecs, size_t count, size_t* _numBytes) { Inode* inode = reinterpret_cast(vnode->private_node); + + TRACE("volume = %p, vnode = %llu, cookie = %p, pos = %llu, " \ + "count = %lu, numBytes = %lu", _volume, inode->ID(), _cookie, pos, + count, *_numBytes); + OpenFileCookie* cookie = reinterpret_cast(_cookie); status_t result; @@ -309,6 +353,8 @@ nfs4_read_pages(fs_volume* _volume, fs_vnode* vnode, void* _cookie, off_t pos, *_numBytes = totalRead; + TRACE("*numBytes = %lu", totalRead); + return B_OK; } @@ -318,6 +364,11 @@ nfs4_write_pages(fs_volume* _volume, fs_vnode* vnode, void* _cookie, off_t pos, const iovec* vecs, size_t count, size_t* _numBytes) { Inode* inode = reinterpret_cast(vnode->private_node); + + TRACE("volume = %p, vnode = %llu, cookie = %p, pos = %llu, " \ + "count = %lu, numBytes = %lu", _volume, inode->ID(), _cookie, pos, + count, *_numBytes); + OpenFileCookie* cookie = reinterpret_cast(_cookie); status_t result; @@ -350,6 +401,9 @@ nfs4_io(fs_volume* volume, fs_vnode* vnode, void* cookie, io_request* request) { Inode* inode = reinterpret_cast(vnode->private_node); + TRACE("volume = %p, vnode = %llu, cookie = %p", volume, inode->ID(), + cookie); + IORequestArgs* args = new(std::nothrow) IORequestArgs; if (args == NULL) { notify_io_request(request, B_NO_MEMORY); @@ -377,6 +431,9 @@ nfs4_get_file_map(fs_volume* volume, fs_vnode* vnode, off_t _offset, static status_t nfs4_set_flags(fs_volume* volume, fs_vnode* vnode, void* _cookie, int flags) { + TRACE("volume = %p, vnode = %llu, cookie = %p, flags = %d", volume, + reinterpret_cast(vnode->private_node)->ID(), _cookie, flags); + OpenFileCookie* cookie = reinterpret_cast(_cookie); cookie->fMode = (cookie->fMode & ~(O_APPEND | O_NONBLOCK)) | flags; return B_OK; @@ -387,6 +444,7 @@ static status_t nfs4_fsync(fs_volume* volume, fs_vnode* vnode) { Inode* inode = reinterpret_cast(vnode->private_node); + TRACE("volume = %p, vnode = %llu", volume, inode->ID()); return inode->SyncAndCommit(); } @@ -396,6 +454,7 @@ nfs4_read_symlink(fs_volume* volume, fs_vnode* link, char* buffer, size_t* _bufferSize) { Inode* inode = reinterpret_cast(link->private_node); + TRACE("volume = %p, link = %llu", volume, inode->ID()); return inode->ReadLink(buffer, _bufferSize); } @@ -405,6 +464,8 @@ nfs4_create_symlink(fs_volume* volume, fs_vnode* dir, const char* name, const char* path, int mode) { Inode* inode = reinterpret_cast(dir->private_node); + TRACE("volume = %p, dir = %llu, name = %s, path = %s, mode = %d", volume, + inode->ID(), name, path, mode); return inode->CreateLink(name, path, mode); } @@ -414,6 +475,8 @@ nfs4_link(fs_volume* volume, fs_vnode* dir, const char* name, fs_vnode* vnode) { Inode* inode = reinterpret_cast(vnode->private_node); Inode* dirInode = reinterpret_cast(dir->private_node); + TRACE("volume = %p, dir = %llu, name = %s, vnode = %llu", volume, + dirInode->ID(), name, inode->ID()); return inode->Link(dirInode, name); } @@ -423,6 +486,8 @@ nfs4_unlink(fs_volume* volume, fs_vnode* dir, const char* name) { Inode* inode = reinterpret_cast(dir->private_node); + TRACE("volume = %p, dir = %llu, name = %s", volume, inode->ID(), name); + ino_t id; status_t result = inode->Remove(name, NF4REG, &id); if (result != B_OK) @@ -439,6 +504,10 @@ nfs4_rename(fs_volume* volume, fs_vnode* fromDir, const char* fromName, Inode* fromInode = reinterpret_cast(fromDir->private_node); Inode* toInode = reinterpret_cast(toDir->private_node); + TRACE("volume = %p, fromDir = %llu, toDir = %llu, fromName = %s, " \ + "toName = %s", volume, fromInode->ID(), toInode->ID(), fromName, + toName); + ino_t id; status_t result = Inode::Rename(fromInode, toInode, fromName, toName, false, &id); @@ -460,6 +529,7 @@ static status_t nfs4_access(fs_volume* volume, fs_vnode* vnode, int mode) { Inode* inode = reinterpret_cast(vnode->private_node); + TRACE("volume = %p, vnode = %llu, mode = %d", volume, inode->ID(), mode); return inode->Access(mode); } @@ -468,6 +538,7 @@ static status_t nfs4_read_stat(fs_volume* volume, fs_vnode* vnode, struct stat* stat) { Inode* inode = reinterpret_cast(vnode->private_node); + TRACE("volume = %p, vnode = %llu", volume, inode->ID()); return inode->Stat(stat); } @@ -477,6 +548,8 @@ nfs4_write_stat(fs_volume* volume, fs_vnode* vnode, const struct stat* stat, uint32 statMask) { Inode* inode = reinterpret_cast(vnode->private_node); + TRACE("volume = %p, vnode = %llu, statMask = %lu", volume, inode->ID(), + statMask); return inode->WriteStat(stat, statMask); } @@ -492,6 +565,9 @@ nfs4_create(fs_volume* volume, fs_vnode* dir, const char* name, int openMode, Inode* inode = reinterpret_cast(dir->private_node); + TRACE("volume = %p, dir = %llu, name = %s, openMode = %d, perms = %d", + volume, inode->ID(), name, openMode, perms); + OpenDelegationData data; status_t result = inode->Create(name, openMode, perms, cookie, &data, _newVnodeID); @@ -530,6 +606,8 @@ nfs4_create(fs_volume* volume, fs_vnode* dir, const char* name, int openMode, } } + TRACE("*cookie = %p, *newVnodeID = %llu", *_cookie, *_newVnodeID); + return result; } @@ -539,6 +617,9 @@ nfs4_open(fs_volume* volume, fs_vnode* vnode, int openMode, void** _cookie) { Inode* inode = reinterpret_cast(vnode->private_node); + TRACE("volume = %p, vnode = %llu, openMode = %d", volume, inode->ID(), + openMode); + if (inode->Type() == S_IFDIR || inode->Type() == S_IFLNK) { *_cookie = NULL; return B_OK; @@ -553,6 +634,8 @@ nfs4_open(fs_volume* volume, fs_vnode* vnode, int openMode, void** _cookie) if (result != B_OK) delete cookie; + TRACE("*cookie = %p", *_cookie); + return result; } @@ -562,6 +645,9 @@ nfs4_close(fs_volume* volume, fs_vnode* vnode, void* _cookie) { Inode* inode = reinterpret_cast(vnode->private_node); + TRACE("volume = %p, vnode = %llu, cookie = %p", volume, inode->ID(), + _cookie); + if (inode->Type() == S_IFDIR || inode->Type() == S_IFLNK) return B_OK; @@ -575,6 +661,9 @@ nfs4_free_cookie(fs_volume* volume, fs_vnode* vnode, void* _cookie) { Inode* inode = reinterpret_cast(vnode->private_node); + TRACE("volume = %p, vnode = %llu, cookie = %p", volume, inode->ID(), + _cookie); + if (inode->Type() == S_IFDIR || inode->Type() == S_IFLNK) return B_OK; @@ -593,6 +682,9 @@ nfs4_read(fs_volume* volume, fs_vnode* vnode, void* _cookie, off_t pos, { Inode* inode = reinterpret_cast(vnode->private_node); + TRACE("volume = %p, vnode = %llu, cookie = %p, pos = %llu, length = %lu", + volume, inode->ID(), _cookie, pos, *length); + if (inode->Type() == S_IFDIR) return B_IS_A_DIRECTORY; @@ -611,6 +703,9 @@ nfs4_write(fs_volume* volume, fs_vnode* vnode, void* _cookie, off_t pos, { Inode* inode = reinterpret_cast(vnode->private_node); + TRACE("volume = %p, vnode = %llu, cookie = %p, pos = %llu, length = %lu", + volume, inode->ID(), _cookie, pos, *length); + if (inode->Type() == S_IFDIR) return B_IS_A_DIRECTORY; @@ -628,6 +723,7 @@ nfs4_create_dir(fs_volume* volume, fs_vnode* parent, const char* name, int mode) { Inode* inode = reinterpret_cast(parent->private_node); + TRACE("volume = %p, parent = %llu, mode = %d", volume, inode->ID(), mode); return inode->CreateDir(name, mode); } @@ -636,6 +732,7 @@ static status_t nfs4_remove_dir(fs_volume* volume, fs_vnode* parent, const char* name) { Inode* inode = reinterpret_cast(parent->private_node); + TRACE("volume = %p, parent = %llu, name = %s", volume, inode->ID(), name); ino_t id; status_t result = inode->Remove(name, NF4DIR, &id); if (result != B_OK) @@ -653,10 +750,13 @@ nfs4_open_dir(fs_volume* volume, fs_vnode* vnode, void** _cookie) *_cookie = cookie; Inode* inode = reinterpret_cast(vnode->private_node); + TRACE("volume = %p, vnode = %llu", volume, inode->ID()); status_t result = inode->OpenDir(cookie); if (result != B_OK) delete cookie; + TRACE("*cookie = %p", *_cookie); + return result; } @@ -664,6 +764,9 @@ nfs4_open_dir(fs_volume* volume, fs_vnode* vnode, void** _cookie) static status_t nfs4_close_dir(fs_volume* volume, fs_vnode* vnode, void* _cookie) { + TRACE("volume = %p, vnode = %llu, cookie = %p", volume, + reinterpret_cast(vnode->private_node)->ID(), _cookie); + Cookie* cookie = reinterpret_cast(_cookie); return cookie->CancelAll(); } @@ -672,6 +775,9 @@ nfs4_close_dir(fs_volume* volume, fs_vnode* vnode, void* _cookie) static status_t nfs4_free_dir_cookie(fs_volume* volume, fs_vnode* vnode, void* cookie) { + TRACE("volume = %p, vnode = %llu, cookie = %p", volume, + reinterpret_cast(vnode->private_node)->ID(), cookie); + delete reinterpret_cast(cookie); return B_OK; } @@ -683,6 +789,10 @@ nfs4_read_dir(fs_volume* volume, fs_vnode* vnode, void* _cookie, { OpenDirCookie* cookie = reinterpret_cast(_cookie); Inode* inode = reinterpret_cast(vnode->private_node); + + TRACE("volume = %p, vnode = %llu, cookie = %p", volume, inode->ID(), + _cookie); + return inode->ReadDir(buffer, bufferSize, _num, cookie); } @@ -690,6 +800,9 @@ nfs4_read_dir(fs_volume* volume, fs_vnode* vnode, void* _cookie, static status_t nfs4_rewind_dir(fs_volume* volume, fs_vnode* vnode, void* _cookie) { + TRACE("volume = %p, vnode = %llu, cookie = %p", volume, + reinterpret_cast(vnode->private_node)->ID(), _cookie); + OpenDirCookie* cookie = reinterpret_cast(_cookie); cookie->fSpecial = 0; cookie->fCurrent = NULL; @@ -708,6 +821,7 @@ nfs4_open_attr_dir(fs_volume* volume, fs_vnode* vnode, void** _cookie) *_cookie = cookie; Inode* inode = reinterpret_cast(vnode->private_node); + TRACE("volume = %p, vnode = %llu", volume, inode->ID()); status_t result = inode->OpenAttrDir(cookie); if (result != B_OK) delete cookie; @@ -869,6 +983,8 @@ nfs4_test_lock(fs_volume* volume, fs_vnode* vnode, void* _cookie, { Inode* inode = reinterpret_cast(vnode->private_node); OpenFileCookie* cookie = reinterpret_cast(_cookie); + TRACE("volume = %p, vnode = %llu, cookie = %p, lock = %p", volume, + inode->ID(), _cookie, lock); return inode->TestLock(cookie, lock); } @@ -879,6 +995,8 @@ nfs4_acquire_lock(fs_volume* volume, fs_vnode* vnode, void* _cookie, { Inode* inode = reinterpret_cast(vnode->private_node); OpenFileCookie* cookie = reinterpret_cast(_cookie); + TRACE("volume = %p, vnode = %llu, cookie = %p, lock = %p", volume, + inode->ID(), _cookie, lock); inode->RevalidateFileCache(); @@ -891,6 +1009,8 @@ nfs4_release_lock(fs_volume* volume, fs_vnode* vnode, void* _cookie, const struct flock* lock) { Inode* inode = reinterpret_cast(vnode->private_node); + TRACE("volume = %p, vnode = %llu, cookie = %p, lock = %p", volume, + inode->ID(), _cookie, lock); if (inode->Type() == S_IFDIR || inode->Type() == S_IFLNK) return B_OK;