ftrace events: parameter tracing

ftrace events: parameter tracing

[Christof Warlich]

Hi all,

using ftrace events to trace the sys_open*() system calls seems to be a 
rather quick way to determine which files were used when running a 
program. E.g., recording the the start and the end of any open* system 
call while running ls /:

    # trace-cmd record --stderr? -e syscalls:sys_enter_open* -e
    syscalls:sys_exit_open* -c -F ls / 2>/dev/null

Printing the recorded trace yields::

    # trace-cmd report
    bin ?? dev??? home??? ??? initrd.img.old? lib32? lost+found mnt?
    proc? run??? snap? sys? usr??? vmlinuz
    etc??? initrd.img? lib??? ??? ??? lib64? media?????? opt? root
    sbin??? srv?? tmp? var??? vmlinuz.old
    version = 6
    CPU 0 is empty
    CPU 1 is empty
    CPU 3 is empty
    CPU 4 is empty
    CPU 5 is empty
    CPU 6 is empty
    CPU 7 is empty
    cpus=8
     ????????????? ls-8307? [002] 15379.397993: sys_enter_open:
    filename: 0x7f471c8e9271, flags: 0x00080000, mode: 0x00000001
     ????????????? ls-8307? [002] 15379.398000: sys_exit_open: 0x3
     ????????????? ls-8307? [002] 15379.398012: sys_enter_open:
    filename: 0x7f471caf0d60, flags: 0x00080000, mode: 0x7f471caf0168
     ????????????? ls-8307? [002] 15379.398013: sys_exit_open: 0x3
     ????????????? ls-8307? [002] 15379.398043: sys_enter_open:
    filename: 0x7f471cad14c8, flags: 0x00080000, mode: 0x7f471caf0168
     ????????????? ls-8307? [002] 15379.398045: sys_exit_open: 0x3
     ????????????? ls-8307? [002] 15379.398070: sys_enter_open:
    filename: 0x7f471cad19a8, flags: 0x00080000, mode: 0x7f471cad1000
     ????????????? ls-8307? [002] 15379.398071: sys_exit_open: 0x3
     ????????????? ls-8307? [002] 15379.398092: sys_enter_open:
    filename: 0x7f471cad1e98, flags: 0x00080000, mode: 0x7f471cad1000
     ????????????? ls-8307? [002] 15379.398094: sys_exit_open: 0x3
     ????????????? ls-8307? [002] 15379.398113: sys_enter_open:
    filename: 0x7f471cad0548, flags: 0x00080000, mode: 0x7f471cad19d0
     ????????????? ls-8307? [002] 15379.398115: sys_exit_open: 0x3
     ????????????? ls-8307? [002] 15379.398326: sys_enter_open:
    filename: 0x7f471c6bfc15, flags: 0x00000000, mode: 0x000001b6
     ????????????? ls-8307? [002] 15379.398331: sys_exit_open: 0x3
     ????????????? ls-8307? [002] 15379.398375: sys_enter_open:
    filename: 0x7f471c470760, flags: 0x00080000, mode: 0x00000000
     ????????????? ls-8307? [002] 15379.398380: sys_exit_open: 0x3
     ????????????? ls-8307? [002] 15379.398428: sys_enter_open:
    filename: 0x01c97cc0, flags: 0x00090800, mode: 0x00000000
     ????????????? ls-8307? [002] 15379.398430: sys_exit_open: 0x3

Unfortunately, although ftrace prints the filename's address for each 
file being opened, I could not seen any way to obtain the filenames 
themselves.

Any ideas on how to get hold of the filenames would be great, thanks.

Cheers,

Chris

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kernelnewbies.org/pipermail/kernelnewbies/attachments/20180214/e46e4a48/attachment.html>

ftrace events: parameter tracing

[valdis.kletnieks at vt.edu]

On Wed, 14 Feb 2018 19:39:31 +0100, Christof Warlich said:

> Unfortunately, although ftrace prints the filename's address for each 
> file being opened, I could not seen any way to obtain the filenames 
> themselves.
>
> Any ideas on how to get hold of the filenames would be great, thanks.

