mod_status: Add cumulated response duration time

in milliseconds.


git-svn-id: https://svn.apache.org/repos/asf/httpd/httpd/trunk@1837590 13f79535-47bb-0310-9956-ffa450edef68

CHANGES

@@ -1,6 +1,9 @@
                                                          -*- coding: utf-8 -*-
 Changes with Apache 2.5.1
 
+  *) mod_status: Add cumulated response duration time in milliseconds.
+     [Rainer Jung]
+
   *) mod_status: Complete the data shown for async MPMs in "auto" mode.
      Added number of processes, number of stopping processes and number
      of busy and idle workers.  [Rainer Jung]

include/ap_mmn.h

@@ -589,6 +589,8 @@
  * 20180720.2 (2.5.1-dev)  Add optional function declaration for
  *                         ap_proxy_balancer_get_best_worker to mod_proxy.h.
  * 20180720.3 (2.5.1-dev)  Add client64 to worker_share
+ * 20180720.4 (2.5.1-dev)  Add new duration field to worker_score struct in
+ *                         scoreboard.h
  *
  */
 
@@ -597,7 +599,7 @@
 #ifndef MODULE_MAGIC_NUMBER_MAJOR
 #define MODULE_MAGIC_NUMBER_MAJOR 20180720
 #endif
-#define MODULE_MAGIC_NUMBER_MINOR 3                 /* 0...n */
+#define MODULE_MAGIC_NUMBER_MINOR 4                 /* 0...n */
 
 /**
  * Determine if the server's current MODULE_MAGIC_NUMBER is at least a

include/scoreboard.h

@@ -117,6 +117,7 @@ struct worker_score {
     char vhost[32];             /* What virtual host is being accessed? */
     char protocol[16];          /* What protocol is used on the connection? */
     char client64[64];
+    apr_time_t duration;
 };
 
 typedef struct {

modules/generators/mod_status.c

@@ -193,6 +193,8 @@ static int status_handler(request_rec *r)
     apr_off_t bytes, my_bytes, conn_bytes;
     apr_off_t bcount, kbcount;
     long req_time;
+    apr_time_t duration_global;
+    apr_time_t duration_slot;
     int short_report;
     int no_table_report;
     worker_score *ws_record;
@@ -232,6 +234,7 @@ static int status_handler(request_rec *r)
     count = 0;
     bcount = 0;
     kbcount = 0;
+    duration_global = 0;
     short_report = 0;
     no_table_report = 0;
 
@@ -374,6 +377,7 @@ static int status_handler(request_rec *r)
 
                     count += lres;
                     bcount += bytes;
+                    duration_global += ws_record->duration;
 
                     if (bcount >= KBYTE) {
                         kbcount += (bcount >> 10);
@@ -461,8 +465,9 @@ static int status_handler(request_rec *r)
     if (ap_extended_status) {
         if (short_report) {
             ap_rprintf(r, "Total Accesses: %lu\nTotal kBytes: %"
-                       APR_OFF_T_FMT "\n",
+                       APR_OFF_T_FMT "\nTotal Duration: %"
-                       count, kbcount);
+                       APR_TIME_T_FMT "\n",
+                       count, kbcount, duration_global / 1000);
 
 #ifdef HAVE_TIMES
             /* Allow for OS/2 not having CPU stats */
@@ -482,14 +487,17 @@ static int status_handler(request_rec *r)
                 ap_rprintf(r, "BytesPerSec: %g\n",
                            KBYTE * (float) kbcount / (float) up_time);
             }
-            if (count > 0)
+            if (count > 0) {
                 ap_rprintf(r, "BytesPerReq: %g\n",
                            KBYTE * (float) kbcount / (float) count);
+                ap_rprintf(r, "DurationPerReq: %g\n",
+                           (float) duration_global / (float) count / 1000.);
+            }
         }
         else { /* !short_report */
             ap_rprintf(r, "<dt>Total accesses: %lu - Total Traffic: ", count);
             format_kbyte_out(r, kbcount);
-            ap_rputs("</dt>\n", r);
+            ap_rprintf(r, " - Total Duration: %" APR_TIME_T_FMT "</dt>\n", duration_global / 1000);
 
 #ifdef HAVE_TIMES
             /* Allow for OS/2 not having CPU stats */
@@ -507,13 +515,15 @@ static int status_handler(request_rec *r)
 
                 format_byte_out(r, (unsigned long)(KBYTE * (float) kbcount
                                                    / (float) up_time));
-                ap_rputs("/second - ", r);
+                ap_rputs("/second", r);
             }
 
             if (count > 0) {
+                ap_rputs(" - ", r);
                 format_byte_out(r, (unsigned long)(KBYTE * (float) kbcount
                                                    / (float) count));
-                ap_rputs("/request", r);
+                ap_rprintf(r, "/request - %g ms/request",
+                (float) duration_global / (float) count / 1000.);
             }
 
             ap_rputs("</dt>\n", r);
@@ -691,7 +701,7 @@ static int status_handler(request_rec *r)
 #ifdef HAVE_TIMES
                      "<th>CPU\n</th>"
 #endif
-                     "<th>SS</th><th>Req</th>"
+                     "<th>SS</th><th>Req</th><th>Dur</th>"
                      "<th>Conn</th><th>Child</th><th>Slot</th>"
                      "<th>Client</th><th>Protocol</th><th>VHost</th>"
                      "<th>Request</th></tr>\n\n", r);
