Add way to profile mutex/spin locks per thread module.

src/decode.h

@@ -284,6 +284,12 @@ typedef struct PktVar_ {
 typedef struct PktProfilingTmmData_ {
     uint64_t ticks_start;
     uint64_t ticks_end;
+    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;
 } PktProfilingTmmData;
 
 typedef struct PktProfilingDetectData_ {

src/threads.h

@@ -27,6 +27,10 @@
 #ifndef __THREADS_H__
 #define __THREADS_H__
 
+#ifdef PROFILING
+#include "util-cpu.h"
+#endif
+
 #if defined OS_FREEBSD || __OpenBSD__
 
 #if ! defined __OpenBSD__
@@ -223,6 +227,31 @@ enum {
 #define SCMutexLock(mut) SCMutexLock_dbg(mut)
 #define SCMutexTrylock(mut) SCMutexTrylock_dbg(mut)
 #define SCMutexUnlock(mut) SCMutexUnlock_dbg(mut)
+#elif defined PROFILE_LOCKING
+#define SCMutexInit(mut, mutattr ) pthread_mutex_init(mut, mutattr)
+#define SCMutexUnlock(mut) pthread_mutex_unlock(mut)
+
+extern __thread uint64_t mutex_lock_contention;
+extern __thread uint64_t mutex_lock_wait_ticks;
+extern __thread uint64_t mutex_lock_cnt;
+
+//printf("%16s(%s:%d): (thread:%"PRIuMAX") locked mutex %p ret %" PRId32 "\n", __FUNCTION__, __FILE__, __LINE__, (uintmax_t)pthread_self(), mut, retl);
+#define SCMutexLock_profile(mut) ({ \
+    mutex_lock_cnt++; \
+    int retl = 0; \
+    uint64_t mutex_lock_start = UtilCpuGetTicks(); \
+    if (pthread_mutex_trylock((mut)) != 0) { \
+        mutex_lock_contention++; \
+        retl = pthread_mutex_lock(mut); \
+    } \
+    uint64_t mutex_lock_end = UtilCpuGetTicks(); \
+    mutex_lock_wait_ticks += (uint64_t)(mutex_lock_end - mutex_lock_start); \
+    retl; \
+})
+
+#define SCMutexLock(mut) SCMutexLock_profile(mut)
+#define SCMutexTrylock(mut) pthread_mutex_trylock(mut)
+
 #else
 #define SCMutexInit(mut, mutattr ) pthread_mutex_init(mut, mutattr)
 #define SCMutexLock(mut) pthread_mutex_lock(mut)
@@ -362,6 +391,32 @@ enum {
 #define SCSpinUnlock                            SCSpinUnlock_dbg
 #define SCSpinInit                              SCSpinInit_dbg
 #define SCSpinDestroy                           SCSpinDestroy_dbg
+#elif defined PROFILE_LOCKING
+
+extern __thread uint64_t spin_lock_contention;
+extern __thread uint64_t spin_lock_wait_ticks;
+extern __thread uint64_t spin_lock_cnt;
+
+//printf("%16s(%s:%d): (thread:%"PRIuMAX") locked mutex %p ret %" PRId32 "\n", __FUNCTION__, __FILE__, __LINE__, (uintmax_t)pthread_self(), mut, retl);
+#define SCSpinLock_profile(spin) ({ \
+    spin_lock_cnt++; \
+    int retl = 0; \
+    uint64_t spin_lock_start = UtilCpuGetTicks(); \
+    if (pthread_spin_trylock((spin)) != 0) { \
+        spin_lock_contention++; \
+        retl = pthread_spin_lock((spin)); \
+    } \
+    uint64_t spin_lock_end = UtilCpuGetTicks(); \
+    spin_lock_wait_ticks += (uint64_t)(spin_lock_end - spin_lock_start); \
+    retl; \
+})
+
+#define SCSpinLock(mut) SCSpinLock_profile(mut)
+#define SCSpinTrylock(spin)                     pthread_spin_trylock(spin)
+#define SCSpinUnlock(spin)                      pthread_spin_unlock(spin)
+#define SCSpinInit(spin, spin_attr)             pthread_spin_init(spin, spin_attr)
+#define SCSpinDestroy(spin)                     pthread_spin_destroy(spin)
+
 #else /* if no dbg threads defined... */
 #define SCSpinLock(spin)                        pthread_spin_lock(spin)
 #define SCSpinTrylock(spin)                     pthread_spin_trylock(spin)

