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.
at

3 comments:

  1. Andrew OverholtJuly 29, 2016 at 6:48 AM

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

    ReplyDelete
  2. Jeff MuizelaarJuly 29, 2016 at 7:39 AM

    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

    ReplyDelete
  3. AnonymousJuly 30, 2016 at 12:00 AM

    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.

    ReplyDelete