fileslower and filetop report TCP instead of file name

[bobrik]

root@myhost:/# /usr/share/bcc/tools/fileslower 1
Tracing sync read/writes slower than 1 ms
TIME(s)  COMM           PID    D BYTES   LAT(ms) FILENAME
0.000    foobarba       25738  R 5         90.12 TCP
0.010    foobarba       25018  R 5         97.56 TCP
0.020    foobarba       24538  R 5         92.43 TCP

I'm running it on 4.4.10.

[brendangregg]

This is because it's tracing at the VFS layer, which catches file read/writes and other read/write types.

This could either be filtered, or, documented. Perhaps the most intuitive option would be to filter by default, unless a verbose option is passed at the command line.

[markdrayton]

I think this could be a consequence of using d_iname for the name lookup in fileslower rather than/as well as catching non file IO.

A few days ago I was investigating a writeback bug that slowed down write syscalls. fileslower showed slow writes for lots of files but it didn't show slow writes to the application log files. This seemed really weird as off-CPU profiling showed the app was clearly blocking on writing its log. Today I dug into what was going on.

I wrote a basic script to trace writes to a given FD for a given process. For these writes I printed de->d_iname as well as de->d_name.name (full code).

Here's the workload generator (write.py):

import tempfile
import time

with tempfile.NamedTemporaryFile(prefix='/tmp/paddingpaddingpaddingpadding') as f:
    while True:
        f.write('test\n')
        f.flush()
        time.sleep(1)

# python write.py &
[1] 1122305

# python print.py 1122305 3
fd: 3, count: 5, iname: TCPv6, name: paddingpaddingpaddingpaddingrGCX
fd: 3, count: 5, iname: TCPv6, name: paddingpaddingpaddingpaddingrGCX
fd: 3, count: 5, iname: TCPv6, name: paddingpaddingpaddingpaddingrGCX

The string in d_iname varies. On our production hosts it's usually TCPv6; on my little-used Ubuntu VM it's the empty string. I'm not really sure why it ends up as this other value — perhaps dentry swapping/copying (see fs/dcache.c)? It seems the right thing to do is use de->d_name.name, since as far as I could tell this is the authoritative source.

This doesn't work, though. I tried updating fileslower like so:

// smaller of the buffer or name length
int len = de->d_name.len < sizeof(val.name) ? de->d_name.len : sizeof(val.name);
bpf_probe_read(&val.name, len, (void *)de->d_name.name);

(full code)

but I get a huge error. Switching for __builtin_memcpy gives a different error (both at https://gist.github.com/markdrayton/d6c9af87125eca7e32e540aadef654bc).

@4ast, @drzaeus77 any suggestions for making this work? #188 looks a bit related but I'm not sure if it's the same underlying cause.

[markdrayton]

Looking at @bobrik's example the slow writes are only 5 bytes so it seems more likely these are legit TCP sockets. Either way, I think #677 improves the fetching of names and filtering of non-regular files. @bobrik, please give it a try if you can.

[brendangregg]

I believe this was fixed by recent commits. Closing ticket.