thr3ads.net - dtrace discuss - [dtrace-discuss] probe order [Dec 2009]

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

tester

2009-Dec-19 00:56 UTC

[dtrace-discuss] probe order

Hi,

In this D script:
#
#
#
#
# cat spa_sync_2.d
#!/usr/sbin/dtrace -qs

BEGIN {

   self->prevtime=0;

}

spa_sync:entry
{
        printf("%Y thread %a enter\n", walltimestamp, curthread );
        self->t = 1;
}

spa_sync:entry
/self->prevtime > 0  && self->t == 1/
{
        times = self->prevtime ? timestamp - self->prevtime : 0;
        printf("%Y thread %a re-entering after %d\n", walltimestamp,
curthread, times/(1000*1000));
}

spa_sync:entry
{
        self->prevtime = timestamp;
}



spa_sync:return
/self->t == 1 && self->prevtime > 0/
{
        self->t = 0;
        printf("%Y thread %a did work for %d ms\n", walltimestamp,
curthread ,(timestamp - self->prevtime)/(1000*1000));
        printf("%Y thread %a leaving \n\n", walltimestamp,curthread);
}

tick-1s {

   printf("%Y \n",walltimestamp);
}

most of the times the probes fire as expected in this order

"enter
re-enter [optional]
did work 
leave
"
2009 Dec 18 19:44:43
2009 Dec 18 19:44:44
2009 Dec 18 19:44:45
2009 Dec 18 19:44:46
2009 Dec 18 19:44:47
2009 Dec 18 19:44:48
2009 Dec 18 19:44:49
2009 Dec 18 19:44:50
2009 Dec 18 19:44:51
2009 Dec 18 19:44:52
2009 Dec 18 19:44:53
2009 Dec 18 19:44:54
2009 Dec 18 19:44:55
2009 Dec 18 19:44:56
2009 Dec 18 19:44:57 thread 0x2a100be7ca0 enter
2009 Dec 18 19:44:57 thread 0x2a100be7ca0 did work for 309 ms
2009 Dec 18 19:44:57 thread 0x2a100be7ca0 leaving

2009 Dec 18 19:44:57
2009 Dec 18 19:44:58 thread 0x2a103aa7ca0 enter
2009 Dec 18 19:44:58 thread 0x2a103aa7ca0 did work for 30 ms
2009 Dec 18 19:44:58 thread 0x2a103aa7ca0 leaving

2009 Dec 18 19:44:58
2009 Dec 18 19:44:59
2009 Dec 18 19:45:00
2009 Dec 18 19:45:01 thread 0x2a1065d9ca0 enter
2009 Dec 18 19:45:01 thread 0x2a1065d9ca0 did work for 15 ms
2009 Dec 18 19:45:01 thread 0x2a1065d9ca0 leaving

2009 Dec 18 19:45:01
2009 Dec 18 19:45:02
2009 Dec 18 19:45:03
2009 Dec 18 19:45:04
2009 Dec 18 19:45:05
2009 Dec 18 19:45:06
2009 Dec 18 19:45:07
2009 Dec 18 19:45:08
2009 Dec 18 19:45:09
2009 Dec 18 19:45:10
2009 Dec 18 19:45:11
2009 Dec 18 19:45:12
2009 Dec 18 19:45:13
2009 Dec 18 19:45:14
2009 Dec 18 19:45:15
2009 Dec 18 19:45:16
2009 Dec 18 19:45:17
2009 Dec 18 19:45:18
2009 Dec 18 19:45:19
2009 Dec 18 19:45:20
2009 Dec 18 19:45:21
2009 Dec 18 19:45:22
2009 Dec 18 19:45:23
2009 Dec 18 19:45:24
2009 Dec 18 19:45:25
2009 Dec 18 19:45:26
2009 Dec 18 19:45:27 thread 0x2a100be7ca0 enter
2009 Dec 18 19:45:27 thread 0x2a100be7ca0 re-entering after 30010
2009 Dec 18 19:45:27
2009 Dec 18 19:45:27 thread 0x2a100be7ca0 did work for 293 ms
2009 Dec 18 19:45:27 thread 0x2a100be7ca0 leaving

2009 Dec 18 19:45:28 thread 0x2a103aa7ca0 enter
2009 Dec 18 19:45:28 thread 0x2a103aa7ca0 re-entering after 30009
2009 Dec 18 19:45:28
2009 Dec 18 19:45:28 thread 0x2a103aa7ca0 did work for 22 ms
2009 Dec 18 19:45:28 thread 0x2a103aa7ca0 leaving

2009 Dec 18 19:45:29
2009 Dec 18 19:45:30
2009 Dec 18 19:45:31 thread 0x2a1065d9ca0 enter
2009 Dec 18 19:45:31 thread 0x2a1065d9ca0 re-entering after 30009
2009 Dec 18 19:45:31 thread 0x2a1065d9ca0 did work for 12 ms
2009 Dec 18 19:45:31 thread 0x2a1065d9ca0 leaving

