[BIOSAL] Thorium - logging?

Tue Nov 25 11:48:29 CST 2014

> From: George K. Thiruvathukal [gkt at cs.luc.edu]
> Sent: Tuesday, November 25, 2014 10:56 AM
> To: Boisvert, Sebastien
> Cc: biosal at lists.cels.anl.gov
> Subject: Re: [BIOSAL] Thorium - logging?
> 
> 
> 
> 
> Hi Seb,
> 
> 
> I like your idea of thorium_actor_log(). We can start with something simple. 

I added:

void thorium_actor_log(struct thorium_actor *self, const char *format, ...);

Usage:

        thorium_actor_log(self, "processed_vertices %" PRIu64
                        " vertices_with_unitig_flag %" PRIu64 "",
                        concrete_self->processed_vertices,
                        concrete_self->vertices_with_unitig_flag);

Output (in stdout):

[11:38:10.973412705] [ACTOR_LOG] biosal_unitig_manager 1000212 ... processed_vertices 2846919 vertices_with_unitig_flag 2842866

Known bug:

localtime_r does not set daylight saving time, so the time reported by thorium_actor_log does not have daylight saving time.

> The two things I often want to log (and filter) are actor and the message tag (ideally, putting these toward the beginning of the log output.

If you want to log and filter received messages (on the action specifier, destination, or source), you should really
try LTTng. You don't need to add instrumentation, it is already there. You just need CONFIG_LTTNG (see build script) to enable
instrumentation.

It is actually easier than it sounds. LTTng actually has some formal proof in academic papers that show that
it is correct and that the ordering of events (in nanoseconds) is best-in-class.

Also, LTTng has a very low impact on running time because it uses the splice() syscall instead of the write() syscall (for printf).

./scripts/lttng/build.sh
lttng create
lttng enable-event -u \
    thorium_actor:receive_enter,thorium_actor:receive_exit \
    --filter "name == 1001563"
lttng start
mpiexec -n 4 ./applications/spate_metagenome_assembler/spate -k 51 -threads-per-node 7 ~/dropbox/S.aureus.fasta.gz
lttng stop
lttng view > trace.txt
llttng destroy

less trace.txt

Example of things found in trace.txt:

[12:44:22.974332982] (+0.002822212) bigmem.biosal thorium_actor:receive_enter: { cpu_id = 58 }, { name = 1001563, script = 0xFFFFFFFFEB3B39FD, action = 0x7724, count = 41 }
[12:44:22.974338367] (+0.000005385) bigmem.biosal thorium_actor:receive_exit: { cpu_id = 58 }, { name = 1001563, script = 0xFFFFFFFFEB3B39FD, action = 0x7724, count = 41 }

The FFF in front of the script (32 bits) is a known bug in LTTng. I was the reporter for this bug a month ago.

The tracepoint definition is located in the following file if you wish to change it (for instance, if you want to add the source and use %d instead of %x for the action:

performance/tracepoints/lttng/actor.tp

> 
> 
> George
> 
> 
> 
> 
> 
> George K. Thiruvathukal, PhD
> 
> Professor of Computer Science, Loyola University Chicago
> 
> Director, Center for Textual Studies and Digital Humanities
> Guest Faculty, Argonne National Laboratory, Math and Computer Science Division
> Editor in Chief, Computing in
>  Science and Engineering (IEEE CS/AIP)
> 
> (w) gkt.tv (v)
>  773.829.4872
> 
> 
> 
> 
> 
> 
> 
> On Tue, Nov 25, 2014 at 9:41 AM, Boisvert, Sebastien 
> <boisvert at anl.gov> wrote:
> 
> Just to be sure, do you want thorium_actor_log() or you are fine with LTTng ?
> 
> 
> In both cases, I can take action so that you get what you need to move forward.
> 
> 
> > From: George K. Thiruvathukal [gkt at cs.luc.edu]
> > Sent: Tuesday, November 25, 2014 9:38 AM
> > To: Boisvert, Sebastien
> > Cc: 
> biosal at lists.cels.anl.gov
> > Subject: Re: [BIOSAL] Thorium - logging?
> 
> >
> >
> >
> >
> > Thanks for reminding me about this! Yes, that's exactly what I was hoping to find.
> >
> >
> > I just don't want to be using explicit printf() statements.
> >
> >
> > See you tomorrow. I am hoping to push out a new version of my hello_acquaintances today. :) We'll work on the paper tomorrow morning (among other things).
> >
> >
> > George
> >
> >
> >
> >
> > George K. Thiruvathukal, PhD
> >
> > Professor of Computer Science, Loyola University Chicago
> >
> > Director, Center for Textual Studies and Digital Humanities
> > Guest Faculty, Argonne National Laboratory, Math and Computer Science Division
> > Editor in Chief, Computing in
> >  Science and Engineering (IEEE CS/AIP)
> >
> > (w)
> > 
> thiruvathukal.com (v) 773.829.4872
> >
> >
> >
> >
> >
> >
> >
> >
> > On Tue, Nov 25, 2014 at 9:35 AM, Boisvert, Sebastien
> > <boisvert at anl.gov> wrote:
> >
> > > From:
> > 
> biosal-bounces at lists.cels.anl.gov [biosal-bounces at lists.cels.anl.gov] on behalf of George
> >  K. Thiruvathukal [gkt at cs.luc.edu]
> > > Sent: Tuesday, November 25, 2014 9:12 AM
> > > To:
> > 
> biosal at lists.cels.anl.gov
> > > Subject: [BIOSAL] Thorium - logging?
> > >
> > >
> > >
> > >
> > > Quick Thorium question...
> > >
> > >
> > > Is there any sort of logging framework for Thorium?
> >
> > There are the LTTng tracepoints, and some "custom" tracepoints. LTTng is very useful to trace race conditions.
> >
> > There are already instrumentation for events such as thorium_actor:receive_enter.
> >
> >
> > > Owing to a bit of a bug, I am suddenly seeing the need for a way to log distributed events (in example/application-oriented codes).
> >
> > If the ordering of these distributed events is important, than LTTng is the tool to use in my opinion.
> >
> > For any message that is received, there is a tracepoint event already instrumented.
> >
> > >
> > >
> > > In the simplest form, something like a log(format, args) would do the trick. What I would like is some way to prefix the output with the actor name (number) so I could filter out various logging events.
> >
> > In your case, I suppose that this could work for you:
> >
> > thorium_actor_log(self, format, args);
> >
> > example:
> >
> > thorium_actor_log(self, "foo = %d bar= %d", 42, 99);
> >
> > which would print
> >
> > [LOG] 2014-11-24T21:14:29+00:00 my_cool_actor_script/1234 says: foo= 42 bar= 99
> >
> > The first iteration of that would write to stdout, if that's all right with you.
> >
> >
> >
> > >
> > >
> > > Best,
> > > George
> > >
> > >
> > >
> > >
> > >
> > > George K. Thiruvathukal, PhD
> > >
> > > Professor of Computer Science, Loyola University Chicago
> > >
> > > Director, Center for Textual Studies and Digital Humanities
> > > Guest Faculty, Argonne National Laboratory, Math and Computer Science Division
> > > Editor in Chief, Computing in
> > >  Science and Engineering (IEEE CS/AIP)
> > >
> > > (w)
> > >
> > 
> thiruvathukal.com (v) 773.829.4872
> > >
> > >
> > >
> > >
> > >
> > >
> > >
> > >
> > >
> >
> >
> >
> >
> >
> 
> 
> 
> 
> 