RFC: DTrace probes for debugging or testing in userland programs

[Hiroki Sato]

Hi,

I am trying to rewrite userland programs (especially daemons) to
support userland DTrace probes to make it possible to trace the
behavior by using dtrace(1). The purpose is to provide a consistent
interface to enable/collect debug log and show internal states. A
lot of daemons define their own debug output function like dprintf()
and there is no consistency of where to be recorded.

I would like your comment about this change because I want to know
whether this change (or direction) is acceptable or not. I put an
example by using syslogd at the following URL:

(diff)
https://people.freebsd.org/~hrs/syslogd_usdt.20161220-1.diff
(tarball)
https://people.freebsd.org/~hrs/syslogd_usdt.20161220-1.tar.gz

You can try to compile a new syslogd, run it, and then attach
dtrace(1) to the syslogd process by "dtrace -q -CI./
-s ./syslogd_trace.d -p `pgrep syslogd`" in the same directory.

Basically this change is invisible for normal users. This includes
some rough edges but I think it is sufficient to understand the
concept. I do not intend to commit this soon.

Questions from me are the following:

1. Where should foo_probes.d and foo_trace.d be installed? And if
they depend on foo.h, where should foo.h be?

2. Is documenting probes into foo.8 reasonable?

The details are as follows.

* Rewrite example

This rewrite is twofold. First, simply replace a call of the
logging function into DTrace USDT like this:

(old) | dprintf("an error occurred, errno=%d\n", errno);

(new) | FOO_LOG(LOG_ERR, "an error occurred, errno=%d\n", errno);

And then if it involves a result of a specific operation, replace
trace probes for the simple logging with dedicated ones:

(old) | error = bind(s, res->ai_addr, res->ar_addrlen);
| if (error) {
| dprintf("bind failed, errno=%d\n", errno);
| close(s);
| return (-1);
| }

(new)
| error = bind(s, res->ai_addr, res->ar_addrlen);
| if (error) {
| FOO_SOCK_BIND_FAILED(errno, s, res->ai_addr, res->ar_addrlen);
| close(s);
| return (-1);
| }
| FOO_SOCK_BIND_SUCCESS(s, res->ai_addr, res->ar_addrlen);

and implement the functionality of the original log message in D
script:

| foo$target:::sock-bind-failed
| {
| printf("bind failed, errno=%d", arg0);
| /* The other argN can be used to report in more detail. */
| }

* Additional files in the existing directory layout

After this rewrite, the directory layout for a daemon "foo" will look
like the following:

| Makefile
| foo.8
| foo.c
| foo.h
| foo_probes.d
| foo_trace.d

foo_probes.d and foo_trace.d are added. The former is the
definition of USDT probes, and the latter is a D script example to
reproduce the original debug log by dprintf() or something like
that. A section to describe what probes are available is added into
foo.8. One can trace the foo daemon using "dtrace -Cs foo_trace.d -p
`pgrep foo`" on runtime, and also can create own script.

foo.h may be added because foo_probes.d and foo_trace.d often require
information of data structure used in foo.c.

* Possible incompatible change

A debug flag to activate additional logging is no longer necessary
after this rewrite, so we can remove it (-d flag in the case of
syslogd). And dump of the internal state can be implemented as a
SIGINFO handler. In the syslogd example, SIGINFO dumps syslogd
configuration and access control list.

-- Hiroki

[Adrian Chadd]

Hi,

I'd love to see a unified-ish logging API for FreeBSD applications. I
always end up reusing some C code I have here that I based on some
Squid style logging API in ages past. I could always polish it up and
put it up for review.

I'm not a big fan of requiring dtrace to use it though. On a lot of
the embedded systems dtrace varies from "it's very big" through to "we
don't have enough RAM/flash to do this".

So although I like the sentiment, I don't think using dtrace for
program logging is the right answer. I like what apple did to wrap
the program logging stuff so people didn't just write their own
libraries (hi!) and so there's a unified-ish way to interact with
apple programs. I think we could do with that.

Thanks,



-adrian