What's wrong with this?

/usr/bin/strace /bin/ls /
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 486 bytes
Desc: not available
URL: <http://lists.kernelnewbies.org/pipermail/kernelnewbies/attachments/20180214/f2a5dbfa/attachment.sig>

ftrace events: parameter tracing

[Christof Warlich]

Am 14.02.2018 um 19:47 schrieb valdis.kletnieks at vt.edu:

 > What's wrong with this?
 > /usr/bin/strace /bin/ls /

I started uisng strace, and you are right, it does what I want. But it 
is just too slow for my purpose: I want to record all dependencies, 
intermediates and results of an arbitrary build process to automatically 
record the build's dependencies. On subsequent runs of the build, these 
depencencies could then be used to decide which compoments must be 
rebuilt due to changed dependencies.

But using strace (or even ptrace directly) typically doubles the build 
times, which is unacceptable particularly because the whole point was to 
speed up (at least subsequent) build times.

 > Bonus hint: ls doesn't even call open() on the files, it calls stat() 
on the files.
 > Your open() calls are probably for shared libraries or stuff in 
/usr/lib/locale/

Yes, using "ls /" /might not have been /the best initial example, but 
listing the loaded shared libraries is perfectly fine for my purpose of 
dependency recording, because the "results" of running "ls -l" do depend 
on its shared libraries!
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kernelnewbies.org/pipermail/kernelnewbies/attachments/20180214/0fd32234/attachment.html>

ftrace events: parameter tracing

[valdis.kletnieks at vt.edu]

On Wed, 14 Feb 2018 20:26:01 +0100, Christof Warlich said:

> record the build's dependencies. On subsequent runs of the build, these
> depencencies could then be used to decide which compoments must be
> rebuilt due to changed dependencies.

Doesn't "make" already do what you want?

Oh, wait...

> dependency recording, because the "results" of running "ls -l" do depend
> on its shared libraries!

This way lies madness - touch glibc or other package like that, and you just forced
a rebuild of the entire world.  In fact, I suspect that trying to follow "dependencies"
to that level will result in build times close to what a 'make world' would do, because
computing what ends up being the transitive closure of all file references is painful.

Hint:  To really do this correctly, you need to be able to force 100% code path
coverage - otherwise you won't pick up the fact that /usr/lib64/libsnark.so is only
actually used in an error path or similar rare-access corner case.

For bonus points:

