Re: timing information with perf

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

Em Fri, Nov 13, 2015 at 05:01:57PM +0000, Kornievskaia, Olga escreveu:
> > On Nov 12, 2015, at 6:34 PM, Arnaldo Carvalho de Melo <acme@kernel.org> wrote:
> > 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

Both will present you with the timestamp and parameters for the enabled
tracepoints, so I think that at this state, yes, you will not get
anything better from perf than what you'll get from ftrace via debugfs.

But this comes from time to time, the logic used for
raw_syscalls:sys_enter -> raw_syscalls:sys_exit, using some set of keys
to match one to the other should be extended to be used with non-syscall
events, such as the ones you mention here.

i.e. whereas raw_syscalls:sys_exit has a "ret" variable to tell the
result of the sys_enter+sys_exit operation, nfs_fsync_exit has "error",
I guess, for the same purpose :)

- Arnaldo