[Domagoj Stolfa]

Hello,

No. A single dtrace process can catch
fired probes of multiple processes if you want.
Filtering probes or the results from probes
is things which should be done in the
D script level, not in the target binary,
in the case of DTrace. My proposal does
not cover how to use the probes. It just
provides probes and a sample script to
reproduce the (almost) same results with
printf() debug logging. The big difference
is that a developer can use these probes
for a more complex debug script and/or
regression test script because the
probes can carry data structures in
question, not just a string.

I suppose this comes down to a way that you want to implement this.
Using the SDT provider would require you to attach to the probes using a
D script to perform simple logging, and additional scripts in order to
do more complex operations(such as quantize certain arguments that
you're getting in during that log and what not).

Eventhough your original proposal doesn't cover using those probes, I'm
still puzzled as to how you would actually attach to the probes, i.e.
would you have a script for each daemon separately or would you create 1
big script, causing it to attach to all the probes created in the
separate daemons? There doesn't seem to be a way around having atleast
one script in order to make the probes actually fire(that is, call
dtrace_probe()). This is one of the reasons why I've argued for a
different provider as opposed to SDT.

Another thing that could perhaps be done is implement the probes in the
daemons and simply attach to them whenever the user needs to attach
while leaving the actual logging functionality as is. That way the SDT
provider would dynamically link the function call into the daemon
whenever one would want to trace for more complex logging(there could be
example scripts). The arguments could be documented, allowing for an
easy way to write the scripts and have context of what the arguments
are.

In any case, I would very much like to have access to SDT probes in
daemons in order to get full disclosure on what's happening in real
time, instead of getting a pre-defined log that I would have to
post-process, and would like to thank you for your efforts in doing
this.

[Adrian Chadd]

*mumble* damnit jordan this requires libdispatch *mumble*



-a

[Domagoj Stolfa]

Hello,

Post by Hiroki Sato
You can try to compile a new syslogd, run it, and then attach
dtrace(1) to the syslogd process by "dtrace -q -CI./
-s ./syslogd_trace.d -p `pgrep syslogd`" in the same directory.

one thing that comes to mind is the lack of a way to actually fire these
probes without running plenty of DTrace scripts. The SDT provider
dynamically links onto the binary using the linker set, so that probes
can be called. This is accomplished using the DTrace command that you've
issued, would we need to issue one for each daemon that operates in such
a way?

Post by Hiroki Sato
1. Where should foo_probes.d and foo_trace.d be installed? And if
they depend on foo.h, where should foo.h be?
2. Is documenting probes into foo.8 reasonable?

This would again depend on the way that they're implemented. If USDTs
are used, documenting them might be beneficial, as the user might at one
point want to turn them off dynamically or write their own script.

Post by Hiroki Sato
foo_probes.d and foo_trace.d are added. The former is the
definition of USDT probes, and the latter is a D script example to
reproduce the original debug log by dprintf() or something like
that. A section to describe what probes are available is added into
foo.8. One can trace the foo daemon using "dtrace -Cs foo_trace.d -p
`pgrep foo`" on runtime, and also can create own script.
foo.h may be added because foo_probes.d and foo_trace.d often require
information of data structure used in foo.c.
* Possible incompatible change
A debug flag to activate additional logging is no longer necessary
after this rewrite, so we can remove it (-d flag in the case of
syslogd). And dump of the internal state can be implemented as a
SIGINFO handler. In the syslogd example, SIGINFO dumps syslogd
configuration and access control list.

One thing that could be done as well is instead of using the SDT
provider, a new provider could be written, which could in turn be
controlled by the additional flags, or pehaps even a sysctl integer that
would specify the level of logging that one would want. This provider
could also be entirely disabled, causing it to disable all the existing
probes and, similarly to SDT, use the linker set to patch a couple of
nops back in.

The user could also attach to this provider with their own scripts,
should they wish to perform some other form of monitoring as well.

This might be redundant with the SDT provider though, so perhaps a more
generic, backwards-compatible way can be thought of that would allow
this sort of behaviour?