thr3ads.net - dtrace discuss - [dtrace-discuss] aggregation on ustack() not aggregating [Nov 2012]

If this information is useful, please help other people find it:
Share via:

Kelly Caudill

2012-Nov-08 14:55 UTC

[dtrace-discuss] aggregation on ustack() not aggregating

I would like to "profile" when threads in certain processes go to
sleep.

The following seems to work, but...

sched:::off-cpu
/execname == "MyProg" && curlwpsinfo->pr_state == SSLEEP/
{
  self->sleepStart = timestamp;
}

sched:::on-cpu
/self->sleepStart/
{
  this->slept = timestamp - self->sleepStart;
  /* I want specifics about LWP#s < 20 and combine all others  */
  this->thrd = tid < 20 ? tid : 0;

  @sleepCnt[this->thrd,ustack()] = count();
  @sleepAvg[this->thrd,ustack()] = avg(this->slept);
  @sleepTot[this->thrd,ustack()] = sum(this->slept);

  @SleepCnt[pid] = count();
  @TotSlp[pid] = sum(this->slept);

  self->sleepStart = 0;
}

dtrace:::END
{
  trunc(@sleepTot, 10);
  trunc(@sleepCnt, 20);
  trunc(@sleepAvg, 10);

  normalize(@sleepTot,1000000);
  normalize(@sleepAvg,1000000);
  printa("lwp %d slept (tot=%@dms) %@d times (avg=%@dms) like
this:%-6k\n",
    @sleepTot, @sleepCnt, @sleepAvg);
}


but I do not understand why it does not combine some entries like:

lwp 5 slept (tot=0ms) 0 times (avg=30000ms) like this:
     libc.so.1`__lwp_park+0x10
     libc.so.1`cond_wait_queue+0x4c
     libc.so.1`cond_wait_common+0x2d4
     libc.so.1`_cond_timedwait+0x34
     libc.so.1`cond_timedwait+0x14
     libc.so.1`pthread_cond_timedwait+0xc
     libnspr4.so`pt_TimedWait+0xe0
     libnspr4.so`PR_WaitCondVar+0x190
     libnspr4.so`PR_Wait+0x1c
     libmqcrt.so.1`0xffffffff57657c48
     libnspr4.so`_pt_root+0xa8
     libc.so.1`_lwp_start

lwp 5 slept (tot=0ms) 0 times (avg=30000ms) like this:
     libc.so.1`__lwp_park+0x10
     libc.so.1`cond_wait_queue+0x4c
     libc.so.1`cond_wait_common+0x2d4
     libc.so.1`_cond_timedwait+0x34
     libc.so.1`cond_timedwait+0x14
     libc.so.1`pthread_cond_timedwait+0xc
     libnspr4.so`pt_TimedWait+0xe0
     libnspr4.so`PR_WaitCondVar+0x190
     libnspr4.so`PR_Wait+0x1c
     libmqcrt.so.1`0xffffffff57657c48
     libnspr4.so`_pt_root+0xa8
     libc.so.1`_lwp_start

lwp 5 slept (tot=0ms) 0 times (avg=30000ms) like this:
     libc.so.1`__lwp_park+0x10
     libc.so.1`cond_wait_queue+0x4c
     libc.so.1`cond_wait_common+0x2d4
     libc.so.1`_cond_timedwait+0x34
     libc.so.1`cond_timedwait+0x14
     libc.so.1`pthread_cond_timedwait+0xc
     libnspr4.so`pt_TimedWait+0xe0
     libnspr4.so`PR_WaitCondVar+0x190
     libnspr4.so`PR_Wait+0x1c
     libmqcrt.so.1`0xffffffff57657c48
     libnspr4.so`_pt_root+0xa8
     libc.so.1`_lwp_start

Those are just one example of thread stacks that seem identical but were not
combined into a single aggregation bucket.

Some of the numbers are 0 due to the trun(xx,N) before the print - because I
only want to see the (hopefully) few worst offenders.

But since it does not combine them properly, the list is overwhelmed with like
above which, unfortunately, are a case I don''t actually care about. If
it combined those, then I the other few printed should be what I do care about.

Am I doing something wrong?

Excluding the stacks like above, by setting a flag when it enters that function,
is problematic because it requires using the pid provider and then I can only
watch one process at a time.

Kelly

Robert Harris

2012-Nov-08 15:16 UTC

head link

[dtrace-discuss] aggregation on ustack() not aggregating

Hi Kelly,

