Anatoli
2008-Oct-08 16:41 UTC
[dtrace-discuss] gettimeofday''s dtarce probe not triggered (?)
Hi, All
Below is some data and a questions is ''why I do not see gettimeofday
with truss & dtrace, but pstack'' ?
(NOTE: I am on the global container, not in zone)
PS: when running, gettimeofday consumes whole CPU
1) # uname -a
SunOS *** 5.10 Generic_127112-11 i86pc i386 i86pc Solaris
2) # cat gettimeofday.c
#include <sys/time.h>
int main( int argc, char* argv[] ){
struct timeval tv;
while( 1 )
gettimeofday( &tv, 0 );
}
3) # gcc -g -O0 -o gettimeofday gettimeofday.c
4) # date ; truss ./gettimeofday ; date
Wednesday, October 8, 2008 12:31:17 PM EDT
execve("gettimeofday", 0x08047CD0, 0x08047CD8) argc = 1
resolvepath("/usr/lib/ld.so.1", "/lib/ld.so.1", 1023) = 12
getcwd("/root/DT-astanko", 1010) = 0
resolvepath("/root/DT-astanko/gettimeofday",
"/root/DT-astanko/gettimeofday", 1023) = 29
sysconfig(_CONFIG_PAGESIZE) = 4096
xstat(2, "/root/DT-astanko/gettimeofday", 0x08047AA8) = 0
open("/var/ld/ld.config", O_RDONLY) = 3
fxstat(2, 3, 0x080479E8) = 0
mmap(0x00000000, 140, PROT_READ, MAP_SHARED, 3, 0) = 0xFEFC0000
close(3) = 0
mmap(0x00000000, 4096, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_ANON, -1,
0) = 0xFEFB0000
xstat(2, "/lib/libc.so.1", 0x080472D8) = 0
resolvepath("/lib/libc.so.1", "/lib/libc.so.1", 1023) = 14
open("/lib/libc.so.1", O_RDONLY) = 3
mmap(0x00010000, 32768, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_ALIGN, 3, 0) =
0xFEFA0000
mmap(0x00010000, 876544, PROT_NONE,
MAP_PRIVATE|MAP_NORESERVE|MAP_ANON|MAP_ALIGN, -1, 0) = 0xFEEC0000
mmap(0xFEEC0000, 772077, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_TEXT, 3,
0) = 0xFEEC0000
mmap(0xFEF8D000, 27239, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_INITDATA, 3, 774144) = 0xFEF8D000
mmap(0xFEF94000, 5392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANON, -1,
0) = 0xFEF94000
munmap(0xFEF7D000, 65536) = 0
memcntl(0xFEEC0000, 123384, MC_ADVISE, MADV_WILLNEED, 0, 0) = 0
close(3) = 0
mmap(0x00010000, 24576, PROT_READ|PROT_WRITE|PROT_EXEC,
MAP_PRIVATE|MAP_ANON|MAP_ALIGN, -1, 0) = 0xFEEB0000
munmap(0xFEFA0000, 32768) = 0
getcontext(0x08047860)
getrlimit(RLIMIT_STACK, 0x08047858) = 0
getpid() = 18738 [18737]
lwp_private(0, 1, 0xFEEB2A00) = 0x000001C3
setustack(0xFEEB2A60)
sysi86(SI86FPSTART, 0xFEF94BC0, 0x0000133F, 0x00001F80) = 0x00000001
^C Received signal #2, SIGINT [default]
Wednesday, October 8, 2008 12:31:26 PM EDT
5) # dtrace -l | grep gettimeofday
13691 fbt genunix gettimeofday entry
13692 fbt genunix gettimeofday return
47531 syscall gettimeofday entry
47532 syscall gettimeofday return
6) # date ; dtrace -vn
''syscall::gettimeofday:entry{trace("gettimeofday:entry");}''
; date
Wednesday, October 8, 2008 12:36:23 PM EDT
dtrace: description ''syscall::gettimeofday:entry'' matched 1
probe
Stability attributes for description syscall::gettimeofday:entry:
Minimum Probe Description Attributes
Identifier Names: Private
Data Semantics: Private
Dependency Class: ISA
Minimum Statement Attributes
Identifier Names: Stable
Data Semantics: Stable
Dependency Class: Common
^C
Wednesday, October 8, 2008 12:36:30 PM EDT
7) # pstack `pgrep gettimeofday`
19500: ./gettimeofday
fef65137 gettimeofday (80506f0, 1, 8047cd0) + 7
080506f0 _start (1, 8047da4, 0, 8047db3, 8047df4, 8047e0c) + 80
--
This message posted from opensolaris.org
Andrew Gabriel
2008-Oct-08 17:17 UTC
[dtrace-discuss] gettimeofday''s dtarce probe not triggered (?)
Anatoli wrote:> Hi, All > Below is some data and a questions is ''why I do not see gettimeofday with truss & dtrace, but pstack'' ? > (NOTE: I am on the global container, not in zone) > > PS: when running, gettimeofday consumes whole CPU >Looking through the source, I don''t think gettimeofday() results in any syscalls -- at least on some architectures, it looks like it''s simply read out of user-accessible CPU registers and then scaled appropriately. Using "truss -u::" you can see the gettimeofday() libc call. -- Andrew
Rayson Ho
2008-Oct-08 17:43 UTC
[dtrace-discuss] gettimeofday''s dtarce probe not triggered (?)
gettimeofday is a "fast trap system call" (T_FASTTRAP). The kernel does not save all the state (registers, for example) that a normal system call entry point performs. And I believe the kernel entry point for fast trap system calls does not trigger the DTrace probe. The reason why you see gettimeofday() in pstack is because it gettimeofday() is still a proper function, which has the stack frame and other context information for pstack to recognize it when looking at the process'' stack frame. Rayson P.S. Anatoli, you are in the Toronto office? Please send my greetings to Prof Stumm! On 10/8/08, Anatoli <astanko at oanda.com> wrote:> Hi, All > Below is some data and a questions is ''why I do not see gettimeofday with truss & dtrace, but pstack'' ? > (NOTE: I am on the global container, not in zone) > > PS: when running, gettimeofday consumes whole CPU > > 1) # uname -a > SunOS *** 5.10 Generic_127112-11 i86pc i386 i86pc Solaris > 2) # cat gettimeofday.c > #include <sys/time.h> > > int main( int argc, char* argv[] ){ > struct timeval tv; > > while( 1 ) > gettimeofday( &tv, 0 ); > } > 3) # gcc -g -O0 -o gettimeofday gettimeofday.c > 4) # date ; truss ./gettimeofday ; date > Wednesday, October 8, 2008 12:31:17 PM EDT > execve("gettimeofday", 0x08047CD0, 0x08047CD8) argc = 1 > resolvepath("/usr/lib/ld.so.1", "/lib/ld.so.1", 1023) = 12 > getcwd("/root/DT-astanko", 1010) = 0 > resolvepath("/root/DT-astanko/gettimeofday", "/root/DT-astanko/gettimeofday", 1023) = 29 > sysconfig(_CONFIG_PAGESIZE) = 4096 > xstat(2, "/root/DT-astanko/gettimeofday", 0x08047AA8) = 0 > open("/var/ld/ld.config", O_RDONLY) = 3 > fxstat(2, 3, 0x080479E8) = 0 > mmap(0x00000000, 140, PROT_READ, MAP_SHARED, 3, 0) = 0xFEFC0000 > close(3) = 0 > mmap(0x00000000, 4096, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_ANON, -1, 0) = 0xFEFB0000 > xstat(2, "/lib/libc.so.1", 0x080472D8) = 0 > resolvepath("/lib/libc.so.1", "/lib/libc.so.1", 1023) = 14 > open("/lib/libc.so.1", O_RDONLY) = 3 > mmap(0x00010000, 32768, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_ALIGN, 3, 0) = 0xFEFA0000 > mmap(0x00010000, 876544, PROT_NONE, MAP_PRIVATE|MAP_NORESERVE|MAP_ANON|MAP_ALIGN, -1, 0) = 0xFEEC0000 > mmap(0xFEEC0000, 772077, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_TEXT, 3, 0) = 0xFEEC0000 > mmap(0xFEF8D000, 27239, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_INITDATA, 3, 774144) = 0xFEF8D000 > mmap(0xFEF94000, 5392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANON, -1, 0) = 0xFEF94000 > munmap(0xFEF7D000, 65536) = 0 > memcntl(0xFEEC0000, 123384, MC_ADVISE, MADV_WILLNEED, 0, 0) = 0 > close(3) = 0 > mmap(0x00010000, 24576, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_ANON|MAP_ALIGN, -1, 0) = 0xFEEB0000 > munmap(0xFEFA0000, 32768) = 0 > getcontext(0x08047860) > getrlimit(RLIMIT_STACK, 0x08047858) = 0 > getpid() = 18738 [18737] > lwp_private(0, 1, 0xFEEB2A00) = 0x000001C3 > setustack(0xFEEB2A60) > sysi86(SI86FPSTART, 0xFEF94BC0, 0x0000133F, 0x00001F80) = 0x00000001 > ^C Received signal #2, SIGINT [default] > Wednesday, October 8, 2008 12:31:26 PM EDT > 5) # dtrace -l | grep gettimeofday > 13691 fbt genunix gettimeofday entry > 13692 fbt genunix gettimeofday return > 47531 syscall gettimeofday entry > 47532 syscall gettimeofday return > 6) # date ; dtrace -vn ''syscall::gettimeofday:entry{trace("gettimeofday:entry");}'' ; date > Wednesday, October 8, 2008 12:36:23 PM EDT > dtrace: description ''syscall::gettimeofday:entry'' matched 1 probe > > Stability attributes for description syscall::gettimeofday:entry: > > Minimum Probe Description Attributes > Identifier Names: Private > Data Semantics: Private > Dependency Class: ISA > > Minimum Statement Attributes > Identifier Names: Stable > Data Semantics: Stable > Dependency Class: Common > > ^C > > Wednesday, October 8, 2008 12:36:30 PM EDT > 7) # pstack `pgrep gettimeofday` > 19500: ./gettimeofday > fef65137 gettimeofday (80506f0, 1, 8047cd0) + 7 > 080506f0 _start (1, 8047da4, 0, 8047db3, 8047df4, 8047e0c) + 80 > -- > This message posted from opensolaris.org > _______________________________________________ > dtrace-discuss mailing list > dtrace-discuss at opensolaris.org >
Anatoli
2008-Oct-08 17:47 UTC
[dtrace-discuss] gettimeofday''s dtarce probe not triggered (?)
Hi, Andrew. truss shows gettimeofday *calls* with -u:: option - thanks for pointing this out! but what do I do with dtrace ? My confusion is: dtrace -l shows the probe for gettimeofday, but how do I hook to it ? and if I can not (well - would want to but will survive), why it is shown ?.. Is it possible that this behavior is due to misconfiguration somewhere ? Thanks again! (one questions is definitely cleared!) -- This message posted from opensolaris.org
Anatoli
2008-Oct-08 17:55 UTC
[dtrace-discuss] gettimeofday''s dtarce probe not triggered (?)
Many Thanks to all for the clarification! (All questions have been answered) -- This message posted from opensolaris.org
Anatoli
2008-Oct-08 18:02 UTC
[dtrace-discuss] gettimeofday''s dtarce probe not triggered (?)
Thanks, Rayson I think to avoid this types of confusions gettimeofday''s probe should not even be listed: i.e. only whose probes that I can hook on should be shown by dtrace -l Thanks for the clarification Anatoli PS: greetings have been *delivered*: you are "welcome to drop by when have a chance" :-) -- This message posted from opensolaris.org
Adam Leventhal
2008-Oct-08 18:12 UTC
[dtrace-discuss] gettimeofday''s dtarce probe not triggered (?)
> I think to avoid this types of confusions gettimeofday''s probe should not even be listed: > i.e. only whose probes that I can hook on should be shown by dtrace -ldtrace -l lists all the probes on the system. There''s a syscall provider probe for gettimeofday because there''s a corresponding system call. It just so happens that there''s a fasttrap that has supplanted it (the system call remains for legacy binaries). DTrace will let you trace system activity; in this case it''s doing exactly the right thing in that the probe you''ve asked to trace isn''t firing because that system call isn''t being invoked. Adam -- Adam Leventhal, Fishworks http://blogs.sun.com/ahl
Casper.Dik at Sun.COM
2008-Oct-08 18:19 UTC
[dtrace-discuss] gettimeofday''s dtarce probe not triggered (?)
>Thanks, Rayson >I think to avoid this types of confusions gettimeofday''s probe should not even be listed: > i.e. only whose probes that I can hook on should be shown by dtrace -lOh, dtrace can certainly "hook" on gettimeofday(); the problem is that the libc will never call it. The implementation of gettimeofday() is using the fasttrap but we kept the old gettimeoday() syscall for older binaries. Casper