How do I interpret the "stopwatch" lines in modsecurity logs?

Question

My modsecurity log produces lines like this in section H:

Stopwatch: 1672766910416996 75370993 (- - -)
Stopwatch2: 1672766910416996 75370993; combined=8155, p1=1356, p2=5617, p3=149, p4=895, p5=137, sr=157, sw=1, l=0, gc=0

1672766910416996 75370993 is the epoch time in nanoseconds, but:

• What do sr, sw, l and gc stand for?
• What unit of time are p1 to p5 in?
• What is Stopwatch vs. Stopwatch2?

If the answers are already documented, I'd appreciate a link. There are a lot of questions that don't seem to be answered in the modsecurity reference guide.

Answer 1

This took some digging. I'm going to answer in reverse order.

First, the difference between Stopwatch and Stopwatch2 is that Stopwatch2 provides more detail about where time is spent. From the source code, there are several notes that Stopwatch has been "left in for compatibility reasons".

Stopwatch has five different values.

Each line can contain up to 5 different values. Some values can be absent; each absent value will be replaced with a dash.
The meanings of the values are as follows (all values are in microseconds):

• Transaction timestamp in microseconds since January 1st, 1970.
• Transaction duration.
• The time between the moment Apache started processing the request and until phase 2 of ModSecurity began. If an asterisk is present that means the time includes the time it took ModSecurity to read the request body from the client (typically slow). This value can be used to provide a rough estimate of the client speed, but only with larger request bodies (the smaller request bodies may arrive in a single TCP/IP packet).
• The time between the start of processing and until phase 2 was completed. If you substract the previous value from this value you will get the exact duration of phase 2 (which is the main rule processing phase).
• The time between the start of request processing and util we began sending a fully-buffered response body to the client. If you substract this value from the total transaction duration and divide with the response body size you may get a rough estimate of the client speed, but only for larger response bodies.

These five values are included in a more granular fashion in Stopwatch2. In Stopwatch only three phases are provided (or replaced by dashes). Stopwatch2 provides them as well along with two more and the other four that we'll get to in a minute. P1 to P5 correspond to Processing Phases in ModSecurity. These phases are:

• Request_Headers
• Request_Body
• Response_Headers
• Response_Body
• Logging

Rules can be placed in any one of the phases and that is what is timed by p1-p5. I need to research this a little more to verify but based on the timing values of everything else, these are also in microseconds.

Finally, The first three of the remaining four values correspond to Storage Read (sr), Storage Write (sw), Logging time (l) and Garbage collection (gc). I found this reference specifically for gc:

        if (msr->txcfg->debuglog_level >= 4) {
            msr_log(msr, 4, "Garbage collection took %" APR_TIME_T_FMT
                " microseconds.", msr->time_gc);
        }

Here is the snippet of source code from the msc_logging.c reference below.

static void format_performance_variables_json(modsec_rec *msr, yajl_gen g) {
     yajl_string(g, "stopwatch");
     yajl_gen_map_open(g);

     yajl_kv_int(g, "p1", msr->time_phase1);
     yajl_kv_int(g, "p2", msr->time_phase2);
     yajl_kv_int(g, "p3", msr->time_phase3);
     yajl_kv_int(g, "p4", msr->time_phase4);
     yajl_kv_int(g, "p5", msr->time_phase5);
     yajl_kv_int(g, "sr", msr->time_storage_read);
     yajl_kv_int(g, "sw", msr->time_storage_write);
     yajl_kv_int(g, "l", msr->time_logging);
     yajl_kv_int(g, "gc", msr->time_gc);

References
ModSecurity-2-Data-Formats
ModSecurity Processing Phases
msc_logging.c
modsecurity.c