Exercise 7

Nature of solution of this exercise depends on your Apache and PHP configuration. In our case (as described in lab description), PHP was built as Apache HTTPD module (by using --with-apxs2 option of configure-script), so all PHP code will be executed in a context of Apache worker, so we can safely use Thread-Local variables. If PHP was deployed with PHP-FPM, things would be more complicated.

So we will need to use process-request-entry probe to get URI of request and pair of probes function-entry/function-entry to measure execution time of a function. Since name of a method is passed in multiple probe arguments, we will have to use string concatenation. Like in many other exercises, we will use aggregations to collect statistics. Note that you can use PHP probe request-startup instead of process-request-entry.

As you could remember from a profiling section of tracing principles, generally you shouldn't measure execution time of a function by tracing entry and exit points of it. However, PHP is an interpreted language, so it has lesser relative overheads of tracing because execution of its opcodes is slower than for the real processor (unless you are using some precompiler to machine language like HHVM) and we can afford full-tracing of it.

Here are resulting implementations of scripts for SystemTap and DTrace:

@define httpd %( "/usr/local/apache2/bin/httpd" %)
@define libphp5 %( "/usr/local/apache2/modules/libphp5.so" %)

global rquri, starttime, functime;

probe process(@httpd).mark("process__request__entry") {
    rquri[tid()] = user_string($arg2);
}

probe process(@libphp5).mark("function__entry") {
    starttime[tid()] = gettimeofday_ns();
}

probe process(@libphp5).mark("function__return") {
    if(starttime[tid()] == 0) next;

    func = user_string($arg4) . user_string($arg5) . user_string($arg1);
    functime[func, rquri[tid()]] <<< (gettimeofday_ns() - starttime[tid()]);
}

probe end {
    foreach([func, uri] in functime) {
        printf("%40s %32s %8d %d\n", func, uri,
               @count(functime[func, uri]), @avg(functime[func, uri]));
    }
}

ap*:::process-request-entry {
    self->uri = copyinstr(arg1);
}

php*:::function-entry {
    self->starttime = timestamp;
}

php*:::function-return 
/ self->starttime != 0 / {
    this->func = strjoin(copyinstr(arg3), 
                         strjoin(copyinstr(arg4), copyinstr(arg0)));
    @[this->func, self->uri] = avg(timestamp - self->starttime);
}

END {
    printa(@);
}