Thursday, July 28, 2016

Counting function calls per second

Say you want to know how often you're allocating tiles in Firefox or the rate of some other thing. There's an easy way to do this using dtrace. The following dtrace script counts calls to any functions matching the pattern '*SharedMemoryBasic*Create*' in XUL in the target process.

#pragma D option quiet
dtrace:::BEGIN
{
    rate = 0;
}

profile:::tick-1sec
{
    printf("%d/sec\n", rate);
    rate = 0;
}

pid$target:XUL:*SharedMemoryBasic*Create*:entry
{
    rate++;
} 

You can run this script with following command:
$ dtrace -s $SCRIPT_NAME -p $PID
I'd be interested in knowing if anyone else has a similar technique for OSs that don't have dtrace.

3 comments:

Andrew Overholt said...

I'd be surprised if you couldn't do something similar with SystemTap: https://sourceware.org/systemtap/

Jeff Muizelaar said...

Indeed. Something like the following seems to work:

global call_count;
probe process.function("some_function_name") { call_count++; }

probe timer.s(1) {
printf("%d/sec\n", call_count);
call_count = 0;
}

run as:

$ stap $SCRIPT_NAME -x $PID

Anonymous said...

Hey,

Regarding the dtrace example, increments of a dtrace global variable aren't made to be atomic by dtrace (last I checked). Hence your results could be incorrect on a multithreaded code base.

But, you can use dtrace aggregations to do this without the race condition. For example,

pid$target:XUL:*SharedMemoryBasic??*:entry
{
@a["calls per second"]=count();
}

profile:::tick-1sec
{
printa(@a);
trunc(@a);
}

One of the simplest most useful features of aggregations is to use ustack() as the aggregation key to get stack traces along with the count of each unique stack trace:

pid$target:XUL:*SharedMemoryBasic??*:entry
{
@a[ustack()]=count();
}

profile:::tick-1sec
{
printa(@a);
trunc(@a);
}

Another key you can try is "@a[probefunc]=count();".

I've found that you can use two question marks to match the :: in a C++ method probe. This makes matching a little more exact. Here's the output I get tracing *SharedMemoryBasic??* with probefunc as the aggregation key.

0 351742 :tick-1sec
mozilla::ipc::SharedMemoryBasic::CloseHandle() 3
mozilla::ipc::SharedMemoryBasic::Create(unsigned long) 3
mozilla::ipc::SharedMemoryBasic::Map(unsigned long) 3
mozilla::ipc::SharedMemoryBasic::ShareToProcess(int, unsigned int*) 3
mozilla::ipc::SharedMemoryBasic::SharedMemoryBasic() 3
mozilla::ipc::SharedMemoryBasic::Type() const 3
mozilla::ipc::SharedMemoryBasic::memory() const 69

The right column is the number of calls in the last 1-second interval.