[BIOSAL] Thorium - logging?

Boisvert, Sebastien boisvert at anl.gov
Tue Nov 25 17:14:00 CST 2014


> From: George K. Thiruvathukal [gkt at cs.luc.edu]
> Sent: Tuesday, November 25, 2014 5:03 PM
> To: Boisvert, Sebastien
> Cc: biosal at lists.cels.anl.gov
> Subject: Re: [BIOSAL] Thorium - logging?
> 
> 
> 
> 
> This is great.
> 
> So just to be clear, do I need to set up lttng to use this new function, or is it a completely separate idea? I may actually try using it. It's a very cool framework.

thorium_actor_log is separate from LTTng.

If you look at the BioSAL code, LTTng tracepoints are those lines that contain things like this:

    tracepoint(provider, event, variable1, variable2);

> 
> 
> I have since figured out what my bug actually was (in my code). So the urgency of logging has suddenly gone down in importance.

I am actually using thorium_actor_log and it is a very good idea.

[boisvert at bigmem biosal]$ grep ACTOR  log
[17:9:44.79409036] [ACTOR_LOG] biosal_unitig_manager 1000212 ... visitor_count_per_worker = 5
[17:10:21.338736159] [ACTOR_LOG] biosal_unitig_manager 1000212 ... processed_vertices 2844032 vertices_with_unitig_flag 2839981



> 
> 
> Now I am trying to understand how to do non-local spawning. It seems like thorium_actor_spawn() does all of its work locally, right?

Yes.

Spawning remotely is easy, you need to send ACTION_SPAWN to an actor. The buffer must contain the
script identifier (SCRIPT_FOOBAR). I typically do it with thorium_actor_send_int().

> Can you help me to understand the correct way to do non-local spawning of actors without having to pass a message to one of
>  the initial remote actors and having it do a local spawn?  (Sorry for asking this dumb question!)

This is a legit question.

ACTION_SPAWN actually does thorium_actor_spawn() on the destination, but it also sets the supervisor
too so that the actor who sent ACTION_SPAWN in the first place is the supervisor of the newly
created actor.


> 
> Thanks,
> 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 11:48 AM, Boisvert, Sebastien 
> <boisvert at anl.gov> wrote:
> 
> > 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
> > > >
> > > >
> > > >
> > > >
> > > >
> > > >
> > > >
> > > >
> > > >
> > >
> > >
> > >
> > >
> > >
> >
> >
> >
> >
> >
> 
> 
> 
> 
> 


More information about the BIOSAL mailing list