@@ -723,6 +733,7 @@ static int status_handler(request_rec *r)
                 bytes = ws_record->bytes_served;
                 my_bytes = ws_record->my_bytes_served;
                 conn_bytes = ws_record->conn_bytes;
+                duration_slot = ws_record->duration;
                 if (ws_record->pid) { /* MPM sets per-worker pid and generation */
                     worker_pid = ws_record->pid;
                     worker_generation = ws_record->generation;
@@ -789,7 +800,7 @@ static int status_handler(request_rec *r)
 #ifdef HAVE_TIMES
                                "u%g s%g cu%g cs%g"
 #endif
-                               "\n %ld %ld (",
+                               "\n %ld %ld %" APR_TIME_T_FMT "(",
 #ifdef HAVE_TIMES
                                ws_record->times.tms_utime / tick,
                                ws_record->times.tms_stime / tick,
@@ -798,7 +809,8 @@ static int status_handler(request_rec *r)
 #endif
                                (long)apr_time_sec(nowtime -
                                                   ws_record->last_used),
-                               (long) req_time);
+                               (long) req_time,
+                               duration_slot / 1000);
 
                     format_byte_out(r, conn_bytes);
                     ap_rputs("|", r);
@@ -878,7 +890,7 @@ static int status_handler(request_rec *r)
 #ifdef HAVE_TIMES
                                "<td>%.2f</td>"
 #endif
-                               "<td>%ld</td><td>%ld",
+                               "<td>%ld</td><td>%ld</td><td>%" APR_TIME_T_FMT,
 #ifdef HAVE_TIMES
                                (ws_record->times.tms_utime +
                                 ws_record->times.tms_stime +
@@ -887,7 +899,8 @@ static int status_handler(request_rec *r)
 #endif
                                (long)apr_time_sec(nowtime -
                                                   ws_record->last_used),
-                               (long)req_time);
+                               (long)req_time,
+                               duration_slot / 1000);
 
                     ap_rprintf(r, "</td><td>%-1.1f</td><td>%-2.2f</td><td>%-2.2f\n",
                                (float)conn_bytes / KBYTE, (float) my_bytes / MBYTE,
@@ -923,6 +936,7 @@ static int status_handler(request_rec *r)
 
 "<tr><th>SS</th><td>Seconds since beginning of most recent request</td></tr>\n \
 <tr><th>Req</th><td>Milliseconds required to process most recent request</td></tr>\n \
+<tr><th>Dur</th><td>Sum of milliseconds required to process all requests</td></tr>\n \
 <tr><th>Conn</th><td>Kilobytes transferred this connection</td></tr>\n \
 <tr><th>Child</th><td>Megabytes transferred this child</td></tr>\n \
 <tr><th>Slot</th><td>Total megabytes transferred this slot</td></tr>\n \

server/scoreboard.c

@@ -641,6 +641,9 @@ AP_DECLARE(void) ap_time_process_request(ap_sb_handle_t *sbh, int status)
     }
     else if (status == STOP_PREQUEST) {
         ws->stop_time = ws->last_used = apr_time_now();
+        if (ap_extended_status) {
+            ws->duration += ws->stop_time - ws->start_time;
+        }
     }
 }