I am trying to use signal-send and signal-handle
to see some timing issues related to the delivery of signals.
However, I am getting very strange results. I happen to be
interested specifically in SIGPOLL, signal 22. However, I
get very different results depending on the predicate I
specify.
The ntpd version 4 daemon uses a SIGPOLL signal to determine that a
packet has arrived on one of the incoming file descriptors. Every
once in a while, we start seeing a though latency between the time
the packet arrives and the time that ntpd reads the packet. So, I
wanted to use dtrace to try to find where the delay come in.
So, I created the following to print out the time of signal-send,
and signal-handle:
#!/usr/sbin/dtrace -Cs
/* The following prints out wallclock time to microseconds */
#define PRINTNOW
printf("%Y.%06d",(this->_wts=walltimestamp),(this->_wts/1000)%1000000);
proc:::signal-send
/args[2] == SIGPOLL/
{
PRINTNOW;
printf(" sig=%d pid=%d",args[2],pid);
}
proc:::signal-handle
/args[0] == SIGPOLL/
{
PRINTNOW;
printf(" sig=%d pid=%d",args[0],pid);
}
Sometimes when I run the above, I don''t get anything, sometimes I just
get signal-send. Once in a great while I get signal-handle.
However, if I remove the predicates from the two clauses, I start
getting the SIGALRMs that ntpd uses each second for house keeping,
but now I always get the SIGPOLL signals too, always with a signal-send
and a signal-handle (though sometimes out of order if they were on
different cpus).
It just doesn''t make sense to me. This has got to be a bug right?
--
blu
Remember when SOX compliant meant they were both the same color?
----------------------------------------------------------------------
Brian Utterback - OP/N1 RPE, Sun Microsystems, Inc.
Ph:877-259-7345, Em:brian.utterback-at-ess-you-enn-dot-kom
On Mon, Aug 08, 2005 at 02:38:02PM -0400, Brian Utterback wrote:> I am trying to use signal-send and signal-handle > to see some timing issues related to the delivery of signals. > > However, I am getting very strange results. I happen to be > interested specifically in SIGPOLL, signal 22. However, I > get very different results depending on the predicate I > specify.[ elided ]> However, if I remove the predicates from the two clauses, I start > getting the SIGALRMs that ntpd uses each second for house keeping, > but now I always get the SIGPOLL signals too, always with a signal-send > and a signal-handle (though sometimes out of order if they were on > different cpus). > > It just doesn''t make sense to me. This has got to be a bug right?Yes, it''s a bug -- and a very nasty one. I happened to run into this myself week-before-last, and I couldn''t believe that we hadn''t run into it before. Anyway, this is the bug: 6304654 predicates containing args[] references may be incorrectly cached This has happened to me so many times I shouldn''t be surprised, but I can''t believe that we don''t see this for ~two years, and then we see it twice inside of a week... - Bryan -------------------------------------------------------------------------- Bryan Cantrill, Solaris Kernel Development. http://blogs.sun.com/bmc
On 8/8/05, Brian Utterback <brian.utterback at sun.com> wrote:> > Using arg0 seems to work for signal-handle, but using arg2 doesn''t > seem to help for signal-send.That''s because args[2] is mapped to arg1 internally for signal-send; you have to look up the source to use the "argn" variables correctly. In this case, see: http://cvs.opensolaris.org/source/search?refs=signal__send 293 DTRACE_PROC2(signal__send, kthread_t *, t, int, sig); Note that sig is the *second* argument, or arg1. Alternatively, you can look at the big table in sdt.c: http://cvs.opensolaris.org/source/xref/usr/src/uts/common/dtrace/sdt_subr.c#sdt_args The entry in question is: 124 { "proc", "signal-send", 2, 1, "int" }, 2 is the args[] array member, 1 is the argn number. Cheers, - jonathan