From bc35ab7e0ba2ffb8be313b0b1eaf90a86e081171 Mon Sep 17 00:00:00 2001 From: ivanr Date: Mon, 1 Feb 2010 11:44:32 +0000 Subject: [PATCH] Implement variables for access to performance measurements. --- CHANGES | 4 +- apache2/modsecurity.c | 2 +- apache2/modsecurity.h | 3 +- apache2/msc_logging.c | 3 +- apache2/persist_dbm.c | 2 +- apache2/re_variables.c | 170 +++++++++++++++++++++++++++++++++++++++++ 6 files changed, 179 insertions(+), 5 deletions(-) diff --git a/CHANGES b/CHANGES index 359b7d20..92a33fa7 100644 --- a/CHANGES +++ b/CHANGES @@ -11,7 +11,9 @@ storage, and time spent on audit logging. The new information is now available in the Stopwatch2 audit log header. The Stopwatch header remains for backward compatiblity, although it now only includes - the request time and request duration values. [Ivan Ristic] + 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] * Added DURATION, which contains the time ellapsed since the beginning of the current transaction, in milliseconds. [Ivan Ristic] diff --git a/apache2/modsecurity.c b/apache2/modsecurity.c index 0d03e738..7fe22a95 100644 --- a/apache2/modsecurity.c +++ b/apache2/modsecurity.c @@ -193,7 +193,7 @@ static apr_status_t modsecurity_tx_cleanup(void *data) { } } - msr->time_persistence += apr_time_now() - time_before; + msr->time_storage_write += apr_time_now() - time_before; /* Multipart processor cleanup. */ if (msr->mpd != NULL) multipart_cleanup(msr); diff --git a/apache2/modsecurity.h b/apache2/modsecurity.h index 9c6025ff..108cc74b 100644 --- a/apache2/modsecurity.h +++ b/apache2/modsecurity.h @@ -323,7 +323,8 @@ struct modsec_rec { apr_time_t time_phase3; apr_time_t time_phase4; apr_time_t time_phase5; - apr_time_t time_persistence; + apr_time_t time_storage_read; + apr_time_t time_storage_write; apr_time_t time_logging; apr_array_header_t *matched_rules; diff --git a/apache2/msc_logging.c b/apache2/msc_logging.c index fa45218d..2d76e224 100644 --- a/apache2/msc_logging.c +++ b/apache2/msc_logging.c @@ -777,7 +777,8 @@ void sec_audit_logger(modsec_rec *msr) { ", p4=%" APR_TIME_T_FMT ", p5=%" APR_TIME_T_FMT ", s=%" APR_TIME_T_FMT ", l=%" APR_TIME_T_FMT "\n", msr->request_time, (now - msr->request_time), msr->time_phase1, msr->time_phase2, msr->time_phase3, msr->time_phase4, - msr->time_phase5, msr->time_persistence, msr->time_logging); + msr->time_phase5, msr->time_storage_read + msr->time_storage_write, + msr->time_logging); sec_auditlog_write(msr, text, strlen(text)); diff --git a/apache2/persist_dbm.c b/apache2/persist_dbm.c index 89bf3584..1d395023 100644 --- a/apache2/persist_dbm.c +++ b/apache2/persist_dbm.c @@ -311,7 +311,7 @@ apr_table_t *collection_retrieve(modsec_rec *msr, const char *col_name, rtable = collection_retrieve_ex(NULL, msr, col_name, col_key, col_key_len); - msr->time_persistence += apr_time_now() - time_before; + msr->time_storage_read += apr_time_now() - time_before; return rtable; } diff --git a/apache2/re_variables.c b/apache2/re_variables.c index d5740833..0a82cea9 100644 --- a/apache2/re_variables.c +++ b/apache2/re_variables.c @@ -1427,6 +1427,88 @@ static int var_urlencoded_error_generate(modsec_rec *msr, msre_var *var, msre_ru } } +static int generate_performance_variable(modsec_rec *msr, msre_var *var, msre_rule *rule, + apr_table_t *vartab, apr_pool_t *mptmp, apr_time_t value) +{ + msre_var *rvar = NULL; + + rvar = apr_pmemdup(mptmp, var, sizeof(msre_var)); + rvar->value = apr_psprintf(mptmp, "%" APR_TIME_T_FMT, value); + rvar->value_len = strlen(rvar->value); + + apr_table_addn(vartab, rvar->name, (void *)rvar); + + return 1; +} + +/* PERF_COMBINED */ + +static int var_perf_combined_generate(modsec_rec *msr, msre_var *var, msre_rule *rule, + apr_table_t *vartab, apr_pool_t *mptmp) +{ + apr_time_t value = 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; + + return generate_performance_variable(msr, var, rule, vartab, mptmp, value); +} + +/* PERF_PHASE1 */ + +static int var_perf_phase1_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_phase1); +} + +/* PERF_PHASE2 */ + +static int var_perf_phase2_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_phase2); +} + +/* PERF_PHASE3 */ + +static int var_perf_phase3_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_phase3); +} + +/* PERF_PHASE4 */ + +static int var_perf_phase4_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_phase4); +} + +/* PERF_PHASE5 */ + +static int var_perf_phase5_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_phase5); +} + +/* PERF_STORAGE */ + +static int var_perf_storage_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_storage_read + msr->time_storage_write); +} + +/* PERF_LOGGING */ + +static int var_perf_logging_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_logging); +} + /* DURATION */ static int var_duration_generate(modsec_rec *msr, msre_var *var, msre_rule *rule, @@ -3036,6 +3118,94 @@ void msre_engine_register_default_variables(msre_engine *engine) { PHASE_RESPONSE_HEADERS ); + /* PERF_COMBINED */ + msre_engine_variable_register(engine, + "PERF_COMBINED", + VAR_SIMPLE, + 0, 0, + NULL, + var_perf_combined_generate, + VAR_DONT_CACHE, + PHASE_REQUEST_HEADERS + ); + + /* PERF_LOGGING */ + msre_engine_variable_register(engine, + "PERF_LOGGING", + VAR_SIMPLE, + 0, 0, + NULL, + var_perf_logging_generate, + VAR_DONT_CACHE, + PHASE_REQUEST_HEADERS + ); + + /* PERF_PHASE1 */ + msre_engine_variable_register(engine, + "PERF_PHASE1", + VAR_SIMPLE, + 0, 0, + NULL, + var_perf_phase1_generate, + VAR_DONT_CACHE, + PHASE_REQUEST_HEADERS + ); + + /* PERF_PHASE2 */ + msre_engine_variable_register(engine, + "PERF_PHASE2", + VAR_SIMPLE, + 0, 0, + NULL, + var_perf_phase2_generate, + VAR_DONT_CACHE, + PHASE_REQUEST_HEADERS + ); + + /* PERF_PHASE3 */ + msre_engine_variable_register(engine, + "PERF_PHASE3", + VAR_SIMPLE, + 0, 0, + NULL, + var_perf_phase3_generate, + VAR_DONT_CACHE, + PHASE_REQUEST_HEADERS + ); + + /* PERF_PHASE4 */ + msre_engine_variable_register(engine, + "PERF_PHASE4", + VAR_SIMPLE, + 0, 0, + NULL, + var_perf_phase4_generate, + VAR_DONT_CACHE, + PHASE_REQUEST_HEADERS + ); + + /* PERF_PHASE5 */ + msre_engine_variable_register(engine, + "PERF_PHASE5", + VAR_SIMPLE, + 0, 0, + NULL, + var_perf_phase5_generate, + VAR_DONT_CACHE, + PHASE_REQUEST_HEADERS + ); + + /* PERF_STORAGE */ + msre_engine_variable_register(engine, + "PERF_STORAGE", + VAR_SIMPLE, + 0, 0, + NULL, + var_perf_storage_generate, + VAR_DONT_CACHE, + PHASE_REQUEST_HEADERS + ); + /* DURATION */ msre_engine_variable_register(engine, "DURATION",