openat(AT_FDCWD, "/usr/lib/locale/en_US.UTF-8/LC_MONETARY", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/locale/en_US.utf8/LC_MONETARY", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/usr/lib/locale/en_US.UTF-8/LC_TIME", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/locale/en_US.utf8/LC_TIME", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/usr/lib/locale/en_US.UTF-8/LC_NUMERIC", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/locale/en_US.utf8/LC_NUMERIC", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/usr/lib/locale/en_US.UTF-8/LC_CTYPE", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/locale/en_US.utf8/LC_CTYPE", O_RDONLY|O_CLOEXEC) = 3

Which file(s) count?  How do you test for all values of $LANG and the various LC_*
environment variables?

There's a reason that most sane software builds and tools like rpm / dpkg and
so on just check "glibc is still version 2.22" and don't bother going any
further than that.

And it just gets worse if you include kernel patches - how many modules end up
involved in an open() call on a USB device?  How do you detect that your code
"depends" on a given behavior - often kernel patches address error conditions
that doesn't change the perceived behavior in your userspace program...

... until a rare error condition arises.  At this point, you need 100% code coverage
of both the userspace *and* the kernel.

To quote the movie Animal House: "My advice to you is to start drinking heavily....."

-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 486 bytes
Desc: not available
URL: <http://lists.kernelnewbies.org/pipermail/kernelnewbies/attachments/20180214/1f7deb5d/attachment-0001.sig>

ftrace events: parameter tracing

[Christof Warlich]

Am 14.02.2018 um 20:43 schrieb valdis.kletnieks at vt.edu:

> Doesn't "make" already do what you want?
No, make itself cannot generate dependency lists on its own, it needs 
tooling like gcc -MD ... to do that. I'm interested in a generic 
approach. But it my read and thus obey them.
> Oh, wait...
>
>> dependency recording, because the "results" of running "ls -l" do depend
>> on its shared libraries!
> This way lies madness - touch glibc or other package like that, and you just forced
> a rebuild of the entire world.  In fact, I suspect that trying to follow "dependencies"
> to that level will result in build times close to what a 'make world' would do, because
> computing what ends up being the transitive closure of all file references is painful.
>
> Hint:  To really do this correctly, you need to be able to force 100% code path
> coverage - otherwise you won't pick up the fact that /usr/lib64/libsnark.so is only
> actually used in an error path or similar rare-access corner case.
Well, unwanted dependencies could be excluded by a blacklist, although I 
still believe that at least /_most_/ of the required shared libraries 
should rightfully be kept as dependencies, last but not least because 
libraries are changed occasionally only on a build server, making world 
builds rare as well.
> For bonus points:
>
> openat(AT_FDCWD, "/usr/lib/locale/en_US.UTF-8/LC_MONETARY", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
> openat(AT_FDCWD, "/usr/lib/locale/en_US.utf8/LC_MONETARY", O_RDONLY|O_CLOEXEC) = 3
> openat(AT_FDCWD, "/usr/lib/locale/en_US.UTF-8/LC_TIME", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
> openat(AT_FDCWD, "/usr/lib/locale/en_US.utf8/LC_TIME", O_RDONLY|O_CLOEXEC) = 3
> openat(AT_FDCWD, "/usr/lib/locale/en_US.UTF-8/LC_NUMERIC", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
> openat(AT_FDCWD, "/usr/lib/locale/en_US.utf8/LC_NUMERIC", O_RDONLY|O_CLOEXEC) = 3
> openat(AT_FDCWD, "/usr/lib/locale/en_US.UTF-8/LC_CTYPE", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
> openat(AT_FDCWD, "/usr/lib/locale/en_US.utf8/LC_CTYPE", O_RDONLY|O_CLOEXEC) = 3
>
> Which file(s) count?  How do you test for all values of $LANG and the various LC_*
> environment variables?
>
> There's a reason that most sane software builds and tools like rpm / dpkg and
> so on just check "glibc is still version 2.22" and don't bother going any
> further than that.
>
> And it just gets worse if you include kernel patches - how many modules end up
> involved in an open() call on a USB device?  How do you detect that your code
> "depends" on a given behavior - often kernel patches address error conditions
> that doesn't change the perceived behavior in your userspace program...
>
> ... until a rare error condition arises.  At this point, you need 100% code coverage
> of both the userspace *and* the kernel.
I'm not so sure whether full coverage is really necessary. Instead, the 
depencency record of a full succesful initial build might be sufficient. 
Even considering other influencing things like the environment should be 
possible.
> To quote the movie Animal House: "My advice to you is to start drinking heavily....."
You are most probably right with that, but I'd still like to continue 
pondering ... - as long as there is a way to yield the filename of an 
opened file using (fast) ftrace instead of slow ptrace?

Thus, I'd still be interested in a solution or hint to my initial question.
>
>
> _______________________________________________
> Kernelnewbies mailing list
> Kernelnewbies at kernelnewbies.org
> https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kernelnewbies.org/pipermail/kernelnewbies/attachments/20180214/2999651c/attachment.html>

ftrace events: parameter tracing

[valdis.kletnieks at vt.edu]

On Wed, 14 Feb 2018 19:39:31 +0100, Christof Warlich said:

> program. E.g., recording the the start and the end of any open* system 
> call while running ls /:
>
>     # trace-cmd record --stderr? -e syscalls:sys_enter_open* -e
>     syscalls:sys_exit_open* -c -F ls / 2>/dev/null

Bonus hint:  ls doesn't even call open() on the files, it calls stat() on the files. :)

Your open() calls are probably for shared libraries or stuff in /usr/lib/locale/
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 486 bytes
Desc: not available
URL: <http://lists.kernelnewbies.org/pipermail/kernelnewbies/attachments/20180214/0fb1dcc2/attachment.sig>