From d908e707d72923cee0712644d223bd8bf6223d4a Mon Sep 17 00:00:00 2001 From: Victor Julien Date: Mon, 19 Mar 2012 10:28:34 +0100 Subject: [PATCH] profiling: add per lock location profiling Add profiling per lock location in the code. Accounts how often a lock is requested, how often it was contended, the max number of ticks spent waiting for it, avg number of ticks waiting for it and the total ticks for that location. Added a new configure flag --enable-profiling-locks to enable this feature. --- configure.in | 8 ++ src/Makefile.am | 1 + src/decode.h | 8 ++ src/suricata-common.h | 2 - src/suricata.c | 6 + src/threads.h | 109 ++++++++++++++++- src/tm-threads.c | 8 ++ src/util-error.c | 1 + src/util-error.h | 1 + src/util-profiling-locks.c | 233 +++++++++++++++++++++++++++++++++++++ src/util-profiling-locks.h | 45 +++++++ src/util-profiling.c | 65 +++++++++-- src/util-profiling.h | 19 ++- suricata.yaml.in | 7 ++ 14 files changed, 497 insertions(+), 16 deletions(-) create mode 100644 src/util-profiling-locks.c create mode 100644 src/util-profiling-locks.h diff --git a/configure.in b/configure.in index e861909bbd..fdf670e7ed 100644 --- a/configure.in +++ b/configure.in @@ -284,6 +284,13 @@ AC_INIT(configure.in) CFLAGS="${CFLAGS} -DPROFILING" ]) + # profiling support, locking + AC_ARG_ENABLE(profiling-locks, + AS_HELP_STRING([--enable-profiling-locks], [Enable performance profiling for locks]),,[enable_profiling_locks=no]) + AS_IF([test "x$enable_profiling_locks" = "xyes"], [ + CFLAGS="${CFLAGS} -DPROFILING -DPROFILE_LOCKING" + ]) + # enable support for IPFW AC_ARG_ENABLE(ipfw, AS_HELP_STRING([--enable-ipfw], [Enable FreeBSD IPFW support for inline IDP]),,[enable_ipfw=no]) @@ -1258,6 +1265,7 @@ Suricata Configuration: Debug output enabled: ${enable_debug} Debug validation enabled: ${enable_debug_validation} Profiling enabled: ${enable_profiling} + Profiling locks enabled: ${enable_profiling_locks} Generic build parameters: Installation prefix (--prefix): ${prefix} diff --git a/src/Makefile.am b/src/Makefile.am index 84f882c072..f3c9e7c451 100644 --- a/src/Makefile.am +++ b/src/Makefile.am @@ -288,6 +288,7 @@ win32-service.c win32-service.h \ util-action.c util-action.h \ win32-syslog.h \ util-profiling.c util-profiling.h \ +util-profiling-locks.c util-profiling-locks.h \ cuda-packet-batcher.c cuda-packet-batcher.h \ util-ioctl.h util-ioctl.c \ util-logopenfile.h util-logopenfile.c diff --git a/src/decode.h b/src/decode.h index 0e79c47c0a..83b0a61074 100644 --- a/src/decode.h +++ b/src/decode.h @@ -284,12 +284,20 @@ typedef struct PktVar_ { typedef struct PktProfilingTmmData_ { uint64_t ticks_start; uint64_t ticks_end; +#ifdef PROFILE_LOCKING uint64_t mutex_lock_cnt; uint64_t mutex_lock_wait_ticks; uint64_t mutex_lock_contention; uint64_t spin_lock_cnt; uint64_t spin_lock_wait_ticks; uint64_t spin_lock_contention; + uint64_t rww_lock_cnt; + uint64_t rww_lock_wait_ticks; + uint64_t rww_lock_contention; + uint64_t rwr_lock_cnt; + uint64_t rwr_lock_wait_ticks; + uint64_t rwr_lock_contention; +#endif } PktProfilingTmmData; typedef struct PktProfilingDetectData_ { diff --git a/src/suricata-common.h b/src/suricata-common.h index b7345fd9bc..f8e5885324 100644 --- a/src/suricata-common.h +++ b/src/suricata-common.h @@ -30,8 +30,6 @@ #define DBG_PERF #endif -//#define PROFILE_LOCKING - #define TRUE 1 #define FALSE 0 diff --git a/src/suricata.c b/src/suricata.c index b1db347886..6d65905b30 100644 --- a/src/suricata.c +++ b/src/suricata.c @@ -559,6 +559,12 @@ void SCPrintBuildInfo(void) { #endif #ifdef HAVE_NSS strlcat(features, "HAVE_NSS ", sizeof(features)); +#endif +#ifdef PROFILING + strlcat(features, "PROFILING ", sizeof(features)); +#endif +#ifdef PROFILE_LOCKING + strlcat(features, "PROFILE_LOCKING ", sizeof(features)); #endif if (strlen(features) == 0) { strlcat(features, "none", sizeof(features)); diff --git a/src/threads.h b/src/threads.h index 71fc718c08..c4e9bba549 100644 --- a/src/threads.h +++ b/src/threads.h @@ -29,6 +29,7 @@ #ifdef PROFILING #include "util-cpu.h" +#include "util-profiling-locks.h" #endif #if defined OS_FREEBSD || __OpenBSD__ @@ -231,6 +232,19 @@ enum { #define SCMutexInit(mut, mutattr ) pthread_mutex_init(mut, mutattr) #define SCMutexUnlock(mut) pthread_mutex_unlock(mut) +typedef struct ProfilingLock_ { + char *file; + char *func; + int line; + int type; + uint32_t cont; + uint64_t ticks; +} ProfilingLock; + +extern __thread ProfilingLock locks[PROFILING_MAX_LOCKS]; +extern __thread int locks_idx; +extern __thread int record_locks; + extern __thread uint64_t mutex_lock_contention; extern __thread uint64_t mutex_lock_wait_ticks; extern __thread uint64_t mutex_lock_cnt; @@ -239,13 +253,25 @@ extern __thread uint64_t mutex_lock_cnt; #define SCMutexLock_profile(mut) ({ \ mutex_lock_cnt++; \ int retl = 0; \ + int cont = 0; \ uint64_t mutex_lock_start = UtilCpuGetTicks(); \ if (pthread_mutex_trylock((mut)) != 0) { \ mutex_lock_contention++; \ + cont = 1; \ retl = pthread_mutex_lock(mut); \ } \ - uint64_t mutex_lock_end = UtilCpuGetTicks(); \ - mutex_lock_wait_ticks += (uint64_t)(mutex_lock_end - mutex_lock_start); \ + uint64_t mutex_lock_end = UtilCpuGetTicks(); \ + mutex_lock_wait_ticks += (uint64_t)(mutex_lock_end - mutex_lock_start); \ + \ + if (locks_idx < PROFILING_MAX_LOCKS && record_locks) { \ + locks[locks_idx].file = (char *)__FILE__; \ + locks[locks_idx].func = (char *)__func__; \ + locks[locks_idx].line = (int)__LINE__; \ + locks[locks_idx].type = LOCK_MUTEX; \ + locks[locks_idx].cont = cont; \ + locks[locks_idx].ticks = (uint64_t)(mutex_lock_end - mutex_lock_start); \ + locks_idx++; \ + } \ retl; \ }) @@ -401,13 +427,25 @@ extern __thread uint64_t spin_lock_cnt; #define SCSpinLock_profile(spin) ({ \ spin_lock_cnt++; \ int retl = 0; \ + int cont = 0; \ uint64_t spin_lock_start = UtilCpuGetTicks(); \ if (pthread_spin_trylock((spin)) != 0) { \ spin_lock_contention++; \ + cont = 1; \ retl = pthread_spin_lock((spin)); \ } \ uint64_t spin_lock_end = UtilCpuGetTicks(); \ spin_lock_wait_ticks += (uint64_t)(spin_lock_end - spin_lock_start); \ + \ + if (locks_idx < PROFILING_MAX_LOCKS && record_locks) { \ + locks[locks_idx].file = (char *)__FILE__; \ + locks[locks_idx].func = (char *)__func__; \ + locks[locks_idx].line = (int)__LINE__; \ + locks[locks_idx].type = LOCK_SPIN; \ + locks[locks_idx].cont = cont; \ + locks[locks_idx].ticks = (uint64_t)(spin_lock_end - spin_lock_start); \ + locks_idx++; \ + } \ retl; \ }) @@ -585,6 +623,73 @@ extern __thread uint64_t spin_lock_cnt; #define SCRWLockTryWRLock(rwl) SCRWLockTryWRLock_dbg(rwl) #define SCRWLockTryRDLock(rwl) SCRWLockTryRDLock_dbg(rwl) #define SCRWLockUnlock(rwl) SCRWLockUnlock_dbg(rwl) +#elif defined PROFILE_LOCKING +#define SCRWLockInit(rwl, rwlattr ) pthread_rwlock_init(rwl, rwlattr) +#define SCRWLockUnlock(rwl) pthread_rwlock_unlock(rwl) + +extern __thread uint64_t rww_lock_contention; +extern __thread uint64_t rww_lock_wait_ticks; +extern __thread uint64_t rww_lock_cnt; + +#define SCRWLockWRLock_profile(mut) ({ \ + rww_lock_cnt++; \ + int retl = 0; \ + int cont = 0; \ + uint64_t rww_lock_start = UtilCpuGetTicks(); \ + if (pthread_rwlock_trywrlock((mut)) != 0) { \ + rww_lock_contention++; \ + cont = 1; \ + retl = pthread_rwlock_wrlock(mut); \ + } \ + uint64_t rww_lock_end = UtilCpuGetTicks(); \ + rww_lock_wait_ticks += (uint64_t)(rww_lock_end - rww_lock_start); \ + \ + if (locks_idx < PROFILING_MAX_LOCKS && record_locks) { \ + locks[locks_idx].file = (char *)__FILE__; \ + locks[locks_idx].func = (char *)__func__; \ + locks[locks_idx].line = (int)__LINE__; \ + locks[locks_idx].type = LOCK_RWW; \ + locks[locks_idx].cont = cont; \ + locks[locks_idx].ticks = (uint64_t)(rww_lock_end - rww_lock_start); \ + locks_idx++; \ + } \ + retl; \ +}) + +extern __thread uint64_t rwr_lock_contention; +extern __thread uint64_t rwr_lock_wait_ticks; +extern __thread uint64_t rwr_lock_cnt; + +#define SCRWLockRDLock_profile(mut) ({ \ + rwr_lock_cnt++; \ + int retl = 0; \ + int cont = 0; \ + uint64_t rwr_lock_start = UtilCpuGetTicks(); \ + if (pthread_rwlock_tryrdlock((mut)) != 0) { \ + rwr_lock_contention++; \ + cont = 1; \ + retl = pthread_rwlock_rdlock(mut); \ + } \ + uint64_t rwr_lock_end = UtilCpuGetTicks(); \ + rwr_lock_wait_ticks += (uint64_t)(rwr_lock_end - rwr_lock_start); \ + \ + if (locks_idx < PROFILING_MAX_LOCKS && record_locks) { \ + locks[locks_idx].file = (char *)__FILE__; \ + locks[locks_idx].func = (char *)__func__; \ + locks[locks_idx].line = (int)__LINE__; \ + locks[locks_idx].type = LOCK_RWR; \ + locks[locks_idx].cont = cont; \ + locks[locks_idx].ticks = (uint64_t)(rwr_lock_end - rwr_lock_start); \ + locks_idx++; \ + } \ + retl; \ +}) + +#define SCRWLockWRLock(mut) SCRWLockWRLock_profile(mut) +#define SCRWLockRDLock(mut) SCRWLockRDLock_profile(mut) + +#define SCRWLockTryWRLock(rwl) pthread_rwlock_trywrlock(rwl) +#define SCRWLockTryRDLock(rwl) pthread_rwlock_tryrdlock(rwl) #else #define SCRWLockInit(rwl, rwlattr ) pthread_rwlock_init(rwl, rwlattr) #define SCRWLockWRLock(rwl) pthread_rwlock_wrlock(rwl) diff --git a/src/tm-threads.c b/src/tm-threads.c index 8b7fd7ccfb..c5eb4c9664 100644 --- a/src/tm-threads.c +++ b/src/tm-threads.c @@ -51,6 +51,14 @@ __thread uint64_t mutex_lock_cnt; __thread uint64_t spin_lock_contention; __thread uint64_t spin_lock_wait_ticks; __thread uint64_t spin_lock_cnt; + +__thread uint64_t rww_lock_contention; +__thread uint64_t rww_lock_wait_ticks; +__thread uint64_t rww_lock_cnt; + +__thread uint64_t rwr_lock_contention; +__thread uint64_t rwr_lock_wait_ticks; +__thread uint64_t rwr_lock_cnt; #endif #ifdef OS_FREEBSD diff --git a/src/util-error.c b/src/util-error.c index 2d064f61fd..450fbba0df 100644 --- a/src/util-error.c +++ b/src/util-error.c @@ -222,6 +222,7 @@ const char * SCErrorToString(SCError err) CASE_CODE (SC_ERR_PCAP_TRANSLATE); CASE_CODE (SC_WARN_OUTDATED_LIBHTP); CASE_CODE (SC_WARN_DEPRECATED); + CASE_CODE (SC_WARN_PROFILE); default: return "UNKNOWN_ERROR"; diff --git a/src/util-error.h b/src/util-error.h index 0fa52d26fb..ee0063a869 100644 --- a/src/util-error.h +++ b/src/util-error.h @@ -237,6 +237,7 @@ typedef enum { SC_ERR_PCAP_TRANSLATE, /* failed to translate ip to dev */ SC_WARN_OUTDATED_LIBHTP, SC_WARN_DEPRECATED, + SC_WARN_PROFILE, } SCError; const char *SCErrorToString(SCError); diff --git a/src/util-profiling-locks.c b/src/util-profiling-locks.c new file mode 100644 index 0000000000..b60bbd39ce --- /dev/null +++ b/src/util-profiling-locks.c @@ -0,0 +1,233 @@ +/* Copyright (C) 2007-2012 Open Information Security Foundation + * + * You can copy, redistribute or modify this Program under the terms of + * the GNU General Public License version 2 as published by the Free + * Software Foundation. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * version 2 along with this program; if not, write to the Free Software + * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA + * 02110-1301, USA. + */ + +/** + * \file + * + * \author Victor Julien + * + * An API for profiling locks. + * + */ + +#ifdef PROFILING +#ifdef PROFILE_LOCKING + +#include "suricata-common.h" +#include "util-profiling-locks.h" +#include "util-hashlist.h" + +__thread ProfilingLock locks[PROFILING_MAX_LOCKS]; +__thread int locks_idx = 0; +__thread int record_locks = 0; + +int profiling_locks_enabled = 0; +int profiling_locks_output_to_file = 0; +char *profiling_locks_file_name = NULL; +char *profiling_locks_file_mode = NULL; + +typedef struct LockRecord_ { + char *file; // hash + + char *func; // info + int type; // info + + int line; // hash + + uint32_t cont; + uint32_t ticks_cnt; + uint64_t ticks_total; + uint64_t ticks_max; +} LockRecord; + +HashListTable *lock_records; +pthread_mutex_t lock_records_mutex; + +static uint32_t LockRecordHash(HashListTable *ht, void *buf, uint16_t buflen) { + LockRecord *fn = (LockRecord *)buf; + uint32_t hash = strlen(fn->file) + fn->line; + uint16_t u; + + for (u = 0; u < strlen(fn->file); u++) { + hash += fn->file[u]; + } + + return hash % ht->array_size; +} + +static char LockRecordCompare(void *buf1, uint16_t len1, void *buf2, uint16_t len2) { + LockRecord *fn1 = (LockRecord *)buf1; + LockRecord *fn2 = (LockRecord *)buf2; + + if (fn1->line != fn2->line) + return 0; + + if (fn1->file == fn2->file) + return 1; + + return 0; +} + +static void LockRecordFree(void *data) { + LockRecord *fn = (LockRecord *)data; + + if (fn == NULL) + return; + SCFree(fn); +} + +int LockRecordInitHash() { + pthread_mutex_init(&lock_records_mutex, NULL); + pthread_mutex_lock(&lock_records_mutex); + + lock_records = HashListTableInit(512, LockRecordHash, LockRecordCompare, LockRecordFree); + BUG_ON(lock_records == NULL); + + pthread_mutex_unlock(&lock_records_mutex); + + return 0; +} + +void LockRecordAdd(ProfilingLock *l) { + LockRecord fn = { NULL, NULL, 0,0,0,0,0,0}, *ptr = &fn; + fn.file = l->file; + fn.line = l->line; + + LockRecord *lookup_fn = (LockRecord *)HashListTableLookup(lock_records, (void *)ptr, 0); + if (lookup_fn == NULL) { + LockRecord *new = SCMalloc(sizeof(LockRecord)); + BUG_ON(new == NULL); + + new->file = l->file; + new->line = l->line; + new->type = l->type; + new->cont = l->cont; + new->func = l->func; + new->ticks_max = l->ticks; + new->ticks_total = l->ticks; + new->ticks_cnt = 1; + + HashListTableAdd(lock_records, (void *)new, 0); + } else { + lookup_fn->ticks_total += l->ticks; + if (l->ticks > lookup_fn->ticks_max) + lookup_fn->ticks_max = l->ticks; + lookup_fn->ticks_cnt++; + lookup_fn->cont += l->cont; + } + + return; +} + +/** \param p void ptr to Packet struct */ +void SCProfilingAddPacketLocks(void *p) { + int i; + for (i = 0; i < locks_idx; i++) { + pthread_mutex_lock(&lock_records_mutex); + LockRecordAdd(&locks[i]); + pthread_mutex_unlock(&lock_records_mutex); + } +} + +void SCProfilingListLocks(void) { + FILE *fp = NULL; + + if (profiling_locks_output_to_file == 1) { + if (strcasecmp(profiling_locks_file_mode, "yes") == 0) { + fp = fopen(profiling_locks_file_name, "a"); + } else { + fp = fopen(profiling_locks_file_name, "w"); + } + + if (fp == NULL) { + SCLogError(SC_ERR_FOPEN, "failed to open %s: %s", + profiling_locks_file_name, strerror(errno)); + return; + } + } else { + fp = stdout; + } + + fprintf(fp, "\n\nLock Cnt Avg ticks Max ticks Total ticks Cont Func\n"); + fprintf(fp, "------------------ ---------- --------- ------------ ------------ ------- ---------\n"); + + uint64_t total = 0; + uint32_t cont = 0; + uint64_t cnt = 0; + + HashListTableBucket *b = HashListTableGetListHead(lock_records); + while (b) { + LockRecord *r = HashListTableGetListData(b); + + char *lock; + switch (r->type) { + case LOCK_MUTEX: + lock = "mtx"; + break; + case LOCK_SPIN: + lock = "spn"; + break; + case LOCK_RWW: + lock = "rww"; + break; + case LOCK_RWR: + lock = "rwr"; + break; + default: + lock = "bug"; + break; + } + + char str[128] = ""; + snprintf(str, sizeof(str), "(%s) %s:%d", lock,r->file, r->line); + + fprintf(fp, "%-50s %-10u %-9u %-12"PRIu64" %-12"PRIu64" %-7u %-s\n", + str, r->ticks_cnt, (int)r->ticks_total/r->ticks_cnt, r->ticks_max, r->ticks_total, r->cont, r->func); + + total += r->ticks_total; + cnt += r->ticks_cnt; + cont += r->cont; + + b = HashListTableGetListNext(b); + } + + fprintf(fp, "\nOverall: locks %"PRIu64", average cost %"PRIu64", contentions %"PRIu32", total ticks %"PRIu64"\n", + cnt, total/cnt, cont, total); + + fclose(fp); +} + +void LockRecordFreeHash() { + if (profiling_locks_enabled == 0) + return; + + pthread_mutex_lock(&lock_records_mutex); + + SCProfilingListLocks(); + + if (lock_records != NULL) { + HashListTableFree(lock_records); + lock_records = NULL; + } + pthread_mutex_unlock(&lock_records_mutex); + + pthread_mutex_destroy(&lock_records_mutex); +} + +#endif +#endif + diff --git a/src/util-profiling-locks.h b/src/util-profiling-locks.h new file mode 100644 index 0000000000..453928a0b0 --- /dev/null +++ b/src/util-profiling-locks.h @@ -0,0 +1,45 @@ +/* Copyright (C) 2007-2012 Open Information Security Foundation + * + * You can copy, redistribute or modify this Program under the terms of + * the GNU General Public License version 2 as published by the Free + * Software Foundation. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * version 2 along with this program; if not, write to the Free Software + * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA + * 02110-1301, USA. + */ + +/** + * \file + * + * \author Victor Julien + */ + +#ifndef __UTIL_PROFILE_LOCKS_H__ +#define __UTIL_PROFILE_LOCKS_H__ + +#ifdef PROFILING + +#define PROFILING_MAX_LOCKS 64 + +enum { + LOCK_MUTEX, + LOCK_SPIN, + LOCK_RWW, /**< rwlock, writer */ + LOCK_RWR, /**< rwlock, reader */ +}; + +void SCProfilingAddPacketLocks(void *); + +int LockRecordInitHash(); +void LockRecordFreeHash(); + +#endif /* PROFILING */ +#endif /* __UTIL_PROFILE_LOCKS_H__ */ + diff --git a/src/util-profiling.c b/src/util-profiling.c index 50e70e2b0b..00e2f80a9b 100644 --- a/src/util-profiling.c +++ b/src/util-profiling.c @@ -1,4 +1,4 @@ -/* Copyright (C) 2007-2011 Open Information Security Foundation +/* Copyright (C) 2007-2012 Open Information Security Foundation * * You can copy, redistribute or modify this Program under the terms of * the GNU General Public License version 2 as published by the Free @@ -27,7 +27,7 @@ */ #include "suricata-common.h" - +#include "decode.h" #include "detect.h" #include "counters.h" #include "conf.h" @@ -37,6 +37,7 @@ #include "util-unittest.h" #include "util-byte.h" #include "util-profiling.h" +#include "util-profiling-locks.h" #ifdef PROFILING @@ -66,9 +67,14 @@ static uint32_t profiling_rules_limit = UINT32_MAX; static SCPerfContext rules_ctx; static SCPerfCounterArray *rules_pca; -static SCMutex packet_profile_lock; +static pthread_mutex_t packet_profile_lock; static FILE *packet_profile_csv_fp = NULL; +extern int profiling_locks_enabled; +extern int profiling_locks_output_to_file; +extern char *profiling_locks_file_name; +extern char *profiling_locks_file_mode; + /** * Extra data for rule profiling. */ @@ -166,7 +172,7 @@ SCProfilingInit(void) memset(rules_profile_data, 0, sizeof(rules_profile_data)); memset(&rules_ctx, 0, sizeof(rules_ctx)); rules_pca = SCPerfGetAllCountersArray(NULL); - if (SCMutexInit(&rules_ctx.m, NULL) != 0) { + if (pthread_mutex_init(&rules_ctx.m, NULL) != 0) { SCLogError(SC_ERR_MUTEX, "Failed to initialize hash table mutex."); exit(EXIT_FAILURE); @@ -242,7 +248,7 @@ SCProfilingInit(void) if (ConfNodeChildValueIsTrue(conf, "enabled")) { profiling_packets_enabled = 1; - if (SCMutexInit(&packet_profile_lock, NULL) != 0) { + if (pthread_mutex_init(&packet_profile_lock, NULL) != 0) { SCLogError(SC_ERR_MUTEX, "Failed to initialize packet profiling mutex."); exit(EXIT_FAILURE); @@ -319,6 +325,36 @@ SCProfilingInit(void) } } } + + conf = ConfGetNode("profiling.locks"); + if (conf != NULL) { + if (ConfNodeChildValueIsTrue(conf, "enabled")) { +#ifndef PROFILE_LOCKING + SCLogWarning(SC_WARN_PROFILE, "lock profiling not compiled in. Add --enable-profiling-locks to configure."); +#else + profiling_locks_enabled = 1; + + LockRecordInitHash(); + + const char *filename = ConfNodeLookupChildValue(conf, "filename"); + if (filename != NULL) { + char *log_dir; + if (ConfGet("default-log-dir", &log_dir) != 1) + log_dir = DEFAULT_LOG_DIR; + + profiling_locks_file_name = SCMalloc(PATH_MAX); + snprintf(profiling_locks_file_name, PATH_MAX, "%s/%s", log_dir, filename); + + profiling_locks_file_mode = (char *)ConfNodeLookupChildValue(conf, "append"); + if (profiling_locks_file_mode == NULL) + profiling_locks_file_mode = DEFAULT_LOG_MODE_APPEND; + + profiling_locks_output_to_file = 1; + } +#endif + } + } + } /** @@ -330,11 +366,11 @@ SCProfilingDestroy(void) if (profiling_rules_enabled) { SCPerfReleasePerfCounterS(rules_ctx.head); SCPerfReleasePCA(rules_pca); - SCMutexDestroy(&rules_ctx.m); + pthread_mutex_destroy(&rules_ctx.m); } if (profiling_packets_enabled) { - SCMutexDestroy(&packet_profile_lock); + pthread_mutex_destroy(&packet_profile_lock); } if (profiling_packets_csv_enabled) { @@ -347,6 +383,10 @@ SCProfilingDestroy(void) if (profiling_file_name != NULL) SCFree(profiling_file_name); + +#ifdef PROFILE_LOCKING + LockRecordFreeHash(); +#endif } /** @@ -651,7 +691,7 @@ SCProfilingCounterAddUI64(uint16_t id, uint64_t val) void SCProfilingUpdateRuleCounter(uint16_t id, uint64_t ticks, int match) { - SCMutexLock(&rules_ctx.m); + pthread_mutex_lock(&rules_ctx.m); SCProfilingCounterAddUI64(id, ticks); rules_profile_data[id].matches += match; if (ticks > rules_profile_data[id].max) @@ -661,7 +701,7 @@ SCProfilingUpdateRuleCounter(uint16_t id, uint64_t ticks, int match) else rules_profile_data[id].ticks_no_match += ticks; - SCMutexUnlock(&rules_ctx.m); + pthread_mutex_unlock(&rules_ctx.m); } void SCProfilingDumpPacketStats(void) { @@ -1074,7 +1114,7 @@ void SCProfilingAddPacket(Packet *p) { if (p->profile.ticks_start == 0 || p->profile.ticks_end == 0 || p->profile.ticks_start > p->profile.ticks_end) return; - SCMutexLock(&packet_profile_lock); + pthread_mutex_lock(&packet_profile_lock); { if (profiling_packets_csv_enabled) @@ -1145,7 +1185,7 @@ void SCProfilingAddPacket(Packet *p) { SCProfilingUpdatePacketDetectRecords(p); } } - SCMutexUnlock(&packet_profile_lock); + pthread_mutex_unlock(&packet_profile_lock); } #define CASE_CODE(E) case E: return #E @@ -1184,6 +1224,9 @@ const char * PacketProfileDetectIdToString(PacketProfileDetectId id) return "UNKNOWN"; } } + + + #ifdef UNITTESTS static int diff --git a/src/util-profiling.h b/src/util-profiling.h index 4f99085e7b..51f6f21996 100644 --- a/src/util-profiling.h +++ b/src/util-profiling.h @@ -1,4 +1,4 @@ -/* Copyright (C) 2007-2011 Open Information Security Foundation +/* Copyright (C) 2007-2012 Open Information Security Foundation * * You can copy, redistribute or modify this Program under the terms of * the GNU General Public License version 2 as published by the Free @@ -27,6 +27,7 @@ #ifdef PROFILING +#include "util-profiling-locks.h" #include "util-cpu.h" extern int profiling_rules_enabled; @@ -75,6 +76,14 @@ void SCProfilingAddPacket(Packet *); spin_lock_cnt = 0; \ spin_lock_wait_ticks = 0; \ spin_lock_contention = 0; \ + rww_lock_cnt = 0; \ + rww_lock_wait_ticks = 0; \ + rww_lock_contention = 0; \ + rwr_lock_cnt = 0; \ + rwr_lock_wait_ticks = 0; \ + rwr_lock_contention = 0; \ + locks_idx = 0; \ + record_locks = 1;\ } while (0) #define PACKET_PROFILING_COPY_LOCKS(p, id) do { \ @@ -84,6 +93,14 @@ void SCProfilingAddPacket(Packet *); (p)->profile.tmm[(id)].spin_lock_cnt = spin_lock_cnt; \ (p)->profile.tmm[(id)].spin_lock_wait_ticks = spin_lock_wait_ticks; \ (p)->profile.tmm[(id)].spin_lock_contention = spin_lock_contention; \ + (p)->profile.tmm[(id)].rww_lock_cnt = rww_lock_cnt; \ + (p)->profile.tmm[(id)].rww_lock_wait_ticks = rww_lock_wait_ticks; \ + (p)->profile.tmm[(id)].rww_lock_contention = rww_lock_contention; \ + (p)->profile.tmm[(id)].rwr_lock_cnt = rwr_lock_cnt; \ + (p)->profile.tmm[(id)].rwr_lock_wait_ticks = rwr_lock_wait_ticks; \ + (p)->profile.tmm[(id)].rwr_lock_contention = rwr_lock_contention; \ + record_locks = 0;\ + SCProfilingAddPacketLocks((p)); \ } while(0) #else #define PACKET_PROFILING_RESET_LOCKS diff --git a/suricata.yaml.in b/suricata.yaml.in index 693f4847f1..f16aac4614 100644 --- a/suricata.yaml.in +++ b/suricata.yaml.in @@ -872,6 +872,13 @@ profiling: enabled: no filename: packet_stats.csv + # profiling of locking. Only available when Suricata was built with + # --enable-profiling-locks. + locks: + enabled: no + filename: lock_stats.log + append: yes + # Suricata core dump configuration. Limits the size of the core dump file to # approximately max-dump. The actual core dump size will be a multiple of the # page size. Core dumps that would be larger than max-dump are truncated. On