9

I have a utility function that I suspect is eating up a large portion of my application's execution time. Using Time Profiler to look at the call stack, this function takes up a large portion of the execution time of any function from which it is called. However, since this utility function is called from many different sources, I am having trouble determining if, overall, this is the best use of my optimization time.

How can I look at total time spent in this function during program execution, regardless of who called it?

For clarity, I want to combine the selected entries with all other calls to that function into a single entry: Profiler Log

user664939
  • 1,977
  • 2
  • 20
  • 35
  • Do you have to flexibility and will to add some code to the culprit function and log the results in debugger or you want an instruments only solution? – SayeedHussain Apr 12 '14 at 03:47
  • @paranoidcoder: I can add code, though I would love an instruments-only solution. – user664939 Apr 12 '14 at 03:53

5 Answers5

7

For me, what does the trick is ticking "Invert Call Tree". It seems to sort "leaf" functions in the call tree in order of those that cumulate the most time, and allow you to see what calls them.

The checkbox can be found in the right panel, called "Display Settings" (If hidden: ⌘2 or View->Inspectors->Show Display Settings)

Alexis Bauchu
  • 71
  • 1
  • 3
3

I am not aware of an instruments based solution but here is something you can do from code. Hope somebody provides an instruments solution but until then to get you going here goes.

#include <time.h> 

//have this as a global variable to track time taken by the culprit function
static double time_consumed = 0;

void myTimeConsumingFunction(){
//add these lines in the function
clock_t start, end;

start = clock();
//main body of the function taking up time
end = clock();

//add this at the bottom and keep accumulating time spent across all calls
time_consumed += (double)(end - start) / CLOCKS_PER_SEC;
}

//at termination/end-of-program log time_consumed.
SayeedHussain
  • 1,696
  • 16
  • 23
  • +1, thanks for the help. I will hold off on accepting for now, though, since I am still hoping there is a way within Instruments. – user664939 Apr 25 '14 at 19:57
2

I can offer the makings of the answer you're looking for but haven't got this working within Instruments yet...

Instruments uses dtrace under the hood. dtrace allows you to respond to events in your program such as a function being entered or returned from. The response to each event can be scripted.

You can create a custom instrument with scripting in Instruments.

Here is a noddy shell script that launches dtrace outside of Instruments and records the time spent in a certain function.

#!/bin/sh

dtrace -c <yourprogram> -n '

unsigned long long totalTime;
self uint64_t lastEntry;

dtrace:::BEGIN
{
    totalTime = 0;
}

pid$target:<yourprogram>:*<yourfunction>*:entry
{
    self->lastEntry = vtimestamp;
}

pid$target:<yourprogram>:*<yourfunction>*:return
{
    totalTime = totalTime + (vtimestamp - self->lastEntry);
    /*@timeByThread[tid] = sum(vtimestamp - self->lastEntry);*/
}

dtrace:::END
{
    printf( "\n\nTotal time %dms\n" , totalTime/1000000 )
}
'

What I haven't figured out yet is how to transfer this into instruments and get the results to appear in a useful way in the GUI.

SimonD
  • 638
  • 5
  • 16
2

To see the totals for a particular function, follow these steps:

  1. Profile your program with Time Profiler
  2. Find and select any mention of the function of interest in the Call Tree view (you can use Edit->Find)
  3. Summon the context menu over the selected function and 'Focus on calls made by ' (Or use Instrument->Call Tree Data Mining->Focus on Calls Made By )

If your program is multi-threaded and you want a total across all threads, make sure 'Separate by Thread' is not checked.

SimonD
  • 638
  • 5
  • 16
0

I think you can call system("time ls"); twice and it will just work for you. The output will be printed on debug console.

Андрей Румянцев
  • 13
  • 3