James Siler
2009-May-26 20:32 UTC
[dtrace-discuss] Losing self-> variables set to timestamp and vtimestamp
Sorry to post this in multiple forums. I posted it earlier in a Sun forum
before noticing an admonision to post to this forum.
That said ...
When running the following code I seem to lose the setting to self->t,
self->t2, self->v, and self->v2. Looking at the output, they all seem
to get set properly at BEGIN, but the first time we fire a probe they are all
reset to zero.
If I use global variables instead of thread locals, everything seems fine (see
dummy2.d and output2, below).
I know I''m probably doing something dumb, but I''ll be damned
if I can see what.
dummy.cpp
=========
#include "myprobes.h"
#include <sys/sdt.h>
#include <iostream>
using namespace std;
void func1(int level)
{
//cout << "func 1 called with " << level << endl;
DUMMY_DO_FUNC1(level);
if(level--)
func1(level);
return;
}
int main(void)
{
DUMMY_CALL_FUNC1_1(10);
//cout << "calling func 1 [1st] with " << 10 <<
endl;
func1(10);
DUMMY_CALL_FUNC1_2(10);
//cout << "calling func 1 [2nd] with " << 10 <<
endl;
func1(10);
char c;
cin >> c;
return 0;
}
=========
myprobes.d
=========
provider dummy
{
probe do_func1(int);
probe call_func1_1(int);
probe call_func1_2(int);
};
#pragma D attributes Evolving/Evolving/Common provider dummy provider
#pragma D attributes Evolving/Evolving/Common provider dummy module
#pragma D attributes Evolving/Evolving/Common provider dummy function
#pragma D attributes Evolving/Evolving/Common provider dummy name
#pragma D attributes Evolving/Evolving/Common provider dummy args
=========
build process
=========[20090526-09:36][jsiler at njdev-x86-app1:~/tmp]$ rm *.o *.h
[20090526-09:36][jsiler at njdev-x86-app1:~/tmp]$ make
dtrace -h -s myprobes.d
CC -V -O0 -c dummy.cpp
CC: Sun Ceres C++ 5.10 SunOS_i386 2009/03/06
ccfe: Sun Ceres C++ 5.10 SunOS_i386 2009/03/06
ir2hf: Sun Ceres Compiler Common 12.1 SunOS_i386 2009/03/06
ube: Sun Ceres Compiler Common 12.1 SunOS_i386 2009/03/06
as: Sun Ceres Compiler Common 12.1 SunOS_i386 2009/03/06
dtrace -G -32 -s myprobes.d dummy.o
CC -V -O0 -o dummy dummy.o myprobes.o
CC: Sun Ceres C++ 5.10 SunOS_i386 2009/03/06
/opt/SSX0903/prod/bin/c++filt: Sun Ceres C++ 5.10 SunOS_i386 2009/03/06
ld: Software Generation Utilities - Solaris Link Editors: 5.10-1.486
[20090526-09:36][jsiler at njdev-x86-app1:~/tmp]$
=========
dummy.d
=========
BEGIN
{
self->vt=vtimestamp;
self->vt2=vtimestamp;
self->t=timestamp;
self->t2=timestamp;
printf("%d, %d, %d, %d, %d, %d\n", timestamp, self->vt,
self->vt2, self->t, self->t2, tid);
}
dummy$target::main:
{
this->vt=vtimestamp-self->vt;
this->vt2=vtimestamp-self->vt2;
this->t=timestamp-self->t;
this->t2=timestamp-self->t2;
printf("%d, %d, %d, %d, %d, %d, %d, %d, %d, %d, %d\n",
timestamp,
vtimestamp,
self->t,
self->t2,
self->vt,
self->vt2,
this->t,
this->t2,
this->vt,
this->vt2,
tid);
printf( "%4d.%09d (%4d.%09d), %4d.%09d (%4d.%09d), %s %d\n",
this->vt/1000000000,
this->vt%1000000000,
this->vt2/1000000000,
this->vt2%1000000000,
this->t/1000000000,
this->t%1000000000,
this->t2/1000000000,
this->t2%1000000000,
probefunc,
arg0);
self->vt2=vtimestamp;
self->t2=timestamp;
}
=========
output
=========
[20090526-09:36][jsiler at njdev-x86-app1:~/tmp]$ dtrace -s dummy.d -q -c
./dummy
2748299975446053, 1, 1, 2748299975446053, 2748299975446053, 1
2748299977369523, 1108655, 0, 0, 0, 0, 2748299977369523, 2748299977369523,
1108655, 1108655, 1
0.001108655 ( 0.001108655), 2748299.977369523 (2748299.977369523), main 10
2748299977395941, 1110294, 0, 2748299977369523, 0, 1108655, 2748299977395941,
26418, 1110294, 1639, 1
0.001110294 ( 0.000001639), 2748299.977395941 ( 0.000026418), main 10
dummy2.d
=========
BEGIN
{
vt=vtimestamp;
vt2=vtimestamp;
t=timestamp;
t2=timestamp;
printf("%d, %d, %d, %d, %d, %d\n", timestamp, vt, vt2, t, t2,
tid);
}
dummy$target::main:
{
this->vt=vtimestamp-vt;
this->vt2=vtimestamp-vt2;
this->t=timestamp-t;
this->t2=timestamp-t2;
printf("%d, %d, %d, %d, %d, %d, %d, %d, %d, %d, %d\n",
timestamp,
vtimestamp,
t,
t2,
vt,
vt2,
this->t,
this->t2,
this->vt,
this->vt2,
tid);
printf( "%4d.%09d (%4d.%09d), %4d.%09d (%4d.%09d), %s %d\n",
this->vt/1000000000,
this->vt%1000000000,
this->vt2/1000000000,
this->vt2%1000000000,
this->t/1000000000,
this->t%1000000000,
this->t2/1000000000,
this->t2%1000000000,
probefunc,
arg0);
vt2=vtimestamp;
t2=timestamp;
}
=========
output2
=========2748450558395934, 1, 1, 2748450558395934, 2748450558395934, 1
2748450560332692, 1162784, 2748450558395934, 2748450558395934, 1, 1, 1936758,
1936758, 1162783, 1162783, 1
0.001162783 ( 0.001162783), 0.001936758 ( 0.001936758), main 10
2748450560355846, 1164842, 2748450558395934, 2748450560332692, 1, 1162784,
1959912, 23154, 1164841, 2058, 1
0.001164841 ( 0.000002058), 0.001959912 ( 0.000023154), main 10
=========
I am sooooo confused.
Jim Siler
--
This message posted from opensolaris.org
-------------- next part --------------
A non-text attachment was scrubbed...
Name: dummy.cpp
Type: application/octet-stream
Size: 474 bytes
Desc: not available
URL:
<http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20090526/92dfbe63/attachment.obj>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: dummy.d
Type: application/octet-stream
Size: 883 bytes
Desc: not available
URL:
<http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20090526/92dfbe63/attachment-0001.obj>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: myprobes.d
Type: application/octet-stream
Size: 436 bytes
Desc: not available
URL:
<http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20090526/92dfbe63/attachment-0002.obj>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: Makefile
Type: application/octet-stream
Size: 267 bytes
Desc: not available
URL:
<http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20090526/92dfbe63/attachment-0003.obj>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: output
Type: application/octet-stream
Size: 418 bytes
Desc: not available
URL:
<http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20090526/92dfbe63/attachment-0004.obj>
Jonathan Adams
2009-May-26 20:43 UTC
[dtrace-discuss] Losing self-> variables set to timestamp and vtimestamp
On Tue, May 26, 2009 at 01:32:56PM -0700, James Siler wrote:> Sorry to post this in multiple forums. I posted it earlier in a Sun > forum before noticing an admonision to post to this forum. > > That said ... > > When running the following code I seem to lose the setting to self->t, > self->t2, self->v, and self->v2. Looking at the output, they all seem > to get set properly at BEGIN, but the first time we fire a probe they > are all reset to zero. > > If I use global variables instead of thread locals, everything seems > fine (see dummy2.d and output2, below). > > I know I''m probably doing something dumb, but I''ll be damned if I can > see what.The BEGIN probe fires in an unspecified thread''s context. That thread will almost certainly not be a thread in your program. You can''t set up thread-local variables in BEGIN; you have to set them up the first time you use them. In this case, you could just change "BEGIN" to "dummy$target::main:entry" (so that it fires before any of your other probes, and everything should work. Cheers, - jonathan
Ryan Johnson
2009-May-26 21:49 UTC
[dtrace-discuss] Losing self-> variables set to timestamp and vtimestamp
Hi Jim, AFAIK, BEGIN runs in the dtrace process context, not the traced process; because of that whatever self->* you set in BEGIN will not be the same self->* available from main(). I think you''re stuck with globals on this one. Regards, Ryan James Siler wrote:> Sorry to post this in multiple forums. I posted it earlier in a Sun forum before noticing an admonision to post to this forum. > > That said ... > > When running the following code I seem to lose the setting to self->t, self->t2, self->v, and self->v2. Looking at the output, they all seem to get set properly at BEGIN, but the first time we fire a probe they are all reset to zero. > > If I use global variables instead of thread locals, everything seems fine (see dummy2.d and output2, below). > > I know I''m probably doing something dumb, but I''ll be damned if I can see what. > > dummy.cpp > =========> > #include "myprobes.h" > #include <sys/sdt.h> > #include <iostream> > > using namespace std; > > void func1(int level) > { > //cout << "func 1 called with " << level << endl; > DUMMY_DO_FUNC1(level); > if(level--) > func1(level); > return; > } > int main(void) > { > DUMMY_CALL_FUNC1_1(10); > //cout << "calling func 1 [1st] with " << 10 << endl; > func1(10); > DUMMY_CALL_FUNC1_2(10); > //cout << "calling func 1 [2nd] with " << 10 << endl; > func1(10); > char c; > cin >> c; > return 0; > } > =========> > myprobes.d > =========> > provider dummy > { > probe do_func1(int); > probe call_func1_1(int); > probe call_func1_2(int); > }; > > #pragma D attributes Evolving/Evolving/Common provider dummy provider > #pragma D attributes Evolving/Evolving/Common provider dummy module > #pragma D attributes Evolving/Evolving/Common provider dummy function > #pragma D attributes Evolving/Evolving/Common provider dummy name > #pragma D attributes Evolving/Evolving/Common provider dummy args > =========> > build process > =========> [20090526-09:36][jsiler at njdev-x86-app1:~/tmp]$ rm *.o *.h > [20090526-09:36][jsiler at njdev-x86-app1:~/tmp]$ make > dtrace -h -s myprobes.d > CC -V -O0 -c dummy.cpp > CC: Sun Ceres C++ 5.10 SunOS_i386 2009/03/06 > ccfe: Sun Ceres C++ 5.10 SunOS_i386 2009/03/06 > ir2hf: Sun Ceres Compiler Common 12.1 SunOS_i386 2009/03/06 > ube: Sun Ceres Compiler Common 12.1 SunOS_i386 2009/03/06 > as: Sun Ceres Compiler Common 12.1 SunOS_i386 2009/03/06 > dtrace -G -32 -s myprobes.d dummy.o > CC -V -O0 -o dummy dummy.o myprobes.o > CC: Sun Ceres C++ 5.10 SunOS_i386 2009/03/06 > /opt/SSX0903/prod/bin/c++filt: Sun Ceres C++ 5.10 SunOS_i386 2009/03/06 > ld: Software Generation Utilities - Solaris Link Editors: 5.10-1.486 > [20090526-09:36][jsiler at njdev-x86-app1:~/tmp]$ > =========> > dummy.d > =========> > BEGIN > { > self->vt=vtimestamp; > self->vt2=vtimestamp; > self->t=timestamp; > self->t2=timestamp; > printf("%d, %d, %d, %d, %d, %d\n", timestamp, self->vt, self->vt2, self->t, self->t2, tid); > } > > > dummy$target::main: > { > this->vt=vtimestamp-self->vt; > this->vt2=vtimestamp-self->vt2; > this->t=timestamp-self->t; > this->t2=timestamp-self->t2; > printf("%d, %d, %d, %d, %d, %d, %d, %d, %d, %d, %d\n", > timestamp, > vtimestamp, > self->t, > self->t2, > self->vt, > self->vt2, > this->t, > this->t2, > this->vt, > this->vt2, > tid); > > printf( "%4d.%09d (%4d.%09d), %4d.%09d (%4d.%09d), %s %d\n", > this->vt/1000000000, > this->vt%1000000000, > this->vt2/1000000000, > this->vt2%1000000000, > this->t/1000000000, > this->t%1000000000, > this->t2/1000000000, > this->t2%1000000000, > probefunc, > arg0); > self->vt2=vtimestamp; > self->t2=timestamp; > } > =========> > output > =========> > [20090526-09:36][jsiler at njdev-x86-app1:~/tmp]$ dtrace -s dummy.d -q -c ./dummy > 2748299975446053, 1, 1, 2748299975446053, 2748299975446053, 1 > 2748299977369523, 1108655, 0, 0, 0, 0, 2748299977369523, 2748299977369523, 1108655, 1108655, 1 > 0.001108655 ( 0.001108655), 2748299.977369523 (2748299.977369523), main 10 > 2748299977395941, 1110294, 0, 2748299977369523, 0, 1108655, 2748299977395941, 26418, 1110294, 1639, 1 > 0.001110294 ( 0.000001639), 2748299.977395941 ( 0.000026418), main 10 > > dummy2.d > =========> > BEGIN > { > vt=vtimestamp; > vt2=vtimestamp; > t=timestamp; > t2=timestamp; > printf("%d, %d, %d, %d, %d, %d\n", timestamp, vt, vt2, t, t2, tid); > } > > > dummy$target::main: > { > this->vt=vtimestamp-vt; > this->vt2=vtimestamp-vt2; > this->t=timestamp-t; > this->t2=timestamp-t2; > printf("%d, %d, %d, %d, %d, %d, %d, %d, %d, %d, %d\n", > timestamp, > vtimestamp, > t, > t2, > vt, > vt2, > this->t, > this->t2, > this->vt, > this->vt2, > tid); > > printf( "%4d.%09d (%4d.%09d), %4d.%09d (%4d.%09d), %s %d\n", > this->vt/1000000000, > this->vt%1000000000, > this->vt2/1000000000, > this->vt2%1000000000, > this->t/1000000000, > this->t%1000000000, > this->t2/1000000000, > this->t2%1000000000, > probefunc, > arg0); > vt2=vtimestamp; > t2=timestamp; > } > =========> > output2 > =========> 2748450558395934, 1, 1, 2748450558395934, 2748450558395934, 1 > 2748450560332692, 1162784, 2748450558395934, 2748450558395934, 1, 1, 1936758, 1936758, 1162783, 1162783, 1 > 0.001162783 ( 0.001162783), 0.001936758 ( 0.001936758), main 10 > 2748450560355846, 1164842, 2748450558395934, 2748450560332692, 1, 1162784, 1959912, 23154, 1164841, 2058, 1 > 0.001164841 ( 0.000002058), 0.001959912 ( 0.000023154), main 10 > =========> > I am sooooo confused. > > Jim Siler > > ------------------------------------------------------------------------ > > This body part will be downloaded on demand.