Hans,
This is a bug in the OS X dtrace:
<rdar://problem/7037927> 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 <james.ma...@oracle.com> 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 ID FUNCTION: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 28571 sysconf: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
> 0 28728 pthread_key_delete:entry
> 0 126037 __tcf_0:entry
> 0 29716 _cleanup:entry
> 0 29717 _fwalk:entry
> 0 29643 __sflush:entry
> 0 29643 __sflush:entry
> 0 29643 __sflush:entry
> 0 28729 _exit:entry
> 2 50753 cerror:entry
> 2 28752 cthread_set_errno_self:entry
> 2 28614 __error:entry
> 2 28614 __error:entry
> 2 28463 stub helpers:entry
> 2 51054 dyld_stub_binder:entry
> 2 28697 _dyld_fast_stub_entry(void*, long):entry
> 2 27717 dyld::fastBindLazySymbol(ImageLoader**, unsigned long):entry
> 2 28106 ImageLoaderMachOCompressed::doBindFastLazySymbol(unsigned int,
> ImageLoader::LinkContext const&):entry
> 2 28010 ImageLoaderMachO::segActualLoadAddress(unsigned int) const:entry
> 2 28074 ImageLoaderMachOCompressed::segmentCommandOffsets() const:entry
> 2 28090 ImageLoaderMachOCompressed::resolve(ImageLoader::LinkContext
> const&, char const*, unsigned char, int, ImageLoader const**, Imag:entry
> 2 28075 ImageLoaderMachOCompressed::libImage(unsigned int) const:entry
> 2 28088
> ImageLoaderMachOCompressed::resolveTwolevel(ImageLoader::LinkContext const&,
> ImageLoader const*, bool, char const*, ImageLoader:entry
> 2 28002 ImageLoaderMachO::findExportedSymbol(char const*, bool,
> ImageLoader const**) const:entry
> 2 28102 ImageLoaderMachOCompressed::findExportedSymbol(char const*,
> ImageLoader const**) const:entry
>
> On Dec 7, 2010, at 5:09 PM, Hans Stimer wrote:
>
>> Thank you for the quick response. I tried a number of things and got some
>> interesting results. In short:
>>
>> 1) pid doesn't work with -c date, but does seem to work with other
>> executables. On osx date is an executable and not a script or built in.
>> 2) pid doesn't let you instrument all entries; I created a hello world
>> program and dtrace didn't return for over 5 minutes
>>
>> * Modify to point to hello world program:
>> $ sudo dtrace -n 'pid$target:::entry { trace(arg0); }' -c ./out
>> dtrace: description 'pid$target:::entry ' matched 7947 probes
>> ^C
>> I gave it over 5 minutes and it didn't return
>>
>> * Trace everything connected to date:
>> $ sudo dtrace -n 'pid$target:::entry { trace(arg0); }' -c date
>> Tue Dec 7 13:49:34 PST 2010
>> dtrace: invalid probe specifier pid$target:::entry { trace(arg0); }: failed
>> to create entry probe for 'stub_binding_helper': No such process
>>
>> * Find entry points for date
>> $ sudo dtrace -ln 'pid$target:::entry,pid$target:::return' -c date
>> Tue Dec 7 13:52:55 PST 2010
>> dtrace: invalid probe specifier pid$target:::entry,pid$target:::return:
>> failed to create entry probe for 'stub_binding_helper': No such process
>>
>> * Find entry points for hello world program:
>> $ sudo dtrace -ln 'pid$target:::entry,pid$target:::return' -c ./out
>> ID PROVIDER MODULE FUNCTION NAME
>> 144623 pid95634 dyld stub_binding_helper entry
>> 144624 pid95634 dyld dyld_func_lookup entry
>> 144625 pid95634 dyld offset_to_dyld_all_image_infos entry
>> 144626 pid95634 dyld _dyld_start entry
>> 144627 pid95634 dyld dyld_fatal_error entry
>> .
>> .
>> .
>>
>> * Find entry points for top:
>> $ sudo dtrace -ln 'pid$target:::entry,pid$target:::return' -c top
>> ID PROVIDER MODULE FUNCTION NAME
>> 36684 pid95691 dyld _dyld_start entry
>> 36685 pid95691 dyld std::vector<dyld_image_info,
>> std::allocator<dyld_image_info>
>> >::erase(__gnu_cxx::__normal_iterator<dyld_image_info*, std::vecto entry
>> 36686 pid95691 dyld std::_Vector_base<dyld_image_info,
>> std::allocator<dyld_image_info> >::~_Vector_base() entry
>> 36687 pid95691 dyld dyld_fatal_error entry
>> .
>> .
>> .
>>
>>
>>
>> On Tue, Dec 7, 2010 at 12:27 PM, Jim Mauro <james.ma...@oracle.com> wrote:
>>
>> 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 mailing list
dtrace-discuss@opensolaris.org
