tracing and profiling interface and basic backends

[trws]

note: this is a sanitized branch, commit cleanup is the main difference

This is a very rough cut on tracing for flux. If TAU_PROFILING is
enabled, it turns on some macros that will register flux event
processing with TAU. Getting flux to build, link, and run with TAU is
another matter entirely. I recommend building your own TAU with only
pthread support, then specifying tau_cc.sh as the compiler with only
the options to use shared linking and track pthreads while only
affecting linking. Then when running preload the pthread indirection
library (this should not be necessary, but it is).

Alternately, there is a caliper backend to the basic macros as well,
which can be turned on with the --with-caliper option on configure.
One still has to have caliper available in appropriate paths, but it's
much easier to get started with this. Unfortunately the data is rather
harder to wrangle from this right now.

Either way, the main point of this is to serve as a starting point for
tracing/profiling in flux rather than a full setup.

[lipari]

Did you withhold the src/common/libutil/profiling.[ch] files for some reason?

[trws]

Thanks for the heads up don. Rebase was giving me fits and something must have gone wrong. I'll add them back in shortly.

---

From: Don Lipari
Sent: Wednesday, May 11, 2016 7:41:31 AM
To: flux-framework/flux-core
Cc: Scogland, Tom; Author
Subject: Re: [flux-framework/flux-core] tracing and profiling interface and basic backends (#672)

Did you withhold the src/common/libutil/profiling.[ch] files for some reason?

—
You are receiving this because you authored the thread.
Reply to this email directly or view it on GitHubhttps://github.com//pull/672#issuecomment-218480557

[trws]

@lipari: the files are in now. I'm re-working how exactly caliper records information so it's a bit easier to parse, but the interface is unlikely to shift much.

One heads up though, don't compile the caliper library and flux with one of the dotkit gccs and try to use it on hype, the compute nodes don't have the appropriate libstdc++, so you'll get cryptic link errors... @dongahn, is there someone to report this kind of thing to? I keep ending up fighting our compilers all over the place.

[coveralls]

Coverage increased (+0.1%) to 74.478% when pulling 7185488 on trws:tau-tracing into 39f2ccf on flux-framework:master.

[dongahn]

@trws: I would start from John Gyllenhaal.

[trws]

@garlick, @grondo: This has had all TAU foolishness removed, been cleaned up somewhat, and rebased to current master. There is something causing an event to be recorded multiple times, but it appears to be a caliper bug that I'm following up on (and it's easy to filter off events that have identical record, times, etc.).

Currently it tracks the rank, thread id, thread type (main or module thread), module name if present, message type and message topic for handle callbacks, and times all such message handlers. If you want to give it a try, just use --enable-caliper and give the library and include paths for a copy of caliper, then run flux with CALI_CONFIG_PROFILE=thread-trace set. There are a variety of extra options available through environment variables for caliper, but that will give pretty decent output.

The one other noticeable downside right now, that I would love some thoughts on if something comes to mind, is that flux/wreck processes under the brokers end up emitting profiles as well. I haven't found a good way to turn off caliper at that boundary yet, but it should be reasonably possible with some environment filtering or similar.

[coveralls]

Coverage decreased (-0.003%) to 75.018% when pulling 06110ff on trws:tau-tracing into d2c9b48 on flux-framework:master.

[garlick]

Great, thanks!

It's easier to grok this PR as a single diff - might want to squash it down, and if there's any detritus remaining from tau (xmalloc? static htab decl. in wrexec), drop it.

Is the global state essential to communicating with caliper, or could it be moved to struct dispatch or maybe assigned to the flux_t handle with flux_aux_set()?

If we're making caliper the "native" trace format, can the indirection through profiling.h be dropped?

I will get caliper built and play with it a bit and probably then all will become clear. Thanks again for getting this all going.

[garlick]

Is there a reason both --with-caliper and --enable-caliper are in configure.ac?

