dtrace discuss - Sep 2009 - Atomicity of committing speculation buffers

Hi

I''m trying to use dtrace speculation in order to avoid interleaving
trace messages by different threads.  I know that this is not what the
speculation mechanism was intended for, so I wanted to ask whether what
I''m doing is safe, and whether there is a better way to achieve the
same
result.

In particular, suppose that I have two different function calls that
I''m
monitoring, say foo() and bar().  Each thread is executing a sequence of
foo() calls followed by a single bar() call, and may execute multiple
such sequences.  In the dtrace script, we print each sequence with a
message for each invocation of foo() or bar(), e.g.:

pid$target::foo:entry
{
  printf("in sequence, params: %d %d", arg0, arg1);
}

pid$target::bar:entry
{
  printf("End sequence, param: %d", arg0);
}


My goal is to avoid intermixing printouts that correspond to different
sequences by different threads.  That is, I would like all printouts
of a sequence of foo() and bar() calls by a thread to be printed
together.  (I''m using the Java DTrace API to analyze these printouts,
and the java program is much simpler if it doesn''t need to deal with
multiple on-going sequences.)

My solution is to allocate a speculation buffer for each such sequence
(storing it in a thread local variable), execute the above printouts
speculatively into the buffer, and only commit the buffer when bar is
called.

My questions:

- Is it safe to assume that when two threads are concurrently committing
  two speculation buffers, then each commit operation is atomic with
  respect to the other? That is, print messages in one buffer will not
  be intermixed with messages in the other buffer?

- Do you know of a better way to achieve the same result? 

  It would be trivial to achieve this goal by building a thread-local
  string concatenating all messages that needed to be printed out for a
  sequence, and print it out when bar is called, but AFAIK DTrace does
  not have an sprintf function, and I do need the messages to be
  formatted in a certain way identified by the java front-end...

Thanks,
Yossi

Hi Yossi,

My suspicion is that speculative buffers won''t eliminate interleaving, 
though they would at least reduce the time window over which 
interleaving can occur.

I normally am interested in the time-sequence, so I print the current 
timestamp (nsec accurate and synchronized across all cores) as part of 
the output, then sort the result in a post-processing step before 
further analysis. In your case you''d want some monotonically increasing
"transaction number" to assign to each subtrace, then sort that (unix 
sort is stable, so you shouldn''t need timestamps within a subtrace).

Somebody will have to confirm, but I think global variables are 
lock-protected in DTrace, so you should be able to use one to store the 
sequence number.

Obviously this only works if the consumer can afford to wait for output 
to complete, though.

Regards,
Ryan

Yossi Lev (Sun Labs) wrote:
> Hi
>
> I''m trying to use dtrace speculation in order to avoid
interleaving
> trace messages by different threads.  I know that this is not what the
> speculation mechanism was intended for, so I wanted to ask whether what
> I''m doing is safe, and whether there is a better way to achieve
the same
> result.
>
> In particular, suppose that I have two different function calls that
I''m
> monitoring, say foo() and bar().  Each thread is executing a sequence of
> foo() calls followed by a single bar() call, and may execute multiple
> such sequences.  In the dtrace script, we print each sequence with a
> message for each invocation of foo() or bar(), e.g.:
>
> pid$target::foo:entry
> {
>  printf("in sequence, params: %d %d", arg0, arg1);
> }
>
> pid$target::bar:entry
> {
>  printf("End sequence, param: %d", arg0);
> }
>
>
> My goal is to avoid intermixing printouts that correspond to different
> sequences by different threads.  That is, I would like all printouts
> of a sequence of foo() and bar() calls by a thread to be printed
> together.  (I''m using the Java DTrace API to analyze these
printouts,
> and the java program is much simpler if it doesn''t need to deal
with
> multiple on-going sequences.)
>
> My solution is to allocate a speculation buffer for each such sequence
> (storing it in a thread local variable), execute the above printouts
> speculatively into the buffer, and only commit the buffer when bar is
> called.
>
> My questions:
>
> - Is it safe to assume that when two threads are concurrently committing
>  two speculation buffers, then each commit operation is atomic with
>  respect to the other? That is, print messages in one buffer will not
>  be intermixed with messages in the other buffer?
>
> - Do you know of a better way to achieve the same result?
>  It would be trivial to achieve this goal by building a thread-local
>  string concatenating all messages that needed to be printed out for a
>  sequence, and print it out when bar is called, but AFAIK DTrace does
>  not have an sprintf function, and I do need the messages to be
>  formatted in a certain way identified by the java front-end...
>
> Thanks,
> Yossi
>
>
>
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss at opensolaris.org