On 8 Nov 2012, at 14:55, Kelly Caudill wrote:> 
> but I do not understand why it does not combine some entries like:
> 
> lwp 5 slept (tot=0ms) 0 times (avg=30000ms) like this:
>     libc.so.1`__lwp_park+0x10
>     libc.so.1`cond_wait_queue+0x4c
>     libc.so.1`cond_wait_common+0x2d4
>     libc.so.1`_cond_timedwait+0x34
>     libc.so.1`cond_timedwait+0x14
>     libc.so.1`pthread_cond_timedwait+0xc
>     libnspr4.so`pt_TimedWait+0xe0
>     libnspr4.so`PR_WaitCondVar+0x190
>     libnspr4.so`PR_Wait+0x1c
>     libmqcrt.so.1`0xffffffff57657c48
>     libnspr4.so`_pt_root+0xa8
>     libc.so.1`_lwp_start
> 
> lwp 5 slept (tot=0ms) 0 times (avg=30000ms) like this:
>     libc.so.1`__lwp_park+0x10
>     libc.so.1`cond_wait_queue+0x4c
>     libc.so.1`cond_wait_common+0x2d4
>     libc.so.1`_cond_timedwait+0x34
>     libc.so.1`cond_timedwait+0x14
>     libc.so.1`pthread_cond_timedwait+0xc
>     libnspr4.so`pt_TimedWait+0xe0
>     libnspr4.so`PR_WaitCondVar+0x190
>     libnspr4.so`PR_Wait+0x1c
>     libmqcrt.so.1`0xffffffff57657c48
>     libnspr4.so`_pt_root+0xa8
>     libc.so.1`_lwp_start
> 
> lwp 5 slept (tot=0ms) 0 times (avg=30000ms) like this:
>     libc.so.1`__lwp_park+0x10
>     libc.so.1`cond_wait_queue+0x4c
>     libc.so.1`cond_wait_common+0x2d4
>     libc.so.1`_cond_timedwait+0x34
>     libc.so.1`cond_timedwait+0x14
>     libc.so.1`pthread_cond_timedwait+0xc
>     libnspr4.so`pt_TimedWait+0xe0
>     libnspr4.so`PR_WaitCondVar+0x190
>     libnspr4.so`PR_Wait+0x1c
>     libmqcrt.so.1`0xffffffff57657c48
>     libnspr4.so`_pt_root+0xa8
>     libc.so.1`_lwp_start
> 
> Those are just one example of thread stacks that seem identical but were
not combined into a single aggregation bucket.
> 
> Some of the numbers are 0 due to the trun(xx,N) before the print - because
I only want to see the (hopefully) few worst offenders.
> 
> But since it does not combine them properly, the list is overwhelmed with
like above which, unfortunately, are a case I don''t actually care
about. If it combined those, then I the other few printed should be what I do
care about.
> 
> Am I doing something wrong?
You''re not doing anything wrong.  This is a known limitation
that arises from the fact that the aggregation key generated
by the ustack() action includes the PID.  The PID itself isn''t
displayed; it''s used to enable the user-land component to
perform the address-to-name translation against the correct process.

Robert

Harendra Rawat

2013-Feb-22 19:52 UTC

head link

[dtrace-discuss] aggregation on ustack() not aggregating

I am also seeing same problem. Test run as follows.


syscall::umask:entry
{
??????? @execnameCntonly[execname, ustack()] = count();
}



bash-3.00# chmod 777 /tmp/abctsidx
bash-3.00# chmod 777 /tmp/abctsidx
bash-3.00# chmod 777 /tmp/abctsidx
bash-3.00# chmod 777 /tmp/abctsidx
bash-3.00# chmod 777 /tmp/abctsidx



? chmod
????????????? 0xfeefb7d5
????????????? 0x8051026
??????????????? 2
? chmod
????????????? 0xfeefb7d5
????????????? 0x8051026
??????????????? 2
? chmod
????????????? 0xfeefb7d5
????????????? 0x8051026
??????????????? 2
? chmod
????????????? 0xfeefb7d5
????????????? 0x8051026
??????????????? 2
? chmod
????????????? 0xfeefb7d5
????????????? 0x8051026
??????????????? 2



________________________________
 From: Kelly Caudill <kelly.caudill at oracle.com>
To: dtrace-discuss at opensolaris.org 
Sent: Thursday, November 8, 2012 6:55 AM
Subject: [dtrace-discuss] aggregation on ustack() not aggregating
 
I would like to "profile" when threads in certain processes go to
sleep.

The following seems to work, but...