src/tm-modules.c

@@ -246,6 +246,8 @@ const char * TmModuleTmmIdToString(TmmId id)
         CASE_CODE (TMM_LOGHTTPLOG4);
         CASE_CODE (TMM_LOGHTTPLOG6);
         CASE_CODE (TMM_PCAPLOG);
+        CASE_CODE (TMM_FILELOG);
+        CASE_CODE (TMM_FILESTORE);
         CASE_CODE (TMM_STREAMTCP);
         CASE_CODE (TMM_DECODEIPFW);
         CASE_CODE (TMM_VERDICTIPFW);
@@ -261,6 +263,7 @@ const char * TmModuleTmmIdToString(TmmId id)
         CASE_CODE (TMM_RECEIVENAPATECH);
         CASE_CODE (TMM_DECODENAPATECH);
         CASE_CODE (TMM_RECEIVEAFP);
+        CASE_CODE (TMM_ALERTPCAPINFO);
         CASE_CODE (TMM_DECODEAFP);
 
         default:

src/tm-threads.c

@@ -43,6 +43,16 @@
 #include "util-optimize.h"
 #include "util-profiling.h"
 
+#ifdef PROFILE_LOCKING
+__thread uint64_t mutex_lock_contention;
+__thread uint64_t mutex_lock_wait_ticks;
+__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;
+#endif
+
 #ifdef OS_FREEBSD
 #include <sched.h>
 #include <sys/param.h>

src/util-profiling.c

@@ -87,6 +87,15 @@ typedef struct SCProfilePacketData_ {
     uint64_t max;
     uint64_t tot;
     uint64_t cnt;
+#ifdef PROFILE_LOCKING
+    uint64_t lock;
+    uint64_t ticks;
+    uint64_t contention;
+
+    uint64_t slock;
+    uint64_t sticks;
+    uint64_t scontention;
+#endif
 } SCProfilePacketData;
 SCProfilePacketData packet_profile_data4[257]; /**< all proto's + tunnel */
 SCProfilePacketData packet_profile_data6[257]; /**< all proto's + tunnel */
