Add PERF_GC.

CHANGES

@@ -16,7 +16,8 @@
    remains for backward compatiblity, although it now only includes
    the request time and request duration values. Added the following
    variables: PERF_COMBINED, PERF_PHASE1, PERF_PHASE2, PERF_PHASE3,
-   PERF_PHASE4, PERF_PHASE5, PERF_STORAGE, PERF_LOGGING. [Ivan Ristic]
+   PERF_PHASE4, PERF_PHASE5, PERF_STORAGE, PERF_LOGGING, PERF_GC.
+   [Ivan Ristic]
 
  * Added DURATION, which contains the time ellapsed since the beginning
    of the current transaction, in milliseconds. [Ivan Ristic]

apache2/modsecurity.c

@@ -164,17 +164,12 @@ static apr_status_t modsecurity_tx_cleanup(void *data) {
     modsec_rec *msr = (modsec_rec *)data;
     const apr_array_header_t *arr;
     apr_table_entry_t *te;
-    int collect_garbage = 0;
-    int i;
     char *my_error_msg = NULL;
-    apr_time_t time_before, duration;
+    apr_time_t time_before, time_after;
+    int i;
 
     if (msr == NULL) return APR_SUCCESS;
 
-    if (rand() < RAND_MAX/100) {
-        collect_garbage = 1;
-    }
-    
     time_before = apr_time_now();
 
     /* Collections, store & remove stale. */
@@ -187,17 +182,26 @@ static apr_status_t modsecurity_tx_cleanup(void *data) {
         if (apr_table_get(msr->collections_dirty, te[i].key)) {
             collection_store(msr, col);
         }
-
-        if (collect_garbage) {
-            collections_remove_stale(msr, te[i].key);
-        }
     }
 
-    duration = apr_time_now() - time_before;
+    time_after = apr_time_now();
-    msr->time_storage_write += duration;
     
-    if (msr->txcfg->debuglog_level >= 3) {
+    msr->time_storage_write += time_after - time_before;
-        msr_log(msr, 3, "Garbage collection took %" APR_TIME_T_FMT " microseconds.", duration);
+    
+    /* Remove stale collections. */
+    if (rand() < RAND_MAX/100) {
+        arr = apr_table_elts(msr->collections);
+        te = (apr_table_entry_t *)arr->elts;
+        for (i = 0; i < arr->nelts; i++) {
+            collections_remove_stale(msr, te[i].key);
+        }
+        
+        msr->time_gc = apr_time_now() - time_after;
+        
+        if (msr->txcfg->debuglog_level >= 3) {
+            msr_log(msr, 3, "Garbage collection took %" APR_TIME_T_FMT
+                " microseconds.", msr->time_gc);
+        }   
     }
 
     /* Multipart processor cleanup. */

apache2/modsecurity.h

@@ -326,6 +326,7 @@ struct modsec_rec {
     apr_time_t		 time_storage_read;
     apr_time_t		 time_storage_write;
     apr_time_t		 time_logging;
+    apr_time_t		 time_gc;
     
     apr_array_header_t  *matched_rules;
     msc_string          *matched_var;

apache2/re_variables.c

@@ -1430,16 +1430,17 @@ static int var_urlencoded_error_generate(modsec_rec *msr, msre_var *var, msre_ru
 apr_time_t calculate_perf_combined(modsec_rec *msr) {
     return msr->time_phase1 + msr->time_phase2 + msr->time_phase3 + msr->time_phase4
         + msr->time_phase5 + msr->time_storage_write /* time_storage_read is already
-        included in phases */ + msr->time_logging;
+        included in phases */ + msr->time_logging + msr->time_gc;
 }
 
 char *format_all_performance_variables(modsec_rec *msr, apr_pool_t *mp) {
     return apr_psprintf(mp, "combined=%" APR_TIME_T_FMT ", p1=%" APR_TIME_T_FMT
         ", p2=%" APR_TIME_T_FMT ", p3=%" APR_TIME_T_FMT ", p4=%" APR_TIME_T_FMT
         ", p5=%" APR_TIME_T_FMT ", sr=%" APR_TIME_T_FMT ", sw=%" APR_TIME_T_FMT
-        ", l=%" APR_TIME_T_FMT, calculate_perf_combined(msr), msr->time_phase1,
+        ", l=%" APR_TIME_T_FMT ", gc=%" APR_TIME_T_FMT, calculate_perf_combined(msr),
-        msr->time_phase2, msr->time_phase3, msr->time_phase4, msr->time_phase5,
+        msr->time_phase1, msr->time_phase2, msr->time_phase3, msr->time_phase4,
-        msr->time_storage_read, msr->time_storage_write, msr->time_logging);
+        msr->time_phase5, msr->time_storage_read, msr->time_storage_write,
+        msr->time_logging, msr->time_gc);
 }
 
 static int generate_performance_variable(modsec_rec *msr, msre_var *var, msre_rule *rule,
@@ -1480,6 +1481,14 @@ static int var_perf_combined_generate(modsec_rec *msr, msre_var *var, msre_rule
     return generate_performance_variable(msr, var, rule, vartab, mptmp, calculate_perf_combined(msr));
 }
 
+/* PERF_GC */
+
+static int var_perf_gc_generate(modsec_rec *msr, msre_var *var, msre_rule *rule,
+    apr_table_t *vartab, apr_pool_t *mptmp)
+{
+    return generate_performance_variable(msr, var, rule, vartab, mptmp, msr->time_gc);
+}
+
 /* PERF_PHASE1 */
 
 static int var_perf_phase1_generate(modsec_rec *msr, msre_var *var, msre_rule *rule,
@@ -3195,6 +3204,17 @@ void msre_engine_register_default_variables(msre_engine *engine) {
         PHASE_REQUEST_HEADERS
     );
     
+    /* PERF_GC */
+    msre_engine_variable_register(engine,
+        "PERF_GC",
+        VAR_SIMPLE,
+        0, 0,
+        NULL,
+        var_perf_gc_generate,
+        VAR_DONT_CACHE,
+        PHASE_REQUEST_HEADERS
+    );
+    
     /* PERF_LOGGING */
     msre_engine_variable_register(engine,
         "PERF_LOGGING",