From: Victor Julien Date: Fri, 9 Mar 2012 16:45:09 +0000 (+0100) Subject: Add way to profile mutex/spin locks per thread module. X-Git-Tag: suricata-1.3beta1~118 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=979edf0b974d7d8dbe1dd0020590fbb43f668850;p=thirdparty%2Fsuricata.git Add way to profile mutex/spin locks per thread module. --- diff --git a/src/decode.h b/src/decode.h index ed27a6f806..0e79c47c0a 100644 --- a/src/decode.h +++ b/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_ { diff --git a/src/threads.h b/src/threads.h index a1e58653d9..71fc718c08 100644 --- a/src/threads.h +++ b/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) diff --git a/src/tm-modules.c b/src/tm-modules.c index 436fee1c2a..aa6f895b68 100644 --- a/src/tm-modules.c +++ b/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: diff --git a/src/tm-threads.c b/src/tm-threads.c index 2623d7a936..8b7fd7ccfb 100644 --- a/src/tm-threads.c +++ b/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 #include diff --git a/src/util-profiling.c b/src/util-profiling.c index 0ce760c4f5..50e70e2b0b 100644 --- a/src/util-profiling.c +++ b/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) { diff --git a/src/util-profiling.h b/src/util-profiling.h index 4bc2ac7c34..1dce64c90a 100644 --- a/src/util-profiling.h +++ b/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(); \ } \ }