> Hi Yossi, My suspicion is that speculative buffers won''t eliminate
> interleaving, though they would at least reduce the time window over 
> which interleaving can occur. 
That explains the phenomena that I was seeing; I had a bug due to the
interleaving before I started using the speculation buffers, that only
happened occasionally.  After introducing the speculation buffers, the
bug disappeared in most cases, but still happens very rarely...
> I normally am interested in the time-sequence, so I print the current 
> timestamp (nsec accurate and synchronized across all cores) as part of 
> the output, then sort the result in a post-processing step before 
> further analysis. In your case you''d want some monotonically 
> increasing "transaction number" to assign to each subtrace, then
sort
> that (unix sort is stable, so you shouldn''t need timestamps within
a
> subtrace). 
The problem is that I''m using the java DTrace API for analyzing all the
traced data, so I cannot wait for all of it to be printed out.  (The
java consumer wakes up periodically whenever the dtrace buffers are not
empty.)  So I have to process the data on the fly.  It is possible for
me to also print out the thread id, and keep track (in the java program)
of all N sequences that might be reported concurrently, but I tried to
avoid it.  I may try to play with string manipulations and buffering in
dtrace before I give up and solve the problem in the java front end...
> Somebody will have to confirm, but I think global variables are 
> lock-protected in DTrace, so you should be able to use one to store 
> the sequence number. 
Actually, from messages that I saw in this forum, and my (little)
experience with dtrace, access to global variable is not MT-safe.  I
definitely recall trying to increment a global counter to count the
number of calls to a function called by multiple threads, and seeing
lost updates.  I also saw messages in this forum telling users to use
aggregations whenever an MT-safe counting is necessary, for both
scalability and safety reasons.  So my understanding is that maintaining
a sequence number (that has to be incremented by each thread at the end
of each sequence) cannot be done using a global variable --- am I
missing something?


Thanks,
Yossi
> Obviously this only works if the consumer can afford to wait for 
> output to complete, though. Regards, Ryan Yossi Lev (Sun Labs) wrote: 
> > Hi > > I''m trying to use dtrace speculation in order to
avoid
> interleaving > trace messages by different threads. I know that this 
> is not what the > speculation mechanism was intended for, so I wanted 
> to ask whether what > I''m doing is safe, and whether there is a
better
> way to achieve the same > result. > > In particular, suppose that
I
> have two different function calls that I''m > monitoring, say
foo() and
> bar(). Each thread is executing a sequence of > foo() calls followed 
> by a single bar() call, and may execute multiple > such sequences. In 
> the dtrace script, we print each sequence with a > message for each 
> invocation of foo() or bar(), e.g.: > > pid$target::foo:entry > {
>
> printf("in sequence, params: %d %d", arg0, arg1); > } >
>
> pid$target::bar:entry > { > printf("End sequence, param:
%d", arg0); >
> } > > > My goal is to avoid intermixing printouts that correspond
to
> different > sequences by different threads. That is, I would like all 
> printouts > of a sequence of foo() and bar() calls by a thread to be 
> printed > together. (I''m using the Java DTrace API to analyze
these
> printouts, > and the java program is much simpler if it doesn''t
need
> to deal with > multiple on-going sequences.) > > My solution is to
> allocate a speculation buffer for each such sequence > (storing it in 
> a thread local variable), execute the above printouts > speculatively 
> into the buffer, and only commit the buffer when bar is > called. >
>
> My questions: > > - Is it safe to assume that when two threads are 
> concurrently committing > two speculation buffers, then each commit 
> operation is atomic with > respect to the other? That is, print 
> messages in one buffer will not > be intermixed with messages in the 
> other buffer? > > - Do you know of a better way to achieve the same 
> result? > It would be trivial to achieve this goal by building a 
> thread-local > string concatenating all messages that needed to be 
> printed out for a > sequence, and print it out when bar is called, but 
> AFAIK DTrace does > not have an sprintf function, and I do need the 
> messages to be > formatted in a certain way identified by the java 
> front-end... > > Thanks, > Yossi > > > > 
> _______________________________________________ > dtrace-discuss 
> mailing list > dtrace-discuss at opensolaris.org

On Sat, Sep 5, 2009 at 12:09 AM, Yossi Lev (Sun Labs)<Yosef.Lev at
sun.com> wrote:
>
>> Somebody will have to confirm, but I think global variables are
>> lock-protected in DTrace, so you should be able to use one to store the
>> sequence number.
>
> Actually, from messages that I saw in this forum, and my (little)
> experience with dtrace, access to global variable is not MT-safe. ?I
> definitely recall trying to increment a global counter to count the
> number of calls to a function called by multiple threads, and seeing
> lost updates. ?I also saw messages in this forum telling users to use
> aggregations whenever an MT-safe counting is necessary, for both
> scalability and safety reasons. ?So my understanding is that maintaining
> a sequence number (that has to be incremented by each thread at the end
> of each sequence) cannot be done using a global variable --- am I
> missing something?
>
No, that''s correct.  There is no protection for global variables in
DTrace.

Chad