[trws]

Completely agree @garlick, I have every intention of squashing it before merge, but there are some things from the history that I may want to put in a future PR ( I had part of a compiler auto-instrument hook in there ) to pull out first.

The global state can be somewhere else, but all they are is named event types. They should be common to the whole process, and there should only ever be one copy of those variables. I have no issue with moving them if you prefer, but there should never be more than one of each (or we may get multiple attributes with the same name and type, which would be confusing).

I can certainly remove the header, but I wasn't sure whether to do it or not. The header allows the common calls to be compiled out without too many guards, but it's no more than a convenience.

If they're both still there, it's by mistake, the --enable-caliper version is the real one.

Clearly this need further cleanup, so I'll get to that shortly and post an update.

[garlick]

No rush! I've got caliper built on my desktop and I'll figure out how to get some trace output tomorrow.

[grondo]

The one other noticeable downside right now, that I would love some thoughts on if something comes to mind, is that flux/wreck processes under the brokers end up emitting profiles as well. I haven't found a good way to turn off caliper at that boundary yet, but it should be reasonably possible with some environment filtering or similar.

If you unset caliper environment variables in the initial program shell does that fix a large part of the problem? For wrexecd or other flux components directly forked from the broker we will have to filter the environment as you say, or do we want to go ahead and keep the caliper data for these processes?

[grondo]

One more (probably very naive) question. In @tpatki's work with tracing in the scheduler we had the idea to start tracing with an event or other request, allowing tracing to be started/stopped dynamically. Would this ever be possible with caliper? (Doesn't need to be now, but dynamic tracing would be extremely handy in the future)

[trws]

Unsettling the end really doesn't do it because of they way the wreck processes are forked. This might be part of choosing when we do and don't want tracing to happen. It's definitely possible to do targeted tracing with caliper, but I haven't worked out the best way to manage that yet. It has built in support for some kinds of filtering and white/blacklisting, but we probably want our own event classes or regions to make that reasonably usable.

---

