Re: [dtrace-discuss] pid probes fail on OSX

2010-12-07 Thread Jim Mauro

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 
  0  

Re: [dtrace-discuss] pid probes fail on OSX

2010-12-07 Thread Hans Stimer
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 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