> On Nov 12, 2015, at 6:34 PM, Arnaldo Carvalho de Melo <a...@kernel.org> wrote: > > Em Thu, Nov 12, 2015 at 11:09:48PM +0000, Kornievskaia, Olga escreveu: >> Just to elaborate further, what I’m interested in timings of NFS >> operations, so I’m not using any new tracepoints, but just the ones >> that are present in the code. However since NFS doesn’t various things >> outside of the process calling into NFS then will “perf trace” still >> work? > >> I’m using “perf record -e ‘nfs4:*’,’nfs:*’ -ag” command to generate >> tracing info. That captures tracepoints executed by the application as >> well as the kernel threads that do asynchronous IO. > > So, you can replace 'perf record' with 'perf trace' and what will be > captured will be the same, its just that 'perf trace' still doesn't > support callchains (-g), but as David Ahern asked, do you want those? > > Also, using -a you're not copying just the apps, but the whole system, > perhaps you want something like: > > [root@felicio /]# perf trace --no-syscalls --event nfs4:*’,’nfs:*’ cp > /etc/passwd /wb > 0.877 nfs:nfs_getattr_enter:fileid=00:26:2359297 fhandle=0x675bf9ee > version=6216388797857602399 ) > 0.891 nfs:nfs_revalidate_inode_enter:fileid=00:26:2359297 > fhandle=0x675bf9ee version=6216388797857602399 ) > 1.440 nfs4:nfs4_map_name_to_uid:error=0 id=0 name=0) > 1.445 nfs4:nfs4_map_group_to_gid:error=0 id=0 name=0) > 1.455 nfs4:nfs4_getattr:error=0 (ACCESS) fileid=00:26:2359297 > fhandle=0x675bf9ee > valid=TYPE|MODE|NLINK|OWNER|GROUP|RDEV|SIZE|FSID|FILEID|ATIME|MTIME|CTIME|CHANGE) > 1.460 nfs:nfs_refresh_inode_enter:fileid=00:26:2359297 fhandle=0x675bf9ee > version=6216388797857602399 ) > 1.466 nfs:nfs_refresh_inode_exit:error=0 fileid=00:26:2359297 > fhandle=0x675bf9ee type=4 (DIR) version=6216388797857602399 size=16384 > cache_validity=0 () nfs_flags=4 ()) > 1.471 nfs:nfs_revalidate_inode_exit:error=0 fileid=00:26:2359297 > fhandle=0x675bf9ee type=4 (DIR) version=6216388797857602399 size=16384 > cache_validity=0 () nfs_flags=4 ()) > 1.476 nfs:nfs_getattr_exit:error=0 fileid=00:26:2359297 > fhandle=0x675bf9ee type=4 (DIR) version=6216388797857602399 size=16384 > cache_validity=0 () nfs_flags=4 ()) > 1.493 nfs:nfs_access_enter:fileid=00:26:2359297 fhandle=0x675bf9ee > version=6216388797857602399 ) > 1.498 nfs:nfs_access_exit:error=0 fileid=00:26:2359297 fhandle=0x675bf9ee > type=4 (DIR) version=6216388797857602399 size=16384 cache_validity=0 () > nfs_flags=4 ()) > 1.504 nfs:nfs_lookup_enter:flags=1 () name=00:26:2359297/passwd) > 1.940 nfs4:nfs4_lookup:error=-2 () name=00:26:2359297/passwd) > 1.948 nfs:nfs_lookup_exit:error=-2 flags=1 () name=00:26:2359297/passwd) > 1.966 nfs:nfs_access_enter:fileid=00:26:2359297 fhandle=0x675bf9ee > version=6216388797857602399 ) > 1.971 nfs:nfs_access_exit:error=0 fileid=00:26:2359297 fhandle=0x675bf9ee > type=4 (DIR) version=6216388797857602399 size=16384 cache_validity=0 () > nfs_flags=4 ()) > 2.124 nfs:nfs_atomic_open_enter:flags=32961 (O_CREAT|O_EXCL) fmode=WRITE > name=00:26:2359297/passwd) > 8.402 nfs4:nfs4_map_name_to_uid:error=0 id=0 name=0) > 8.421 nfs4:nfs4_map_group_to_gid:error=0 id=0 name=0) > 13.156 nfs4:nfs4_map_name_to_uid:error=0 id=0 name=0) > 13.175 nfs4:nfs4_map_group_to_gid:error=0 id=0 name=0) > 13.187 nfs4:nfs4_setattr:error=0 (ACCESS) fileid=00:26:2360376 > fhandle=0xfd52be06) > 13.199 nfs4:nfs4_open_file:error=0 (ACCESS) flags=32961 (O_CREAT|O_EXCL) > fmode=WRITE fileid=00:26:2360376 fhandle=0xfd52be06 name=00:26:2359297/passwd) > 13.212 nfs:nfs_atomic_open_exit:error=0 flags=32961 (O_CREAT|O_EXCL) > fmode=WRITE name=00:26:2359297/passwd) > 13.223 nfs:nfs_getattr_enter:fileid=00:26:2360376 fhandle=0xfd52be06 > version=6216410651367497762 ) > 13.229 nfs:nfs_writeback_inode_enter:fileid=00:26:2360376 > fhandle=0xfd52be06 version=6216410651367497762 ) > 13.235 nfs:nfs_writeback_inode_exit:error=0 fileid=00:26:2360376 > fhandle=0xfd52be06 type=8 (REG) version=6216410651367497762 size=0 > cache_validity=24 (INVALID_ACCESS|INVALID_ACL) nfs_flags=0 ()) > 13.239 nfs:nfs_getattr_exit:error=0 fileid=00:26:2360376 > fhandle=0xfd52be06 type=8 (REG) version=6216410651367497762 size=0 > cache_validity=24 (INVALID_ACCESS|INVALID_ACL) nfs_flags=0 ()) > 13.275 nfs:nfs_fsync_enter:fileid=00:26:2360376 fhandle=0xfd52be06 > version=6216410651367497762 ) > 18.359 nfs:nfs_fsync_exit:error=0 fileid=00:26:2360376 fhandle=0xfd52be06 > type=8 (REG) version=6216410651372497681 size=1576 cache_validity=25 > (INVALID_ATTR|INVALID_ACCESS|INVALID_ACL) nfs_flags=0 ()) > [root@felicio /]# > > If you remove the --no-syscalls, it gets even nicer, here is a slice: > > 10.909 ( 7.182 ms): cp/14149 ... [continued]: open()) = 4 > 10.922 ( 0.005 ms): cp/14149 fstat(fd: 4, statbuf: 0x7ffe38a34be0 > ) ... > 10.922 ( ): nfs:nfs_getattr_enter:fileid=00:26:2360376 > fhandle=0xfd52be06 version=6216410999163535246 ) > 10.927 ( ): nfs:nfs_writeback_inode_enter:fileid=00:26:2360376 > fhandle=0xfd52be06 version=6216410999163535246 ) > 10.931 ( ): nfs:nfs_writeback_inode_exit:error=0 > fileid=00:26:2360376 fhandle=0xfd52be06 type=8 (REG) > version=6216410999163535246 size=0 cache_validity=24 > (INVALID_ACCESS|INVALID_ACL) nfs_flags=4 ()) > 10.936 ( ): nfs:nfs_getattr_exit:error=0 fileid=00:26:2360376 > fhandle=0xfd52be06 type=8 (REG) version=6216410999163535246 size=0 > cache_validity=24 (INVALID_ACCESS|INVALID_ACL) nfs_flags=4 ()) > 10.948 ( 0.031 ms): cp/14149 ... [continued]: fstat()) = 0 > 10.959 ( 0.005 ms): cp/14149 fadvise64(fd: 3</etc/passwd>, advice: 2 > ) = 0 > 10.978 ( 0.013 ms): cp/14149 mmap(len: 1056768, prot: READ|WRITE, flags: > PRIVATE|ANONYMOUS, fd: -1 ) = 0x7f4de0fd3000 > 10.994 ( 0.008 ms): cp/14149 read(fd: 3</etc/passwd>, buf: 0x7f4de0fd4000, > count: 1048576 ) = 1576 > 11.012 ( 0.013 ms): cp/14149 write(fd: 4, buf: 0x7f4de0fd4000, count: 1576 > ) = 1576 > 11.022 ( 0.005 ms): cp/14149 read(fd: 3</etc/passwd>, buf: 0x7f4de0fd4000, > count: 1048576 ) = 0 > 11.033 ( 0.005 ms): cp/14149 close(fd: 4 > ) ... > 11.033 ( ): nfs:nfs_fsync_enter:fileid=00:26:2360376 > fhandle=0xfd52be06 version=6216410999163535246 ) > 15.535 ( ): nfs:nfs_fsync_exit:error=0 fileid=00:26:2360376 > fhandle=0xfd52be06 type=8 (REG) version=6216410999169535149 size=1576 > cache_validity=25 (INVALID_ATTR|INVALID_ACCESS|INVALID_ACL) nfs_flags=4 ()) > 15.544 ( 4.517 ms): cp/14149 ... [continued]: close()) = 0 > 16.058 ( 0.011 ms): cp/14149 close(fd: 3</etc/passwd> > ) = 0 > > Humm, so you want to pair things like: > > 10.927 ( ): nfs:nfs_writeback_inode_enter:fileid=00:26:2360376 > fhandle=0xfd52be06 version=6216410999163535246 ) > 10.931 ( ): nfs:nfs_writeback_inode_exit:error=0 > fileid=00:26:2360376 fhandle=0xfd52be06 type=8 (REG) > version=6216410999163535246 size=0 cache_validity=24 > (INVALID_ACCESS|INVALID_ACL) nfs_flags=4 ()) > > Using fileid as the key i addition to the common_pid, etc? That would be a > nice > feature to have in 'perf trace'... :-) > > There is also: > > 11.033 ( ): nfs:nfs_fsync_enter:fileid=00:26:2360376 > fhandle=0xfd52be06 version=6216410999163535246 ) > 15.535 ( ): nfs:nfs_fsync_exit:error=0 fileid=00:26:2360376 > fhandle=0xfd52be06 type=8 (REG) version=6216410999169535149 size=1576 > cache_validity=25 (INVALID_ATTR|INVALID_ACCESS|INVALID_ACL) nfs_flags=4 ()) > > Well, you also can just get these and do some scripting, no, in this case: > > 15.535 - 11.033 = 4.502ms > > for that nfs_fsync :-)
David and Arnaldo thank you your replies. I can see that to acquire the timings for non-syscall events requires scripting. Would I be missing something by not using “perf” and instead doing scripting on the output that I get from the trace_pipe? I guess instead of the numeric timestamps that are present in the raw tracepoint information, I’ll get a converted value in seconds from perf. Is there something else I’d be missing? Thank you.
