LWN.net Logo

Announcing a new utility: 'trace'

Announcing a new utility: 'trace'

Posted Nov 16, 2010 22:29 UTC (Tue) by nix (subscriber, #2304)
Parent article: Announcing a new utility: 'trace'

- Arguments are printed in plain hex representation, except for important arguments like filenames, which are resolved after the syscall is recorded. 'trace' wont do full decoding like strace does.
If 'wont' meant 'is not implemented yet', this is fine and indeed expected. If 'wont' means 'will never be implemented', then it is nearly useless for virtually every application I can imagine using strace for. Sorry, arguments matter, and not just filenames. strace is already annoying because there are some arguments (notably structure pointers) it can't drill down into: eliminating even more of them just makes the tool next to useless for diagnostics (at least for any of the diagnostics I, as a userspace programmer and sysadmin, carry out day-to-day).


(Log in to post comments)

Announcing a new utility: 'trace'

Posted Nov 16, 2010 22:41 UTC (Tue) by mingo (subscriber, #31122) [Link]

Could you list a few everyday examples of strace argument decoding that you find the most useful?

Thanks,

Ingo

Announcing a new utility: 'trace'

Posted Nov 16, 2010 22:50 UTC (Tue) by walters (subscriber, #7396) [Link]

I haven't actually tried trace yet (it sounds awesome though). One thing that comes to mind that I looked at recently with strace is the arguments to poll().

Announcing a new utility: 'trace'

Posted Nov 16, 2010 23:02 UTC (Tue) by foom (subscriber, #14868) [Link]

Let's take some of your example output:
firefox/28132 ( 0.010 ms): mmap(addr: 0x0, len: 0x1000, prot: 0x3, flags: 0x22, fd:
0xffffffff, off: 0x0) => 0x7fb3f442c000
( 0.001 ms): rt_sigaction(sig: 0x14, act: 0x7fffcc4caa80, oact: 0x7fffcc4ca9e0, sigsetsize: 0x8)
=> 0x0

That tells me almost nothing.

Compare that to strace's:

mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb3f442c000
rt_sigaction(SIGTSTP, {SIG_IGN}, {SIG_DFL}, 8) = 0

Sorry, strace wins by a landslide. Decoding the flags to symbolic names is hugely useful. Decoding the struct sigaction is even more useful (since I can't even do that manually by grepping include files -- you've just given me a random pointer, completely useless).

Argument names, not so useful: that's basically just noise. I know the API of mmap, but I sure as heck don't know what the flags' raw integer values are!

Announcing a new utility: 'trace'

Posted Nov 16, 2010 23:22 UTC (Tue) by tglx (subscriber, #31301) [Link]

We know that and for one this can be improved, but OTOH our main objective at the moment was to provide features which are not in strace (and never will be): The analysis of blocking events, pagefaults etc.

This is just the rough start of this tool and we are happy to listen to your feedback!

Thanks,

tglx

Announcing a new utility: 'trace'

Posted Nov 16, 2010 23:48 UTC (Tue) by foom (subscriber, #14868) [Link]

If there's no technical or philosophical impediment to their reimplementation in the future: Awesome!

I'm certainly looking forward to all those other features -- they are sorely needed, and it makes total sense to work on the unique features first. Indeed I've been wishing for a tool which would easily tell me what pages I'm faulting in (and in what order) out of a 5GB mmaped file, in order to help debug performance issues with disk seeks when the file is totally paged out.

I just hope that in time, the existing featureset of strace can also be supported, so that we don't end up with two half-useful tools instead of one awesome tool.

Announcing a new utility: 'trace'

Posted Nov 17, 2010 12:17 UTC (Wed) by nix (subscriber, #2304) [Link]

Strongly agreed. strace *is* a crufty old goat that would be nice to replace, and anything that can put ptrace() uses to death is a good thing in my eyes. But we do need argument decoding if we're to use it to figure out what on earth a program is up to, which is, y'know, the point of it. AIX has a syscall trace program that doesn't do any argument decoding (even of strings!), and it's main use is as a source of frustration (though of course it doesn't do any of the other things trace does either). Kicking up the debugger is often easier, even without debugging information.

(I know that argument decoding is really boring to get right and tends to involve giant tables of syscalls so needs active maintenance, but unfortunately it's also hard to avoid for a useful tool. But, hey, if you don't actually object to it so it might turn up later, that's fine: we know there's nothing in the implementation that makes it harder for trace than it is for strace. At least you don't need to worry too much about putting new syscalls in fast: the new syscalls will be relatively unused for a long time, so you don't need to rush to add them to the syscall table in the tracing tool.)

Announcing a new utility: 'trace'

Posted Nov 26, 2010 2:33 UTC (Fri) by kabloom (guest, #59417) [Link]

Hey! Since `trace' lives in the kernel tree, this means that all of the syscall decoding code will ALSO live in the kernel tree, and that whoever writes a new syscall can be asked to provide the decoder at the same time.

Announcing a new utility: 'trace'

Posted Nov 20, 2010 17:01 UTC (Sat) by kleptog (subscriber, #1183) [Link]

Anything that brings something like strace but better is good. However, if you do decide to do argument decoding I strongly suggest looking at the source for strace. It contains scripts for dozens of OSes and architechtures for extracting syscall, ioctl and signal information. Along with code to print it out.

It's probably a good idea to at least glance at it once in a while to make sure the impedance mismatch doesn't get too great, so that when you do want it it won't be much work.

(The PORTING document of strace suggests that you should be able to create a new event loop and you'll have a basic working version pretty quick.)

Announcing a new utility: 'trace'

Posted Nov 16, 2010 23:27 UTC (Tue) by marineam (subscriber, #28387) [Link]

The argument names could be useful, just as the name/pid (timing) prefix could be useful. Both could be optional. One thing that I really like about strace is that it defaults to being pretty terse. Pids are only included if tracing children is enabled, timing information is a whole set of options depending on what type of timing you need, etc. That way the simple case of just seeing what system calls are bing made isn't clouded by extra information. (Am I in the event loop or stuck on a futex?)

Announcing a new utility: 'trace'

Posted Nov 17, 2010 9:45 UTC (Wed) by rvfh (subscriber, #31018) [Link]

> firefox/28132 ( 0.010 ms): mmap(addr: 0x0, len: 0x1000, prot: 0x3, flags: 0x22, fd: 0xffffffff, off: 0x0) => 0x7fb3f442c000

> mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb3f442c000 rt_sigaction(SIGTSTP, {SIG_IGN}, {SIG_DFL}, 8) = 0

Looks better in trace to me!
addr: 0x0 <=> NULL
len: 0x1000 <=> 4096 (which is 0x1000 in hex)
You can decode the protocol/flags given the value (I know it's more effort), and 0xffffffff is -1

Announcing a new utility: 'trace'

Posted Nov 17, 2010 15:01 UTC (Wed) by mpr22 (subscriber, #60784) [Link]

You can decode the protocol/flags given the value (I know it's more effort)

It's not just more effort, it's something the machine can do better than me.

Announcing a new utility: 'trace'

Posted Nov 17, 2010 10:10 UTC (Wed) by renox (subscriber, #23785) [Link]

I disagree with your comment about the argument names which are very useful IMHO:
1) if you have an unfamiliar function, the argument names (if well chosen) can help a lot grasp what the function does.
2) if you're debugging, it helps catching a very common programming mistake: putting the argument in the wrong order (which is only caught by the compiler when the arguments types are incompatible).

Announcing a new utility: 'trace'

Posted Nov 16, 2010 23:06 UTC (Tue) by marineam (subscriber, #28387) [Link]

In my usage often the important strings other than filenames that I look at frequently in strace are the arguments to execve() and read()/write() so I can narrow down my debugging to things like "Ok, I see that it is receiving all of the data correctly but it somehow truncated it before calling xyz"

The vast majority of the strings aren't important but that one time an important string isn't decoded it is annoying and slightly time consuming to switch to a more complex tool such as gdb to answer the otherwise 3 second question of "that data is good/bad." (I can't remember what syscall it was that I hit this with strace any more but the data wasn't in a struct and yet it didn't know it could decode it.)

Decoding strings by default does add noise but strace's default of truncating after 32 characters seems to be a reasonable compromise.

Announcing a new utility: 'trace'

Posted Nov 16, 2010 23:27 UTC (Tue) by ajross (subscriber, #4563) [Link]

Symbolic ioctl names are a big one for me. These are often infuriatingly hard to grep out of headers.

Announcing a new utility: 'trace'

Posted Nov 17, 2010 14:20 UTC (Wed) by madcoder (subscriber, #30027) [Link]

Well, I will repeat some of what nix said, but here is what is tremendously useful to me in strace that trace doesn't provide:

* flags demangling (see the mmap example);
* pretty-printing of the standard types, see various strace examples:
rt_sigaction(SIGRTMIN, {0x7fe36e983860, [], SA_RESTORER|SA_SIGINFO, 0x7fe36e98cf60}, NULL, 8) = 0
stat("/usr/bin/test", {st_mode=S_IFREG|0755, st_size=30136, ...}) = 0
* see through buffers (strace -s) for reads and writes (it's *VERY* useful to detect off-by-ones in read(v)s/write(v)s/{send,recv}{,msg} and so forth (I've used it numerous times);
* CMSG decoding (for example for the SCM_CREDENTIALS or SCM_RIGHTS stuff for unix sockets).

Argument names are good though, and useful for the reader for less used functions (or raw kernel syscalls that the libc usually wraps in more known interfaces e.g.).

I know "trace" can do stuff that strace doesn't like reporting what was slow, filter the trace for many things. But it cannot claim to replace strace until it can do that. Strace is (for me) more used for debugging purposes (What does my $KJASD*(*@!#*&!@ program is doing with the syscalls because I'm too dumb to understand what is happening by reading the code) than for performance reasons (even if did use it one or twice to do that with post-filtering of strace -tt output, clearly painful and here "trace" is a clear winner).

Right now trace is a *very interesting* performance oriented trace tool, on the way to take some "market share" to strace, but it's not a drop in replacement by far.

Announcing a new utility: 'trace'

Posted Nov 17, 2010 15:22 UTC (Wed) by cventers (subscriber, #31465) [Link]

I use strace to debug one of my Perl par build processes. The PAR archive support included in the Perl Catalyst web framework's make has a nasty habit of shutting down stderr somewhere in the chain, and so build failures often result in a generic make error.

In those cases I pass -f, -s 50000 and -e trace=read,write and I can see what went wrong.

handy structure/array pretty-printing in strace

Posted Nov 17, 2010 23:13 UTC (Wed) by pbonzini (subscriber, #60935) [Link]

select/poll arguments are quite handy, and so are socket addresses so that you can understand which socket is yours and which are created by the resolver. sigaction also comes to mind.

handy structure/array pretty-printing in strace

Posted Nov 19, 2010 17:11 UTC (Fri) by adamgundy (subscriber, #5418) [Link]

seems like a good case for ripping out the strace syscall decoding logic into a separate library that both projects can share...

Copyright © 2013, Eklektix, Inc.
Comments and public postings are copyrighted by their creators.
Linux is a registered trademark of Linus Torvalds