sched:::off-cpu
/execname == "MyProg" && curlwpsinfo->pr_state == SSLEEP/
{
? self->sleepStart = timestamp;
}

sched:::on-cpu
/self->sleepStart/
{
? this->slept = timestamp - self->sleepStart;
? /* I want specifics about LWP#s < 20 and combine all others? */
? this->thrd = tid < 20 ? tid : 0;

? @sleepCnt[this->thrd,ustack()] = count();
? @sleepAvg[this->thrd,ustack()] = avg(this->slept);
? @sleepTot[this->thrd,ustack()] = sum(this->slept);

? @SleepCnt[pid] = count();
? @TotSlp[pid] = sum(this->slept);

? self->sleepStart = 0;
}

dtrace:::END
{
? trunc(@sleepTot, 10);
? trunc(@sleepCnt, 20);
? trunc(@sleepAvg, 10);

? normalize(@sleepTot,1000000);
? normalize(@sleepAvg,1000000);
? printa("lwp %d slept (tot=%@dms) %@d times (avg=%@dms) like
this:%-6k\n",
? ? @sleepTot, @sleepCnt, @sleepAvg);
}


but I do not understand why it does not combine some entries like:

lwp 5 slept (tot=0ms) 0 times (avg=30000ms) like this:
? ?  libc.so.1`__lwp_park+0x10
? ?  libc.so.1`cond_wait_queue+0x4c
? ?  libc.so.1`cond_wait_common+0x2d4
? ?  libc.so.1`_cond_timedwait+0x34
? ?  libc.so.1`cond_timedwait+0x14
? ?  libc.so.1`pthread_cond_timedwait+0xc
? ? libnspr4.so`pt_TimedWait+0xe0
? ?  libnspr4.so`PR_WaitCondVar+0x190
? ?  libnspr4.so`PR_Wait+0x1c
? ?  libmqcrt.so.1`0xffffffff57657c48
? ?  libnspr4.so`_pt_root+0xa8
? ?  libc.so.1`_lwp_start

lwp 5 slept (tot=0ms) 0 times (avg=30000ms) like this:
? ?  libc.so.1`__lwp_park+0x10
? ?  libc.so.1`cond_wait_queue+0x4c
? ?  libc.so.1`cond_wait_common+0x2d4
? ?  libc.so.1`_cond_timedwait+0x34
? ?  libc.so.1`cond_timedwait+0x14
? ?  libc.so.1`pthread_cond_timedwait+0xc
? ?  libnspr4.so`pt_TimedWait+0xe0
? ?  libnspr4.so`PR_WaitCondVar+0x190
? ?  libnspr4.so`PR_Wait+0x1c
? ?  libmqcrt.so.1`0xffffffff57657c48
? ?  libnspr4.so`_pt_root+0xa8
? ?  libc.so.1`_lwp_start

lwp 5 slept (tot=0ms) 0 times (avg=30000ms) like this:
? ?  libc.so.1`__lwp_park+0x10
? ?  libc.so.1`cond_wait_queue+0x4c
? ?  libc.so.1`cond_wait_common+0x2d4
? ?  libc.so.1`_cond_timedwait+0x34
? ?  libc.so.1`cond_timedwait+0x14
? ?  libc.so.1`pthread_cond_timedwait+0xc
? ?  libnspr4.so`pt_TimedWait+0xe0
? ?  libnspr4.so`PR_WaitCondVar+0x190
? ?  libnspr4.so`PR_Wait+0x1c
? ?  libmqcrt.so.1`0xffffffff57657c48
? ?  libnspr4.so`_pt_root+0xa8
? ?  libc.so.1`_lwp_start

Those are just one example of thread stacks that seem identical but were not
combined into a single aggregation bucket.

Some of the numbers are 0 due to the trun(xx,N) before the print - because I
only want to see the (hopefully) few worst offenders.

But since it does not combine them properly, the list is overwhelmed with like
above which, unfortunately, are a case I don''t actually care about. If
it combined those, then I the other few printed should be what I do care about.

Am I doing something wrong?

Excluding the stacks like above, by setting a flag when it enters that function,
is problematic because it requires using the pid provider and then I can only
watch one process at a time.

Kelly
_______________________________________________
dtrace-discuss mailing list
dtrace-discuss at opensolaris.org
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20130222/fe603fe2/attachment.html>

dtrace discuss - Nov 2012 - aggregation on ustack() not aggregating

[dtrace-discuss] aggregation on ustack() not aggregating

[dtrace-discuss] aggregation on ustack() not aggregating

[dtrace-discuss] aggregation on ustack() not aggregating