RAII for perf_log #199

Open
benkirk opened this Issue Feb 10, 2014 · 2 comments

Projects

None yet

3 participants

@benkirk
Owner
benkirk commented Feb 10, 2014

OK, START_LOG(.,.) / STOP_LOG(.,.) pairs are annoying.

@roystgnr, we've talked about this a few times, and I think I have a good solution I'd like to run by you. The basic problem is one of scope & unique names.

What we'd like is something like

PerfItem foo(.,.,perf_log);
...

where the constructor begins the logging, and the destructor stops the logging.

But requiring unique names seems like a hassle and a pain to go back and drop in existing code.

What if we used the compiler LINE macro to create something automatic along the lines of

http://stackoverflow.com/questions/1597007/creating-c-macro-with-and-line-token-concatenation-with-positioning-macr

So then behind the scenes

START_LOG("action A", "Group");
START_LOG("action B", "Group");

would expand to

PerfItem perf_item_1("action A", "Group",perf_log);
PerfItem perf_item_2("action B", "Group",perf_log);

and then STOP_LOG(.,.) would be a no-op, and implemented in the PerfItem (or better class name...) destructor?

@permcody - thoughts?

@benkirk benkirk self-assigned this Feb 10, 2014
Owner

I really like the unique names trick for the macro.

One wishlist item, and two concerns:

Wish: I wonder if we could improve things further by creating two objects per START_LOG.

static PerfLookup perf_lookup_1("action A", "Group", perf_log);
PerfItem perf_item_1(perf_lookup_1);

so that hopefully we only have to do string tests once per program execution rather than once per logged event. As it is, our perf_log gets a bit heisen-buggy if we try to make too fine-grained a use of it, when the string operations start to become comparable in cost to the operations being measured.

First concern: often we want to stop logging an event before an object created by START_LOG would go out of scope. Even if we add scoping to every use in the library, I'd rather not silently corrupt logging results in user code. Code like this is common:

START_LOG("first_half", "Group")
first_half();
STOP_LOG("first_half", "Group")

START_LOG("second_half", "Group")
second_half();
STOP_LOG("second_half", "Group")

And we don't want to start silently and mistakenly logging those as nested routines rather than sequential ones.

We could write a separate "perf_item_N.destroy()" call that could be called by STOP_LOG, we could make sure the destructor handled a pre-destroyed state properly, but where I'm stumped is that we'd need some way to figure out how to get STOP_LOG to fill in N correctly - how do we tell STOP_LOG which START_LOG it should correspond to?

Second concern: it's currently at least possible to have a START_LOG in one scope but then the STOP_LOG outside that scope. I don't recall seeing any code do this, though, and unless others object I'd be fine with turning it into a compile-time error (as any STOP_LOG implementation addressing my first concern would be likely to do), just as long as we don't silently return wrong results.

@jwpeterson jwpeterson added a commit to jwpeterson/libmesh that referenced this issue Apr 21, 2016
@jwpeterson jwpeterson Add PerfItem class and LOG_SCOPE/LOG_SCOPE_IF macros.
This gets us about 95% of the way to the RAII PerfLog feature
discussed in #199.  It uses the macro trick to generate a unique
variable name based on __LINE__, but instead of outright replacing the
existing START_LOG/STOP_LOG macros with this new macro, I've
introduced a new one.  There are situations where a scope-based
logging macro just doesn't make sense, but they are pretty rare.
Almost all START_LOG/STOP_LOG pairs in the library can be replaced
with the new LOG_SCOPE macro, and the ones that can't easily be
replaced can just remain unchanged.

The logging capability can also be disabled at runtime by passing the
appropriate flag to the LOG_SCOPE_IF macro.  See examples of the way
this is used in the dof_map_constraints.C code.
8dba7fd
Owner
jwpeterson commented Apr 21, 2016 edited

Most of the RAII capability was implemented in #906. Not closing this yet, since we still have not implemented:

  • static PerfLookup objects
  • The ability to specify a PerfLog other than libMesh::PerfLog when creating LOG_SCOPE objects.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment