dtrace discuss - May 2010 - More DTrace Questions - Release builds & Performance

Again, I am using Mac OS X 10.6.3.



First, I am curious, how is DTrace getting the function name information for a
release build when all of it''s symbols have been stripped from it and
there is not dSym file either in the application package or adjacent to it? For
example, I create the default Cocoa Application, and wrote:

- (void) myRandomMethod
{
	int x;
		
	for ( x = 0; x < 9000000; x++ )
	{
	}
}

- (void) applicationDidFinishLaunching:(NSNotification *)aNotification 
{
	[self myRandomMethod];
}


sudo dtrace -l -n ''pid1221:MyApp::entry'' produced the
following results for the release build:

   ID   PROVIDER            MODULE                          FUNCTION NAME
26601    pid1221             MyApp                             start entry
26602    pid1221             MyApp                              main entry
26603    pid1221             MyApp -[MyAppAppDelegate myRandomMethod] entry
26604    pid1221             MyApp        -[MyAppAppDelegate window] entry
26605    pid1221             MyApp    -[MyAppAppDelegate setWindow:] entry
26606    pid1221             MyApp -[MyAppAppDelegate
applicationDidFinishLaunching:] entry
26607    pid1221             MyApp                      stub helpers entry


Now, there is a dSym file for this application, but for DTrace to find it, it
would have needed to search the drive for it''s location...

---
---
---

I am looking into the performance hit of doing probe enabled checks.

To test this, I created the default Cocoa application and then wrote:

- (unsigned long) myMethod:(unsigned long)inX
{
	return inX + 1;
}

- (void)applicationDidFinishLaunching:(NSNotification *)aNotification 
{
	if ( DTRACETEST_TEST_START_ENABLED() )
		DTRACETEST_TEST_START();
		
	unsigned long x;
	unsigned long y = 0;
	
	for ( x = 0; x < 1000000000; x++ )
	{
		y = [self myMethod:x];

		if ( DTRACETEST_TEST_MINE_ENABLED() )
		{
			DTRACETEST_TEST_MINE();
		}
		
	}
	
	if ( DTRACETEST_TEST_END_ENABLED() )
		DTRACETEST_TEST_END();
	
	printf( "%lu", y );
	
	// Insert code here to initialize your application 
}

In the Debug build,

If I remove DTRACETEST_TEST_MINE_ENABLED block, the time between the start and
end probes is ~8.8 seconds.
Adding DTRACETEST_TEST_MINE_ENABLED back in, but keeping the probe disabled
(i.e. DTRACETEST_TEST_MINE_ENABLED returns false), took ~8.9 seconds.

In the Release build,

If I remove DTRACETEST_TEST_MINE_ENABLED block, the time between the start and
end probes is ~5.7 seconds.
Adding DTRACETEST_TEST_MINE_ENABLED back in, but keeping the probe disabled,
took ~6.4 seconds.

The overhead has increased significantly in the release build.

This doesn''t seem like it is as close to zero cost as I initially
thought it should be, leading me to think that i may not be measuring what I
think I am measuring.

Based on these results, it would seem that one would want to keep probes out of
the tightest loops in an application.

But, considering how pervasive such things are even in Mac OS X, my conclusion
does not seem to be correct.



Thank you.



-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20100507/c9c45811/attachment-0001.html>

On May 7, 2010, at 11:41 AM, Eric Gorr wrote:
> Again, I am using Mac OS X 10.6.3.
> 
> 
> 
> First, I am curious, how is DTrace getting the function name information
for a release build when all of it''s symbols have been stripped from it
and there is not dSym file either in the application package or adjacent to it?
For example, I create the default Cocoa Application, and wrote:
> 
> - (void) myRandomMethod
> {
> 	int x;
> 		
> 	for ( x = 0; x < 9000000; x++ )
> 	{
> 	}
> }
> 
> - (void) applicationDidFinishLaunching:(NSNotification *)aNotification 
> {
> 	[self myRandomMethod];
> }
> 
> 
> sudo dtrace -l -n ''pid1221:MyApp::entry'' produced the
following results for the release build:
> 
>    ID   PROVIDER            MODULE                          FUNCTION NAME
> 26601    pid1221             MyApp                             start entry
> 26602    pid1221             MyApp                              main entry
> 26603    pid1221             MyApp -[MyAppAppDelegate myRandomMethod] entry
> 26604    pid1221             MyApp        -[MyAppAppDelegate window] entry
> 26605    pid1221             MyApp    -[MyAppAppDelegate setWindow:] entry
> 26606    pid1221             MyApp -[MyAppAppDelegate
applicationDidFinishLaunching:] entry
> 26607    pid1221             MyApp                      stub helpers entry
> 
> 
> Now, there is a dSym file for this application, but for DTrace to find it,
it would have needed to search the drive for it''s location...
	The OS X dtrace uses spotlight to find dSYM(s), if you want to disable this,
move the dSYM to a directory not indexed by spotlight, or turn off spotlight.

> 
> ---
> ---
> ---
> 
> I am looking into the performance hit of doing probe enabled checks.
> 
> To test this, I created the default Cocoa application and then wrote:
> 
> - (unsigned long) myMethod:(unsigned long)inX
> {
> 	return inX + 1;
> }
> 
> - (void)applicationDidFinishLaunching:(NSNotification *)aNotification 
> {
> 	if ( DTRACETEST_TEST_START_ENABLED() )
> 		DTRACETEST_TEST_START();
> 		
> 	unsigned long x;
> 	unsigned long y = 0;
> 	
> 	for ( x = 0; x < 1000000000; x++ )
> 	{
> 		y = [self myMethod:x];
> 
> 		if ( DTRACETEST_TEST_MINE_ENABLED() )
> 		{
> 			DTRACETEST_TEST_MINE();
> 		}
> 		
> 	}
> 	
> 	if ( DTRACETEST_TEST_END_ENABLED() )
> 		DTRACETEST_TEST_END();
> 	
> 	printf( "%lu", y );
> 	
> 	// Insert code here to initialize your application 
> }
> 
> In the Debug build,
> 
> If I remove DTRACETEST_TEST_MINE_ENABLED block, the time between the start
and end probes is ~8.8 seconds.
> Adding DTRACETEST_TEST_MINE_ENABLED back in, but keeping the probe disabled
(i.e. DTRACETEST_TEST_MINE_ENABLED returns false), took ~8.9 seconds.
> 
> In the Release build,
> 
> If I remove DTRACETEST_TEST_MINE_ENABLED block, the time between the start
and end probes is ~5.7 seconds.
> Adding DTRACETEST_TEST_MINE_ENABLED back in, but keeping the probe
disabled, took ~6.4 seconds.
> 
> The overhead has increased significantly in the release build.
> 
> This doesn''t seem like it is as close to zero cost as I initially
thought it should be, leading me to think that i may not be measuring what I
think I am measuring.
> 
> Based on these results, it would seem that one would want to keep probes
out of the tightest loops in an application.
> 
> But, considering how pervasive such things are even in Mac OS X, my
conclusion does not seem to be correct.
	The debug build has a less optimized loop. The cpu is able to "hide"
more of the dtrace probe cost by overlapping its execution time with other
instructions in the loop.

	The release build is tighter code, you''re seeing more of the actual
probe cost.

	It looks to me like you are doing 1 billion loops, at a cost of .7 seconds of
execution time.

	That puts the cost of an ENABLED() guarded probe at .0000000007 seconds, or .7
nanoseconds.

	Call that ~1.5 clock cycles on most laptop cpu''s, maybe ~2.x clock
cycles if you are on a desktop.

	That''s pretty low cost. If you''re writing seriously hot code,
where a clock or two really matters, I''d leave the dtrace probe out.

	James M

On May 7, 2010, at 4:09 PM, James McIlree wrote:
> 
> On May 7, 2010, at 11:41 AM, Eric Gorr wrote:
>> Now, there is a dSym file for this application, but for DTrace to find
it, it would have needed to search the drive for it''s location...
> 
> 	The OS X dtrace uses spotlight to find dSYM(s), if you want to disable
this, move the dSYM to a directory not indexed by spotlight, or turn off
spotlight.
Confirmed. (Not that I doubted you for a second - it was for my edification)

To confirm this, I create a sample application, made sure that no dSym file was
around. Verified no symbols were anywhere to be seen using both nm and otool -t
-V.

And, (to no one''s surprise), dtrace couldn''t find any entry
probes at all.

For those who are interested, the sample application can be found at:

http://ericgorr.net/cocoadev/dtracetest.zip

So, now that I understand this part...or at least think I do....it leads me to a
couple of more questions.



QUESTION #1:

I have defined three custom probes in my application. When I create a custom
instrument in Instruments to record when those probes fire, I do see them (
http://ericgorr.net/cocoadev/dtracetest_ins.trace.zip ).

However, when I do the following:



~ $ps -ax | grep dtracetest
31449 ??         0:00.46 /Developer/usr/bin/ibtool --start-agent
/Users/egorr/Desktop/dtracetest/dtracetest.xcodeproj --agent-timeout 1800.000000
33021 ??         0:00.09
/Users/egorr/Desktop/dtracetest/build/Release/dtracetest.app/Contents/MacOS/dtracetest
-psn_0_667811
33067 ttys000    0:00.00 grep dtracetest

~ $sudo dtrace -l -n ''pid33021:dtracetest::''
   ID   PROVIDER            MODULE                          FUNCTION NAME
dtrace: failed to match pid33021:dtracetest::: No probe matches description

~ $cat dtracetest.d
pid$target:dtracetest::
{
 @probecount[ probefunc ] = count();
}

~ $sudo dtrace -p 33021 -s dtracetest.d
dtrace: failed to compile script dtracetest.d: line 1: probe description
pid33021:dtracetest:: does not match any probes



DTrace from the command line doesn''t know about the probes.

Why is that?

---
---
---

QUESTION #2:

Clearly, I can prevent DTrace from the command line from automatically creating
entry, etc. probes for my application.

So, the question then becomes, how can I tell DTrace that I want it to
automatically create entry, etc. probes for a subset of my functions.

For example, say I wanted the automatic creation of entry and exit probes for
just the myCFunc function in my sample application?
What if there were 100 or 1000 more functions that I wanted dtrace to
automatically create entry and exit probes for?

Is it possible to be selective in terms of what dtrace with automatically create
entry and exit probes for? Or is it (more or less) an all or nothing
proposition?

(Although, this question has probably entered the realm of being specific to
Xcode.)



Thanks again.



(Again, using Mac OS X 10.6.3)



-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20100507/fcd2658b/attachment-0001.html>

On May 7, 2010, at 6:10 PM, Eric Gorr wrote:
> QUESTION #1:
> 
> I have defined three custom probes in my application. When I create a
custom instrument in Instruments to record when those probes fire, I do see them
( http://ericgorr.net/cocoadev/dtracetest_ins.trace.zip ).
> 
> However, when I do the following:
> 
> 
> 
> ~ $ps -ax | grep dtracetest
> 31449 ??         0:00.46 /Developer/usr/bin/ibtool --start-agent
/Users/egorr/Desktop/dtracetest/dtracetest.xcodeproj --agent-timeout 1800.000000
> 33021 ??         0:00.09
/Users/egorr/Desktop/dtracetest/build/Release/dtracetest.app/Contents/MacOS/dtracetest
-psn_0_667811
> 33067 ttys000    0:00.00 grep dtracetest
> 
> ~ $sudo dtrace -l -n ''pid33021:dtracetest::''
>    ID   PROVIDER            MODULE                          FUNCTION NAME
> dtrace: failed to match pid33021:dtracetest::: No probe matches description
> 
> ~ $cat dtracetest.d
> pid$target:dtracetest::
> {
>  @probecount[ probefunc ] = count();
> }
> 
> ~ $sudo dtrace -p 33021 -s dtracetest.d
> dtrace: failed to compile script dtracetest.d: line 1: probe description
pid33021:dtracetest:: does not match any probes
> 
> 
> 
> DTrace from the command line doesn''t know about the probes.
> 
> Why is that?
Well, the answer finally came to me... I needed to do:

~ $sudo dtrace -l -n ''DTraceTest*:::''

Password:
   ID   PROVIDER            MODULE                          FUNCTION NAME
22415 DTraceTest45612        dtracetest -[dtracetestAppDelegate buttonPushed:]
test_end
22416 DTraceTest45612        dtracetest -[dtracetestAppDelegate buttonPushed:]
test_mine
22417 DTraceTest45612        dtracetest -[dtracetestAppDelegate buttonPushed:]
test_start

> ---
> ---
> ---
> 
> QUESTION #2:
> 
> Clearly, I can prevent DTrace from the command line from automatically
creating entry, etc. probes for my application.
> 
> So, the question then becomes, how can I tell DTrace that I want it to
automatically create entry, etc. probes for a subset of my functions.
> 
> For example, say I wanted the automatic creation of entry and exit probes
for just the myCFunc function in my sample application?
> What if there were 100 or 1000 more functions that I wanted dtrace to
automatically create entry and exit probes for?
> 
> Is it possible to be selective in terms of what dtrace with automatically
create entry and exit probes for? Or is it (more or less) an all or nothing
proposition?
> 
> (Although, this question has probably entered the realm of being specific
to Xcode.)

Still looking for the answer for this one, but believe one would be able to
manage it with the Exported Symbols File.

On May 9, 2010, at 4:46 AM, Eric Gorr wrote:
>> 
>> DTrace from the command line doesn''t know about the probes.
>> 
>> Why is that?
> 
> Well, the answer finally came to me... I needed to do:
> 
> ~ $sudo dtrace -l -n ''DTraceTest*:::''
> 
> Password:
>   ID   PROVIDER            MODULE                          FUNCTION NAME
> 22415 DTraceTest45612        dtracetest -[dtracetestAppDelegate
buttonPushed:] test_end
> 22416 DTraceTest45612        dtracetest -[dtracetestAppDelegate
buttonPushed:] test_mine
> 22417 DTraceTest45612        dtracetest -[dtracetestAppDelegate
buttonPushed:] test_start
> 
> 
>> ---
>> ---
>> ---
>> 
>> QUESTION #2:
>> 
>> Clearly, I can prevent DTrace from the command line from automatically
creating entry, etc. probes for my application.
>> 
>> So, the question then becomes, how can I tell DTrace that I want it to
automatically create entry, etc. probes for a subset of my functions.
>> 
>> For example, say I wanted the automatic creation of entry and exit
probes for just the myCFunc function in my sample application?
>> What if there were 100 or 1000 more functions that I wanted dtrace to
automatically create entry and exit probes for?
>> 
>> Is it possible to be selective in terms of what dtrace with
automatically create entry and exit probes for? Or is it (more or less) an all
or nothing proposition?
>> 
>> (Although, this question has probably entered the realm of being
specific to Xcode.)
> 
> 
> Still looking for the answer for this one, but believe one would be able to
manage it with the Exported Symbols File.
Eric,

	I think you may be misunderstanding the difference between USDT probes, and pid
probes.

	USDT probes are what you created above, test_end, test_mine, test_start. You
chose the name and placement of these probes by placing macros in your compiled
code.

	Pid probes are created for you, if dtrace can find a symbol with the name of
the function.

	I''m guessing, I think your question above is:

	"Can I be selective with USDT probes, and have dtrace only create them for
certain functions?"

	Ultimately, you have control over all USDT probes, if you don''t place
them in your code, they will not show up.

	However, once you have placed them, the only way to remove them is recompiling
the code.

	You don''t have to *use* all the probes you place, though.

	For example, suppose you only want the test_end, test_mine, and test_start
probes in "myCFunc".

	If you write a probe descriptor like this:

	DTraceTest1234::myCFunc:*

	That will only enable the DTraceTest probes in myCFunc, even though you may
have many other probes.

	James M

On May 10, 2010, at 6:15 PM, James McIlree wrote:
>>> QUESTION #2:
>>> 
>>> Clearly, I can prevent DTrace from the command line from
automatically creating entry, etc. probes for my application.
>>> 
>>> So, the question then becomes, how can I tell DTrace that I want it
to automatically create entry, etc. probes for a subset of my functions.
>>> 
>>> For example, say I wanted the automatic creation of entry and exit
probes for just the myCFunc function in my sample application?
>>> What if there were 100 or 1000 more functions that I wanted dtrace
to automatically create entry and exit probes for?
>>> 
>>> Is it possible to be selective in terms of what dtrace with
automatically create entry and exit probes for? Or is it (more or less) an all
or nothing proposition?
>>> 
>>> (Although, this question has probably entered the realm of being
specific to Xcode.)
>> 
>> 
>> Still looking for the answer for this one, but believe one would be
able to manage it with the Exported Symbols File.
> 
> Eric,
> 
> 	I think you may be misunderstanding the difference between USDT probes,
and pid probes.
> 
> 	USDT probes are what you created above, test_end, test_mine, test_start.
You chose the name and placement of these probes by placing macros in your
compiled code.
> 
> 	Pid probes are created for you, if dtrace can find a symbol with the name
of the function.
> 
> 	I''m guessing, I think your question above is:
> 
> 	"Can I be selective with USDT probes, and have dtrace only create
them for certain functions?"
> 
> 	Ultimately, you have control over all USDT probes, if you don''t
place them in your code, they will not show up.
> 
> 	However, once you have placed them, the only way to remove them is
recompiling the code.
> 
> 	You don''t have to *use* all the probes you place, though.
> 
> 	For example, suppose you only want the test_end, test_mine, and test_start
probes in "myCFunc".
> 
> 	If you write a probe descriptor like this:
> 
> 	DTraceTest1234::myCFunc:*
> 
> 	That will only enable the DTraceTest probes in myCFunc, even though you
may have many other probes.
Thank you. This was all useful information.

However, in this case, I am talking about the pid probes that dtrace will
auto-generate if dtrace can find a symbol with the name of the function.

What I am wondering is how or if I control what symbols, with the name of the
function, dtrace will find.

If, for example, I could generate a dSym file with only a small subset of these
symbols, then this dSym file could be distributed to a customer to help track
down a problem where these pid probes would be useful. What symbols might be
excluded from the dSym? Symbols involved with the protection or other sensitive
systems not involved in the problem.

Now, if a dSym cannot be used to accomplish this, then perhaps there is some
other kind of file that could be used or a way to more selectively strip symbols
from the binary.