2009 Dec 18 19:45:31
2009 Dec 18 19:45:32
2009 Dec 18 19:45:33
2009 Dec 18 19:45:34
2009 Dec 18 19:45:35
2009 Dec 18 19:45:36
2009 Dec 18 19:45:37
2009 Dec 18 19:45:38
2009 Dec 18 19:45:39
2009 Dec 18 19:45:40
2009 Dec 18 19:45:41
2009 Dec 18 19:45:42
2009 Dec 18 19:45:43
2009 Dec 18 19:45:44
2009 Dec 18 19:45:45
2009 Dec 18 19:45:46
2009 Dec 18 19:45:47
2009 Dec 18 19:45:48
2009 Dec 18 19:45:49
2009 Dec 18 19:45:50
2009 Dec 18 19:45:51
2009 Dec 18 19:45:52
2009 Dec 18 19:45:53
2009 Dec 18 19:45:54
2009 Dec 18 19:45:55
2009 Dec 18 19:45:56
2009 Dec 18 19:45:57 thread 0x2a100be7ca0 enter
2009 Dec 18 19:45:57 thread 0x2a100be7ca0 re-entering after 30010
2009 Dec 18 19:45:57
2009 Dec 18 19:45:57 thread 0x2a100be7ca0 did work for 286 ms
2009 Dec 18 19:45:57 thread 0x2a100be7ca0 leaving

2009 Dec 18 19:45:58 thread 0x2a103aa7ca0 enter
2009 Dec 18 19:45:58 thread 0x2a103aa7ca0 re-entering after 30010
2009 Dec 18 19:45:58 thread 0x2a103aa7ca0 did work for 20 ms
2009 Dec 18 19:45:58 thread 0x2a103aa7ca0 leaving

2009 Dec 18 19:45:58
2009 Dec 18 19:45:59
2009 Dec 18 19:46:00
2009 Dec 18 19:46:01 thread 0x2a1065d9ca0 did work for 17 ms
2009 Dec 18 19:46:01 thread 0x2a1065d9ca0 leaving

2009 Dec 18 19:46:01 thread 0x2a1065d9ca0 enter
2009 Dec 18 19:46:01 thread 0x2a1065d9ca0 re-entering after 30009
2009 Dec 18 19:46:01

but in the last instance we have the order
"did work
leaving
enter
re-enter"

I checked that thread 0x2a1065d9ca0 did fire spa_sync:return, so I
don''t understand why the order changed.

Thanks for any clarification.
-- 
This message posted from opensolaris.org

Michael Ernest

2009-Dec-19 20:18 UTC

head link

[dtrace-discuss] probe order

Is this by any chance running on a multi-core system?
-- 
This message posted from opensolaris.org

tester

2009-Dec-21 15:19 UTC

head link

[dtrace-discuss] probe order

Yes, a T5220.

S10, patch 141414-10
-- 
This message posted from opensolaris.org

Nicolas Williams

2009-Dec-21 15:38 UTC

head link

[dtrace-discuss] probe order

On Mon, Dec 21, 2009 at 07:19:35AM -0800, tester wrote:> Yes, a T5220.
You''re printing the thread ID, which is good.  But, suppose thre thread
in question gets re-scheduled on a different processor (or hw thread).

DTrace has a per-CPU trace log...  You can see how such re-ordering
might happen :)

Nico
--

tester

2009-Dec-21 19:58 UTC

head link

[dtrace-discuss] probe order

> You''re printing the thread ID, which is good.  But,
> suppose thre thread
> in question gets re-scheduled on a different
> processor (or hw thread).
> 
> DTrace has a per-CPU trace log...  You can see how
> such re-ordering
> might happen :)
I am lost, I thought the probe was enabled on all CPU''s.

2009 Dec 18 19:45:31 thread 0x2a1065d9ca0 leaving -> this means thread
0x2a1065d9ca0 executed spa_sync:return and that thread''s local variable
"t" should be ''0''. and the second spa_sync:enter has
a predicate
/self->t == 1 && self->prevtime > 0/ and should not run the 2nd
spa_sync:enter unless the 1st spa_sync:enter runs in which case it should print
"thread enter" message.

Of-course I don''t understand it well enough. Thanks for the time.
-- 
This message posted from opensolaris.org

Michael Ernest

2009-Dec-21 21:32 UTC

head link

[dtrace-discuss] probe order

Since DTrace buffers the information on a per-CPU basis, there''s a
chance on a multi-sumpn system that the buffers may be consumed out of turn.
Your exiting stuff is recorded later, but every once in a while the buffer it
was written to is consumed first, and so it looks like the events themselves
occur out of turn.

If you add a nanosecond timestamps to your actions, I''m sure
you''ll see that they fired in the correct time order.
-- 
This message posted from opensolaris.org

dtrace discuss - Dec 2009 - probe order

[dtrace-discuss] probe order

[dtrace-discuss] probe order

[dtrace-discuss] probe order

[dtrace-discuss] probe order

[dtrace-discuss] probe order

[dtrace-discuss] probe order