]> git.ipfire.org Git - thirdparty/suricata.git/commitdiff
profiling: add per lock location profiling
authorVictor Julien <victor@inliniac.net>
Mon, 19 Mar 2012 09:28:34 +0000 (10:28 +0100)
committerVictor Julien <victor@inliniac.net>
Mon, 19 Mar 2012 09:28:34 +0000 (10:28 +0100)
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.

14 files changed:
configure.in
src/Makefile.am
src/decode.h
src/suricata-common.h
src/suricata.c
src/threads.h
src/tm-threads.c
src/util-error.c
src/util-error.h
src/util-profiling-locks.c [new file with mode: 0644]
src/util-profiling-locks.h [new file with mode: 0644]
src/util-profiling.c
src/util-profiling.h
suricata.yaml.in

index e861909bbdb54c0161d79591ca6007d4a76391b3..fdf670e7edf4aa18b766c73746d52aabfefb2916 100644 (file)
@@ -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}
index 84f882c07262c9f19d09aa18a3ea62563b2f0d16..f3c9e7c451860c7ae2b842e6c90646ffe2794b47 100644 (file)
@@ -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
index 0e79c47c0af05fbed7038b0a3a0e596665ae9a78..83b0a61074a9c40ba208821636100200c8484686 100644 (file)
@@ -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_ {
index b7345fd9bc1cf1e2c00bf7888cae23666797b187..f8e58853249cd3423936427d9ce5b8f10e98d860 100644 (file)
@@ -30,8 +30,6 @@
 #define DBG_PERF
 #endif
 
-//#define PROFILE_LOCKING
-
 #define TRUE   1
 #define FALSE  0
 
index b1db347886c0a8158dd8a829f088821af1ecd7fb..6d65905b308a31714137aea2d653ee814751733c 100644 (file)
@@ -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));
index 71fc718c08833f07615d75df32a2db71b56a1342..c4e9bba5493a64a6739053a5c92886dfd5e28d06 100644 (file)
@@ -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)
index 8b7fd7ccfb335992a3b323aae2ea13a72003780f..c5eb4c9664fc9bafbcbab659250eff0d3795d400 100644 (file)
@@ -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
index 2d064f61fd8786d2ece395c517941f952c1411dc..450fbba0df75d1e4aef5eceec85e229c458e865d 100644 (file)
@@ -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";
index 0fa52d26fbecf30e3c98b40a5c8b79a5029876f9..ee0063a869634dde7c92f81337c5b0f12fd1bf01 100644 (file)
@@ -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 (file)
index 0000000..b60bbd3
--- /dev/null
@@ -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 <victor@inliniac.net>
+ *
+ * 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 (file)
index 0000000..453928a
--- /dev/null
@@ -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 <victor@inliniac.net>
+ */
+
+#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__ */
+
index 50e70e2b0b21bbd5e8b86f6d99b89b0b7951fc4f..00e2f80a9bb15d31ea87dbe00b00851a80334831 100644 (file)
@@ -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
index 4f99085e7b734b53cb48a62ce44919319cf0183f..51f6f219960fae3044102d184d9b65c8677f938b 100644 (file)
@@ -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
index 693f4847f136c828c6e0b77a800092395232e94c..f16aac46146b5c06409e613db942012763e772a1 100644 (file)
@@ -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