@@ -710,10 +719,22 @@ void SCProfilingDumpPacketStats(void) {
 
     fprintf(fp, "\nPer Thread module stats:\n");
 
-    fprintf(fp, "\n%-24s   %-6s   %-5s   %-12s   %-12s   %-12s   %-12s\n",
+    fprintf(fp, "\n%-24s   %-6s   %-5s   %-12s   %-12s   %-12s   %-12s",
             "Thread Module", "IP ver", "Proto", "cnt", "min", "max", "avg");
-    fprintf(fp, "%-24s   %-6s   %-5s   %-12s   %-12s   %-12s   %-12s\n",
+#ifdef PROFILE_LOCKING
+    fprintf(fp, "   %-10s   %-10s   %-12s   %-12s   %-10s   %-10s   %-12s   %-12s\n",
+            "locks", "ticks", "cont.", "cont.avg", "slocks", "sticks", "scont.", "scont.avg");
+#else
+    fprintf(fp, "\n");
+#endif
+    fprintf(fp, "%-24s   %-6s   %-5s   %-12s   %-12s   %-12s   %-12s",
             "------------------------", "------", "-----", "----------", "------------", "------------", "-----------");
+#ifdef PROFILE_LOCKING
+    fprintf(fp, "   %-10s   %-10s   %-12s   %-12s   %-10s   %-10s   %-12s   %-12s\n",
+            "--------", "--------", "----------", "-----------", "--------", "--------", "------------", "-----------");
+#else
+    fprintf(fp, "\n");
+#endif
     int m;
     for (m = 0; m < TMM_SIZE; m++) {
         int p;
@@ -724,8 +745,14 @@ void SCProfilingDumpPacketStats(void) {
                 continue;
             }
 
-            fprintf(fp, "%-24s    IPv4     %3d  %12"PRIu64"     %12"PRIu64"   %12"PRIu64"  %12"PRIu64"\n",
+            fprintf(fp, "%-24s    IPv4     %3d  %12"PRIu64"     %12"PRIu64"   %12"PRIu64"  %12"PRIu64,
                     TmModuleTmmIdToString(m), p, pd->cnt, pd->min, pd->max, (uint64_t)(pd->tot / pd->cnt));
+#ifdef PROFILE_LOCKING
+            fprintf(fp, "  %10.2f  %12"PRIu64"  %12"PRIu64"  %10.2f  %10.2f  %12"PRIu64"  %12"PRIu64"  %10.2f\n",
+                    (float)pd->lock/pd->cnt, (uint64_t)pd->ticks/pd->cnt, pd->contention, (float)pd->contention/pd->cnt, (float)pd->slock/pd->cnt, (uint64_t)pd->sticks/pd->cnt, pd->scontention, (float)pd->scontention/pd->cnt);
+#else
+            fprintf(fp, "\n");
+#endif
         }
     }
 
@@ -1015,6 +1042,15 @@ void SCProfilingUpdatePacketTmmRecord(int module, uint8_t proto, PktProfilingTmm
 
     pd->tot += (uint64_t)delta;
     pd->cnt ++;
+
+#ifdef PROFILE_LOCKING
+    pd->lock += pdt->mutex_lock_cnt;
+    pd->ticks += pdt->mutex_lock_wait_ticks;
+    pd->contention += pdt->mutex_lock_contention;
+    pd->slock += pdt->spin_lock_cnt;
+    pd->sticks += pdt->spin_lock_wait_ticks;
+    pd->scontention += pdt->spin_lock_contention;
+#endif
 }
 
 void SCProfilingUpdatePacketTmmRecords(Packet *p) {

src/util-profiling.h

@@ -27,6 +27,8 @@
 
 #ifdef PROFILING
 
+//#define PROFILE_LOCKING
+
 #include "util-cpu.h"
 
 extern int profiling_rules_enabled;
@@ -67,16 +69,41 @@ void SCProfilingAddPacket(Packet *);
         SCProfilingAddPacket((p));                                  \
     }
 
+#ifdef PROFILE_LOCKING
+#define PACKET_PROFILING_RESET_LOCKS do {                           \
+        mutex_lock_cnt = 0;                                         \
+        mutex_lock_wait_ticks = 0;                                  \
+        mutex_lock_contention = 0;                                  \
+        spin_lock_cnt = 0;                                          \
+        spin_lock_wait_ticks = 0;                                   \
+        spin_lock_contention = 0;                                   \
+    } while (0)
+
+#define PACKET_PROFILING_COPY_LOCKS(p, id) do {                     \
+            (p)->profile.tmm[(id)].mutex_lock_cnt = mutex_lock_cnt; \
+            (p)->profile.tmm[(id)].mutex_lock_wait_ticks = mutex_lock_wait_ticks; \
+            (p)->profile.tmm[(id)].mutex_lock_contention = mutex_lock_contention; \
+            (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; \
+    } while(0)
+#else
+#define PACKET_PROFILING_RESET_LOCKS
+#define PACKET_PROFILING_COPY_LOCKS(p, id)
+#endif
+
 #define PACKET_PROFILING_TMM_START(p, id)                           \
     if (profiling_packets_enabled) {                                \
         if ((id) < TMM_SIZE) {                                      \
             (p)->profile.tmm[(id)].ticks_start = UtilCpuGetTicks(); \
+            PACKET_PROFILING_RESET_LOCKS;                           \
         }                                                           \
     }
 
 #define PACKET_PROFILING_TMM_END(p, id)                             \
     if (profiling_packets_enabled) {                                \
         if ((id) < TMM_SIZE) {                                      \
+            PACKET_PROFILING_COPY_LOCKS((p), (id));                 \
             (p)->profile.tmm[(id)].ticks_end = UtilCpuGetTicks();   \
         }                                                           \
     }