Re: [dtrace-discuss] pid probes fail on OSX
Hans,
This is a bug in the OS X dtrace:
Dtrace finishes execution of binary before
creating probes when using -c option
There is a "workaround" of sorts, which is adding the following flags:
-xevaltime=exec -Z
That tells dtrace to start tracing from the very beginning of the
target process spawn, which is why you need the -Z flag, because the process
will not have loaded any libraries at that time, and normally probes won't be
matching that are expected to match.
In your case, using pid$target:::entry, you might get away with the -Z
flag :-)
James M
On Dec 7, 2010, at 8:28 PM, Hans Stimer wrote:
> Interesting. My expectation was that it would work like gdb i.e. that the app
> would not run until gdb was in full control. For me, -c implies that behavior.
>
> I tried putting in a sleep for 10 seconds; still nothing:
>
> $ sudo dtrace -n 'pid$target:::entry { trace(arg0); }' -c ./out
>
> On Tue, Dec 7, 2010 at 6:53 PM, Jim Mauro wrote:
>
> I am cross-posting back to dtrace-discuss, since the Apple folks listen...
>
> I'm not sure what your hello world program is doing. I tried the same thing
> with compiled C code.
>
> The problem I ran into with hello world, and with the date example, is
> the program is executing and completing before dtrace can
> instrument it. Adding a sleep(1); to the hello world program and
> I get expected output.
>
> This does not happen on Solaris. I expect it's due to implementation
> differences in the pid provider between the operating systems.
>
> In any event, it seems on OS X using the pid provider on a binary
> the runs for less than a second does not give the pid provider
> time to instrument the code.
>
> That's not necessarily an issue (at least for me), since I never need
> to chase performance problems on something that runs in
> a few hundred milliseconds
>
> ;^)
>
> /jim
>
> dtrace'ing hello world with a 1 second sleep;
>
> macosx> dtrace -n 'pid$target:::entry' -c ./hw
> dtrace: description 'pid$target:::entry' matched 7950 probes
> Hello World
> dtrace: pid 16109 has exited
> CPU IDFUNCTION:NAME
> 0 27974 ImageLoaderMachO::getExportedSymbolAddress(ImageLoader::Symbol
> const*, ImageLoader::LinkContext const&, ImageLoader const*) con:entry
> 0 27973 ImageLoaderMachO::getSymbolAddress(ImageLoader::Symbol const*,
> ImageLoader const*, ImageLoader::LinkContext const&) const:entry
> 0 28101
> ImageLoaderMachOCompressed::exportedSymbolAddress(ImageLoader::Symbol const*)
> const:entry
> 0 27982 ImageLoaderMachO::bindLocation(ImageLoader::LinkContext const&,
> unsigned long, unsigned long, ImageLoader const*, unsigned char:entry
> 0 30491 puts:entry
> 0 28559 strlen:entry
> 0 28719 __sfvwrite:entry
> 0 29640 __swsetup:entry
> 0 28749__sinit:entry
> 0 28571sysconf:entry
> 0 28750 getrlimit:entry
> 0 28751__getrlimit:entry
> 0 29641 __smakebuf:entry
> 0 29642 __swhatbuf:entry
> 0 28684 fstat$INODE64:entry
> 0 29812 isatty:entry
> 0 28723 ioctl:entry
> 0 28724__ioctl:entry
> 0 28549 malloc:entry
> 0 28574 malloc_zone_malloc:entry
> 0 28575 szone_malloc:entry
> 0 28576 szone_malloc_should_clear:entry
> 0 28640 small_malloc_from_free_list:entry
> 0 28553 allocate_pages:entry
> 0 28554 mmap:entry
> 0 28555 __mmap:entry
> 0 28578 munmap:entry
> 0 28578 munmap:entry
> 0 29393 memchr:entry
> 0 28523 memcpy:entry
> 0 29393 memchr:entry
> 0 28523 memcpy:entry
> 0 29719 __fflush:entry
> 0 29643 __sflush:entry
> 0 29644_swrite:entry
> 0 29645 __swrite:entry
> 0 29646 write$NOCANCEL:entry
> 0 28463 stub helpers:entry
> 0 51054 dyld_stub_binder:entry
> 0 28697 _dyld_fast_stub_entry(void*, long):entry
> 0 27717 dyld::fastBindLazySymbol(ImageLoader**, unsigned long):entry
> 0 28106 ImageLoaderMachOCompressed::doBindFastLazySymbol(unsigned int,
> ImageLoader::LinkContext const&):entry
> 0 28010 ImageLoaderMachO::segActualLoadAddress(unsigned int) const:entry
> 0 28074 ImageLoaderMachOCompressed::segmentCommandOffsets() const:entry
> 0 28090 ImageLoaderMachOCompressed::resolve(ImageLoader::LinkContext
> const&, char const*, unsigned char, int, ImageLoader const**, Imag:entry
> 0 28075 ImageLoaderMachOCompressed::libImage
Re: [dtrace-discuss] pid probes fail on OSX
Interesting. My expectation was that it would work like gdb i.e. that the
app would not run until gdb was in full control. For me, -c implies that
behavior.
I tried putting in a sleep for 10 seconds; still nothing:
$ sudo dtrace -n 'pid$target:::entry { trace(arg0); }' -c ./out
On Tue, Dec 7, 2010 at 6:53 PM, Jim Mauro wrote:
>
> I am cross-posting back to dtrace-discuss, since the Apple folks listen...
>
> I'm not sure what your hello world program is doing. I tried the same thing
> with compiled C code.
>
> The problem I ran into with hello world, and with the date example, is
> the program is executing and completing before dtrace can
> instrument it. Adding a sleep(1); to the hello world program and
> I get expected output.
>
> This does not happen on Solaris. I expect it's due to implementation
> differences in the pid provider between the operating systems.
>
> In any event, it seems on OS X using the pid provider on a binary
> the runs for less than a second does not give the pid provider
> time to instrument the code.
>
> That's not necessarily an issue (at least for me), since I never need
> to chase performance problems on something that runs in
> a few hundred milliseconds
>
> ;^)
>
> /jim
>
> dtrace'ing hello world with a 1 second sleep;
>
> macosx> dtrace -n 'pid$target:::entry' -c ./hw
> dtrace: description 'pid$target:::entry' matched 7950 probes
> Hello World
> dtrace: pid 16109 has exited
> CPU IDFUNCTION:NAME
> 0 27974 ImageLoaderMachO::getExportedSymbolAddress(ImageLoader::Symbol
> const*, ImageLoader::LinkContext const&, ImageLoader const*) con:entry
> 0 27973 ImageLoaderMachO::getSymbolAddress(ImageLoader::Symbol const*,
> ImageLoader const*, ImageLoader::LinkContext const&) const:entry
> 0 28101
> ImageLoaderMachOCompressed::exportedSymbolAddress(ImageLoader::Symbol
> const*) const:entry
> 0 27982 ImageLoaderMachO::bindLocation(ImageLoader::LinkContext const&,
> unsigned long, unsigned long, ImageLoader const*, unsigned char:entry
> 0 30491 puts:entry
> 0 28559 strlen:entry
> 0 28719 __sfvwrite:entry
> 0 29640 __swsetup:entry
> 0 28749__sinit:entry
> 0 28571sysconf:entry
> 0 28750 getrlimit:entry
> 0 28751__getrlimit:entry
> 0 29641 __smakebuf:entry
> 0 29642 __swhatbuf:entry
> 0 28684 fstat$INODE64:entry
> 0 29812 isatty:entry
> 0 28723 ioctl:entry
> 0 28724__ioctl:entry
> 0 28549 malloc:entry
> 0 28574 malloc_zone_malloc:entry
> 0 28575 szone_malloc:entry
> 0 28576 szone_malloc_should_clear:entry
> 0 28640 small_malloc_from_free_list:entry
> 0 28553 allocate_pages:entry
> 0 28554 mmap:entry
> 0 28555 __mmap:entry
> 0 28578 munmap:entry
> 0 28578 munmap:entry
> 0 29393 memchr:entry
> 0 28523 memcpy:entry
> 0 29393 memchr:entry
> 0 28523 memcpy:entry
> 0 29719 __fflush:entry
> 0 29643 __sflush:entry
> 0 29644_swrite:entry
> 0 29645 __swrite:entry
> 0 29646 write$NOCANCEL:entry
> 0 28463 stub helpers:entry
> 0 51054 dyld_stub_binder:entry
> 0 28697 _dyld_fast_stub_entry(void*, long):entry
> 0 27717 dyld::fastBindLazySymbol(ImageLoader**, unsigned long):entry
> 0 28106 ImageLoaderMachOCompressed::doBindFastLazySymbol(unsigned int,
> ImageLoader::LinkContext const&):entry
> 0 28010 ImageLoaderMachO::segActualLoadAddress(unsigned int)
> const:entry
> 0 28074 ImageLoaderMachOCompressed::segmentCommandOffsets() const:entry
> 0 28090 ImageLoaderMachOCompressed::resolve(ImageLoader::LinkContext
> const&, char const*, unsigned char, int, ImageLoader const**, Imag:entry
> 0 28075 ImageLoaderMachOCompressed::libImage(unsigned int) const:entry
> 0 28088
> ImageLoaderMachOCompressed::resolveTwolevel(ImageLoader::LinkContext const&,
> ImageLoader const*, bool, char const*, ImageLoader:entry
> 0 28002 ImageLoaderMachO::findExportedSymbol(char const*, bool,
> ImageLoader const**) const:entry
> 0 28102 ImageLoaderMachOCompressed::findExportedSymbol(char const*,
> ImageLoader const**) const:entry
> 0 27974 ImageLoaderMachO::getExportedSymbolAddress(ImageLoader::Symbol
> const*, ImageLoader::LinkContext const&, ImageLoader const*) con:entry
> 0 27973 ImageLoaderMachO::getSymbolAddress(ImageLoader::Symbol const*,
> ImageLoader const*, ImageLoader::LinkContext const&) const:entry
> 0 28101
> ImageLoaderMachOCompressed::exportedSymbolAddress(Imag
Re: [dtrace-discuss] pid probes fail on OSX
I am cross-posting back to dtrace-discuss, since the Apple folks listen... I'm not sure what your hello world program is doing. I tried the same thing with compiled C code. The problem I ran into with hello world, and with the date example, is the program is executing and completing before dtrace can instrument it. Adding a sleep(1); to the hello world program and I get expected output. This does not happen on Solaris. I expect it's due to implementation differences in the pid provider between the operating systems. In any event, it seems on OS X using the pid provider on a binary the runs for less than a second does not give the pid provider time to instrument the code. That's not necessarily an issue (at least for me), since I never need to chase performance problems on something that runs in a few hundred milliseconds ;^) /jim dtrace'ing hello world with a 1 second sleep; macosx> dtrace -n 'pid$target:::entry' -c ./hw dtrace: description 'pid$target:::entry' matched 7950 probes Hello World dtrace: pid 16109 has exited CPU IDFUNCTION:NAME 0 27974 ImageLoaderMachO::getExportedSymbolAddress(ImageLoader::Symbol const*, ImageLoader::LinkContext const&, ImageLoader const*) con:entry 0 27973 ImageLoaderMachO::getSymbolAddress(ImageLoader::Symbol const*, ImageLoader const*, ImageLoader::LinkContext const&) const:entry 0 28101 ImageLoaderMachOCompressed::exportedSymbolAddress(ImageLoader::Symbol const*) const:entry 0 27982 ImageLoaderMachO::bindLocation(ImageLoader::LinkContext const&, unsigned long, unsigned long, ImageLoader const*, unsigned char:entry 0 30491 puts:entry 0 28559 strlen:entry 0 28719 __sfvwrite:entry 0 29640 __swsetup:entry 0 28749__sinit:entry 0 28571sysconf:entry 0 28750 getrlimit:entry 0 28751__getrlimit:entry 0 29641 __smakebuf:entry 0 29642 __swhatbuf:entry 0 28684 fstat$INODE64:entry 0 29812 isatty:entry 0 28723 ioctl:entry 0 28724__ioctl:entry 0 28549 malloc:entry 0 28574 malloc_zone_malloc:entry 0 28575 szone_malloc:entry 0 28576 szone_malloc_should_clear:entry 0 28640 small_malloc_from_free_list:entry 0 28553 allocate_pages:entry 0 28554 mmap:entry 0 28555 __mmap:entry 0 28578 munmap:entry 0 28578 munmap:entry 0 29393 memchr:entry 0 28523 memcpy:entry 0 29393 memchr:entry 0 28523 memcpy:entry 0 29719 __fflush:entry 0 29643 __sflush:entry 0 29644_swrite:entry 0 29645 __swrite:entry 0 29646 write$NOCANCEL:entry 0 28463 stub helpers:entry 0 51054 dyld_stub_binder:entry 0 28697 _dyld_fast_stub_entry(void*, long):entry 0 27717 dyld::fastBindLazySymbol(ImageLoader**, unsigned long):entry 0 28106 ImageLoaderMachOCompressed::doBindFastLazySymbol(unsigned int, ImageLoader::LinkContext const&):entry 0 28010 ImageLoaderMachO::segActualLoadAddress(unsigned int) const:entry 0 28074 ImageLoaderMachOCompressed::segmentCommandOffsets() const:entry 0 28090 ImageLoaderMachOCompressed::resolve(ImageLoader::LinkContext const&, char const*, unsigned char, int, ImageLoader const**, Imag:entry 0 28075 ImageLoaderMachOCompressed::libImage(unsigned int) const:entry 0 28088 ImageLoaderMachOCompressed::resolveTwolevel(ImageLoader::LinkContext const&, ImageLoader const*, bool, char const*, ImageLoader:entry 0 28002 ImageLoaderMachO::findExportedSymbol(char const*, bool, ImageLoader const**) const:entry 0 28102 ImageLoaderMachOCompressed::findExportedSymbol(char const*, ImageLoader const**) const:entry 0 27974 ImageLoaderMachO::getExportedSymbolAddress(ImageLoader::Symbol const*, ImageLoader::LinkContext const&, ImageLoader const*) con:entry 0 27973 ImageLoaderMachO::getSymbolAddress(ImageLoader::Symbol const*, ImageLoader const*, ImageLoader::LinkContext const&) const:entry 0 28101 ImageLoaderMachOCompressed::exportedSymbolAddress(ImageLoader::Symbol const*) const:entry 0 27982 ImageLoaderMachO::bindLocation(ImageLoader::LinkContext const&, unsigned long, unsigned long, ImageLoader const*, unsigned char:entry 0 28726 exit:entry 0 28727 __cxa_finalize:entry 0 27719 dyld::runTerminators(void*):entry 0 27701 dyld::notifyBatchPartial(dyld_image_states, bool, char const* (*)(dyld_image_states, unsigned int, dyld_image_info const*)):entry
Re: [dtrace-discuss] pid probes fail on OSX
When you say "straight from the dtrace book", I assume you mean
the soon-to-be-published book?
If that is the case, please allow me to clarify. Not every invocation of dtrace,
both one-liners and scripts, that are in the book (and there are hundreds) is
tested and guaranteed to work under all three operating systems
(Solaris, OS X, FreeBSD). In fact, some will not work across different Solaris
releases, depending on (for example) which provider is used.
We are very clear in the book with our examples about the differences in
the underlying implementations. There are a great many scripts and one-liners
in the book that will only work on Solaris.
The good news is that, in addition to the actual examples, there is a lot of
emphasis on methodology in the book, such that you can use DTrace
to figure out which probes/modules, etc, you should be instrumenting
based on the problem you are trying to solve or what you are trying
to observe.
For example, if you change your D to;
pid$target:::entry { @[probemod] = count(); }'
You will see what the actual module names are available for you
to instrument.
Binaries on OS X link to libSystem.B.dylib for common functions.
Thanks
/jim
On Dec 7, 2010, at 3:09 PM, Hans Stimer wrote:
> Under osx 10.6.5:
>
> ~ $ sudo dtrace -n 'pid$target:libc::entry { @[probefunc] = count(); }' -c
> date
> Tue Dec 7 11:40:59 PST 2010
> dtrace: invalid probe specifier pid$target:libc::entry { @[probefunc] =
> count(); }: probe description pid94942:libc::entry does not match any probes
>
> This is an example straight from the dtrace book which claims to test under
> osx, so I'm guessing that something broke in osx?
> ___
> dtrace-discuss mailing list
> dtrace-discuss@opensolaris.org
___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org
[dtrace-discuss] pid probes fail on OSX
Under osx 10.6.5:
~ $ sudo dtrace -n 'pid$target:libc::entry { @[probefunc] = count(); }' -c
date
Tue Dec 7 11:40:59 PST 2010
dtrace: invalid probe specifier pid$target:libc::entry { @[probefunc] =
count(); }: probe description pid94942:libc::entry does not match any probes
This is an example straight from the dtrace book which claims to test under
osx, so I'm guessing that something broke in osx?
___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org