From: Mark Grondona
Sent: Tuesday, June 14, 2016 6:52:48 AM
To: flux-framework/flux-core
Cc: Scogland, Tom; Mention
Subject: Re: [flux-framework/flux-core] tracing and profiling interface and basic backends (#672)

One more (probably very naive) question. In @tpatkihttps://github.com/tpatki's work with tracing in the scheduler we had the idea to start tracing with an event or other request, allowing tracing to be started/stopped dynamically. Would this ever be possible with caliper? (Doesn't need to be now, but dynamic tracing would be extremely handy in the future)

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHubhttps://github.com//pull/672#issuecomment-225887451, or mute the threadhttps://github.com/notifications/unsubscribe/AAoStZYt_idwr2PMQ3OcbWLCFq5Lr6ABks5qLrIwgaJpZM4IbtwD.

[grondo]

Unsettling the end really doesn't do it because of they way the wreck processes are forked.

Sorry I'm being dense but I don't follow that, I'm not sure of how wreck processes are forked in any special way, but this would be easy to change if it helps here, and is good feedback for the replacement.

It's definitely possible to do targeted tracing with caliper, but I haven't worked out the best way to manage that yet. It has built in support for some kinds of filtering and white/blacklisting, but we probably want our own event classes or regions to make that reasonably usable.

Yeah, I was thinking the same thing, if we had our own filters, possibly dynamic like linux ftrace, that would be extremely handy. However, I looked at how ftrace accomplishes near zero overhead when tracing is disabled and it is suitably tricky that I don't think it is something we'd attempt.

I was hoping we'd be able to hide any complexity behind a flux trace command, but that might be well down the road...

[grondo]

I have every intention of squashing it before merge, but there are some things from the history that I may want to put in a future PR ( I had part of a compiler auto-instrument hook in there ) to pull out first.

You could push a copy of this branch first

git push origin tau-tracing:tau-tracing-saved

Then go ahead and modify the PR branch as needed and tau-tracing-saved will always be available with your old commits.

[garlick]

Incidentally, d193241 is a simplified version of your pr

• rebased on master
• dropped profiler.h
• moved cali_id_t's to struct dispatch (according to docs cali_create_attribute() can be called multiple times and only one actual attribute will be created so pthread_once is maybe not needed?)
• dropped xrealloc change
• dropped lua debugging
• dropped wrexecd htab static

Didn't mean to gut your abstractions but I found this a bit easier to map directly to the caliper documentation for starting out. Feel free to ignore.

[garlick]

I didn't get very far yesterday with some interruptions, but did have this thought (and started writing some code for it though not there yet): it seems that caliper gets initialized and produces a zero length output file for an executable linked to it, even if no caliper calls are made. To get control of this, it seems like caliper should only be linked to executables that require tracing, for starters the broker.

To get trace calls added to the dispatcher without linking caliper to libflux.so, perhaps we could implement a trace registration interface that registers begin/end callbacks for specific topic strings or fstruct flux_match specs? Then the callbacks (back in the broker, say) would be the only bits required to link with caliper.

Any feelings about this approach? Can we come up with a generic flux_trace_f callback signature that could work for begin/end callbacks in the different subsystems that we might like to trace? I was thinking something as simple as this could work:

typedef void (*flux_trace_f)(const char *name, void *arg);

(In the dispatcher I would construct name to be message-type:topic-string.

[grondo]

Could we also push a patch to caliper that opens output files dynamically, and only when there is data to write?

I like your callback idea. I'd really like to see the ability to have tracing enabled by default in the build with a flux trace frontend to enable/disable it at runtime, with message and function matching as you describe. Compile time tracing is useful, but runtime tracing will be very very useful, IMO.

However, if I'm the only one asking for this feel free to ignore me.

[trws]

@grondo, as to the patch, it wouldn't be a bad thing to have a caliper plugin that does something more sensible for flux in general for sure.

The specific avoid opening until there's output patch that is something I imagine @daboehme would take if someone wants to make the adjustment.

As to using callbacks for tracing, I'm generally for having some of those mechanisms, especially since that's how compiler-instrumentation works at runtime it's good to have a way to tie into that. That said, it means we have to build rather more on a per-trace-target basis than we would otherwise, and every call into it will be a bit more expensive.

Either way, having a way to filter what does and doesn't get logged is going to be important, so the code for selecting a pattern or set of specs would be useful regardless. I have an appointment set up with @daboehme to talk about how to use caliper with flux, and how to use the built-in filtering stuff, this Friday if anyone is interested in joining in. I want to have a better handle on that before building too much abstraction that might be duplicative. Speaking of, I think you're right @garlick that it's best to drop the profiling.h header, at least until we have a generic interface or something we want to use, with TAU gone there's no reason for it, so I'll probably merge your commit and add some of the adjustments I've been working on to that.

[garlick]

I'm going to be away this afternoon, so in case it's useful, my cruedly formed dispatch hook is working and available on my caliper branch here, specifically

88df4dd broker: call dispatch trace hooks
59355e9 libflux/dispatch: add trace hooks to dispatch

[garlick]

Just a clarification: I think we get empty caliper logs only if we set the CALI_CONFIG_PROFILE environment variable. If that's set (e.g. inherited by wrexecd) then we get a log file per process.

That seemed odd to me because wrexecd didn't call cali_* at all internally, but I could see the argument for it: if you enable tracing and none of the trace points happen to be executed, that's a valid trace result. So maybe not a bug?

[grondo]

That seems more reasonable to me.

[garlick]

dlopening libcaliper might be a way to enable Flux to be built with tracing that is enabled at runtime, and to avoiding getting trace files where they are not wanted. There is not much in the C API to make accessing it via dlsym super incovenient.

[tpatki]

Should I move the flux-sched tracing to caliper as well? @dongahn wanted a simpler tracing mechanism (what I was working on earlier) but caliper was Martin/my original suggestion too. What do you all think?

[lipari]

Should I move the flux-sched tracing to caliper as well?

Sounds good to me.

[grondo]

I like @garlick's idea -- it would be interesting to see if there is a measurable performance overhead using this approach. @tpatki, it would be cool if sched tracing uses a similar scheme @garlick is working toward, then all flux tracing would come out in a similar format to the same files. That would be cool.

We still might want some scheme for filtering which tracepoints get enabled

[garlick]

Should I move the flux-sched tracing to caliper as well?

Well, I think we are headed towards a generic trace framework provided by core, but it wouldn't hurt for you to switch over to caliper if you don't mind switching again once we have sorted out the generic hooks.

At least that's what I was thinking. @trws should chime in with hits thoughts - I hope he doesn't feel I've hijacked his PR :-)

[trws]

@daboehme, I've put in some time looking for the invalid node record issue. It's definitely related to using the C interface snapshot function, in that I get one invalid node record for each element I place in the snapshot, once per run. The data being snapshotted appears to be correct, but I still get the invalid node with no data and a UINT64_MAX attr. Any thoughts?

[coveralls]

Coverage decreased (-0.08%) to 74.934% when pulling baffbb0 on trws:tau-tracing into fd8723b on flux-framework:master.

[trws]

Ok, I think this last push addresses the remaining issues. The invalid nodes were being created because the profiling call was being invoked inside of connector_init by messaging happening after it initialized its part of the handle but before letting the handle finish initializing itself. Also rebased and squashed down.

Review @garlick, @grondo?

[coveralls]

Coverage decreased (-0.05%) to 74.966% when pulling f977ec8 on trws:tau-tracing into fd8723b on flux-framework:master.

[grondo]

Thanks! I'll take a look asap, hopefully by early tomorrow.

[grondo]

@trws, I sanity checked this PR and it all looks pretty good!

Some minor comments:

1. Did you address the second of @garlick's comments above?

   (as discussed in Flux meeting) centralize the caliper build options (append to LIBS, and whatever CPPFLAGS variable is appropriate?)

2. Probably want to remove wording the commit message that references prior versions of the PR that won't exist in permanent git history. Possibly rewrite commit message explaining just what is in the commit?

3. One of the t2000-wreck.t tests fail without setting CALI_LOG_VERBOSITY=0 (due to the unexpected CALIPER messages on stderr). This isn't a critical thing to get fixed, but I wonder if @daboehme would consider making 0 the default log verbosity, or we could simulate that in flux by something like if (!getenv ("CALI_LOG_VERBOSITY")) setenv ("CALI_LOG_VERBOSITY", "0", 0) before the first Caliper call. (Unless caliper is initialized in a library constructor?)

[trws]

I did, or at least thought I did, address @garlick's comment about the flags, and rewording the commit message is no problem. As to the logging, there's actually a bit of a choice there. I can actually build flux so that it builds against the stubs library, then use LD_PRELOAD to load in caliper when we actually want results. Alternately, we can control the logging and other things, but having it use the stubs by default should fix all of the testing issues, and make a build with caliper built in run faster when caliper's real implementation isn't loaded. What do you think would make more sense there? Either is equally easy honestly.

[grondo]

Ok, thanks, sorry I missed your changes related to @garlick's comment!

For the Caliper logging issue, I guess it is a matter of taste, but my personal preference is that libraries do not log to stderr by default for informational messages like "hello" and "goodbye" ;-)

Even when I'm using Caliper purposely to trace a 100 broker job, I'm probably not going to want to see 100 "Initialized" messages on stderr I guess is my point.

The dlopen idea sounds great to me! Perhaps as a follow on to this PR? If you fix up the commit message I'd be willing to merge this PR as is so that you aren't required to continually rebase on master (and it will be nice to have some kind of canned tracing support in the next flux-core tag)

Thanks!

[coveralls]

Coverage decreased (-0.07%) to 74.946% when pulling 6e6af1f on trws:tau-tracing into fd8723b on flux-framework:master.

[trws]

I completely agree with that sentiment for what it's worth... @daboehme, any chance of a default change on that at some point? For now, we can manipulate the environment variables or something, but for a library we want to keep loaded I'm not sure it's a good thing.

Let me take a minute to see if I can do the switch to stubs easily, failing that we'll make that part of another pr.

[coveralls]

Coverage decreased (-0.06%) to 74.954% when pulling 1d0ac9b on trws:tau-tracing into fd8723b on flux-framework:master.

[coveralls]

Coverage decreased (-0.08%) to 74.934% when pulling 039e5b2 on trws:tau-tracing into fd8723b on flux-framework:master.

[grondo]

I poked at this Friday and over the weekend a bit. The stubs seem to work fine, but I do have to make the following change to ./configure.ac to build with libcaliper-stubs installed in a non-standard location:
(missing caliper arg to pkg-config)

--- a/configure.ac
+++ b/configure.ac
@@ -124,7 +124,8 @@ AC_ARG_ENABLE(caliper,
 if test "$enable_caliper" = "yes"; then
     PKG_CHECK_MODULES([CALIPER], [caliper], [], [])
     CFLAGS="${CFLAGS} ${CALIPER_CFLAGS} "
-    LIBS="${LIBS} $(pkg-config --libs-only-L ) -lcaliper-stub -lrt "
+    # Do not use CALIPER_LIBS, only link to libcaliper-stub
+    LIBS="${LIBS} $(pkg-config --libs-only-L caliper) -lcaliper-stub -lrt "
     AC_DEFINE([HAVE_CALIPER], [1], [Define if you have libcaliper])
 fi

was also thinking, would it be a total kludge to add a --profile option to flux-start that sets LD_PRELOAD=libcaliper.so?

Alternately, if we pull in the stubs library ourselves, we could perhaps redirect symbols at runtime with dlopen() instead of preloading them, and allow tracing to be enabled and eventually disabled at runtime? (I'm not sure of the performance impact, however, and this could be future work)

[garlick]

would it be a total kludge to add a --profile option to flux-start

I wouldn't object to that.

[grondo]

Something like the below seems to work -- the option only appears if flux-core is built with --enable-caliper -- An alternative would be to always build with the option, but return an error if the option is used when built without caliper support.

We could also set some other CALIPER_* environment variables under --profile (without overwrite of course), but I don't know of a reasonable default -- or perhaps the Caliper configuration profile could be given on the cmdline, e.g. --profile=thread-trace?

Hmm, maybe --profile should be named --caliper-profile

diff --git a/src/cmd/flux-start.c b/src/cmd/flux-start.c
index c40d46f..fa3a755 100644
--- a/src/cmd/flux-start.c
+++ b/src/cmd/flux-start.c
@@ -96,6 +96,10 @@ static struct optparse_option opts[] = {
       .usage = "Add comma-separated broker options, e.g. \"-o,-q\"", },
     { .name = "killer-timeout",.key = 'k', .has_arg = 1, .arginfo = "SECONDS",
       .usage = "After a broker exits, kill other brokers after SECONDS", },
+#if HAVE_CALIPER
+    { .name = "profile",.key = 'P', .has_arg = 0,
+      .usage = "Run brokers with Caliper profiling enabled", },
+#endif
     OPTPARSE_TABLE_END,
 };

@@ -387,6 +391,22 @@ struct client *client_create (struct context *ctx, int rank
     subprocess_setenvf (cli->p, "PMI_FD", 1, "%d", client_fd);
     subprocess_setenvf (cli->p, "PMI_RANK", 1, "%d", rank);
     subprocess_setenvf (cli->p, "PMI_SIZE", 1, "%d", ctx->size);
+
+#if HAVE_CALIPER
+    /*
+     *  If --profile was used, set or append libcaliper.so in LD_PRELOAD
+     *   to subprocess environment, swapping stub symbols for the actual
+     *   libcaliper symbols.
+     */
+    if (optparse_hasopt (ctx->opts, "profile")) {
+        const char *pl = getenv ("LD_PRELOAD");
+        subprocess_setenvf (cli->p, "LD_PRELOAD", 1, "%s%s%s",
+            pl ? pl : "",
+            pl ? " ": "",
+            "libcaliper.so");
+    }
+#endif
+
     return cli;
 fail:
     client_destroy (cli);

[garlick]

I like where you ended up: --caliper-profile[=type] and option present but returning helpful error if built without caliper. (No reason to give them "bad option" and make them sleuth out the reason).

[grondo]

Ok, something like this?
(Though in general I do not have a problem with cmdline options that come and go with optional code -- we will likely eventually have that when plugins are able to provide new options to utilities in the future -- it does seem valid in this case I think)

$ src/cmd/flux start --help
Usage: flux-start [OPTIONS] command ...
  -X, --noexec           Don't execute (useful with -v, --verbose)
  -h, --help             Display this message.
  -k, --killer-timeout=SECONDS
                         After a broker exits, kill other brokers after SECONDS
  -o, --broker-opts=OPTS Add comma-separated broker options, e.g. "-o,-q"
  -s, --size=N           Set number of ranks in new instance
  -v, --verbose          Be annoyingly informative
      --caliper-profile=PROFILE
                         Enable profiling in brokers using Caliper configuration
                         profile named `PROFILE'

$ src/cmd/flux start /bin/true

$ src/cmd/flux start --caliper-profile=thread-trace /bin/true
== CALIPER: Registered event trigger service
== CALIPER: Registered pthread service
== CALIPER: Registered recorder service
== CALIPER: Registered timestamp service
== CALIPER: Registered trace service
== CALIPER: Initialized
2016-08-01T23:45:45.596233Z broker.err[0]: rc1: == CALIPER: Initialized
2016-08-01T23:45:45.665101Z broker.err[0]: rc1: == CALIPER: Initialized
2016-08-01T23:45:45.747175Z broker.err[0]: rc1: == CALIPER: Initialized
2016-08-01T23:45:45.818867Z broker.err[0]: rc1: == CALIPER: Initialized
2016-08-01T23:45:45.872114Z broker.err[0]: rc1: == CALIPER: == CALIPER: InitializedInitialized
2016-08-01T23:45:45.964693Z broker.err[0]: rc1: == CALIPER: Initialized
2016-08-01T23:45:46.055275Z broker.err[0]: rc1: == CALIPER: Initialized
2016-08-01T23:45:46.167584Z broker.err[0]: rc3: == CALIPER: Initialized
2016-08-01T23:45:46.224110Z broker.err[0]: rc3: == CALIPER: Initialized
2016-08-01T23:45:46.278749Z broker.err[0]: rc3: == CALIPER: Initialized
2016-08-01T23:45:46.334260Z broker.err[0]: rc3: == CALIPER: Initialized
2016-08-01T23:45:46.389870Z broker.err[0]: rc3: == CALIPER: Initialized
2016-08-01T23:45:46.445450Z broker.err[0]: rc3: == CALIPER: Initialized
2016-08-01T23:45:46.500377Z broker.err[0]: rc3: == CALIPER: Initialized
== CALIPER: Trace: Flushed 622 snapshots.
== CALIPER: Wrote 975 records.

Built without --enable-caliper

$ src/cmd/flux start --caliper-profile=thread-trace /bin/true
flux-start: Error: --caliper-profile used but no Caliper support found

[garlick]

That looks great to me!

[garlick]

Closing as we've merged #741.