Re: timing information with perf

[Arnaldo Carvalho de Melo <acme@kernel.org>]

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 :-)

- Arnaldo