summaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorPhilip Withnall <philip@tecnocode.co.uk>2011-09-19 17:24:02 +0100
committerLennart Poettering <lennart@poettering.net>2011-09-19 23:58:43 +0200
commite23dc4213bbe4238a3c22fdad229e92c9d1f0553 (patch)
tree73c188b684127b3763bd27e271d537637d408f3c
parentb205ffc3a6bd39d6575f7a051e1d0a8b1137c1ab (diff)
Add support for profiling condition variablesHEADmaster
This adds a separate hash table of structures for profiling data for each condition variable in the program. Statistics such as the number of waits, signals, number of contended waits (waits while another thread is already waiting), contended signals (signals while no threads are waiting) and contention time are collected and presented in a second table in the summary printout.
-rw-r--r--mutrace.c752
-rwxr-xr-xmutrace.in48
2 files changed, 716 insertions, 84 deletions
diff --git a/mutrace.c b/mutrace.c
index 67be2b5..0de5bb1 100644
--- a/mutrace.c
+++ b/mutrace.c
@@ -105,13 +105,49 @@ struct mutex_info {
struct mutex_info *next;
};
+struct cond_info {
+ pthread_cond_t *cond;
+
+ bool broken:1;
+ bool realtime:1;
+ bool dead:1;
+
+ unsigned n_wait_level;
+ pthread_mutex_t *mutex;
+
+ unsigned n_wait;
+ unsigned n_signal;
+ unsigned n_broadcast;
+
+ unsigned n_wait_contended; /* number of wait() calls made while another
+ * thread is already waiting on the cond */
+ unsigned n_signal_contended; /* number of signal() or broadcast() calls
+ * made while no thread is waiting */
+
+ uint64_t nsec_wait_total;
+ uint64_t nsec_wait_max;
+
+ uint64_t nsec_wait_contended_total;
+ uint64_t nsec_wait_contended_max;
+
+ uint64_t nsec_timestamp;
+ struct stacktrace_info stacktrace;
+
+ unsigned id;
+
+ struct cond_info *next;
+};
+
static unsigned hash_size = 3371; /* probably a good idea to pick a prime here */
static unsigned frames_max = 16;
-static volatile unsigned n_broken = 0;
+static volatile unsigned n_broken_mutexes = 0;
+static volatile unsigned n_broken_conds = 0;
+
static volatile unsigned n_collisions = 0;
static volatile unsigned n_self_contended = 0;
+static unsigned show_n_wait_min = 1;
static unsigned show_n_locked_min = 1;
static unsigned show_n_read_locked_min = 0;
static unsigned show_n_contended_min = 0;
@@ -128,6 +164,10 @@ static int (*real_pthread_mutex_lock)(pthread_mutex_t *mutex) = NULL;
static int (*real_pthread_mutex_trylock)(pthread_mutex_t *mutex) = NULL;
static int (*real_pthread_mutex_timedlock)(pthread_mutex_t *mutex, const struct timespec *abstime) = NULL;
static int (*real_pthread_mutex_unlock)(pthread_mutex_t *mutex) = NULL;
+static int (*real_pthread_cond_init)(pthread_cond_t *cond, const pthread_condattr_t *attr) = NULL;
+static int (*real_pthread_cond_destroy)(pthread_cond_t *cond) = NULL;
+static int (*real_pthread_cond_signal)(pthread_cond_t *cond) = NULL;
+static int (*real_pthread_cond_broadcast)(pthread_cond_t *cond) = NULL;
static int (*real_pthread_cond_wait)(pthread_cond_t *cond, pthread_mutex_t *mutex) = NULL;
static int (*real_pthread_cond_timedwait)(pthread_cond_t *cond, pthread_mutex_t *mutex, const struct timespec *abstime) = NULL;
static int (*real_pthread_create)(pthread_t *newthread, const pthread_attr_t *attr, void *(*start_routine) (void *), void *arg) = NULL;
@@ -150,6 +190,9 @@ static void (*real_backtrace_symbols_fd)(void *const *array, int size, int fd) =
static struct mutex_info **alive_mutexes = NULL, **dead_mutexes = NULL;
static pthread_mutex_t *mutexes_lock = NULL;
+static struct cond_info **alive_conds = NULL, **dead_conds = NULL;
+static pthread_mutex_t *conds_lock = NULL;
+
static __thread bool recursive = false;
static volatile bool initialized = false;
@@ -157,34 +200,34 @@ static volatile bool threads_existing = false;
static uint64_t nsec_timestamp_setup;
-/* Must be kept in sync with summary_order_details. */
-typedef enum {
- ORDER_ID = 0,
- ORDER_N_LOCKED,
- ORDER_N_READ_LOCKED,
- ORDER_N_CONTENDED,
- ORDER_N_READ_CONTENDED,
- ORDER_N_OWNER_CHANGED,
- ORDER_NSEC_LOCKED_TOTAL,
- ORDER_NSEC_LOCKED_MAX,
- ORDER_NSEC_LOCKED_AVG,
- ORDER_NSEC_READ_LOCKED_TOTAL,
- ORDER_NSEC_READ_LOCKED_MAX,
- ORDER_NSEC_READ_LOCKED_AVG,
- ORDER_NSEC_CONTENDED_TOTAL,
- ORDER_NSEC_CONTENDED_AVG,
- ORDER_NSEC_READ_CONTENDED_TOTAL,
- ORDER_NSEC_READ_CONTENDED_AVG,
-} SummaryOrder;
-#define ORDER_INVALID ORDER_NSEC_READ_CONTENDED_AVG + 1 /* first invalid order */
-
typedef struct {
const char *command; /* as passed to --order command line argument */
const char *ui_string; /* as displayed by show_summary() */
} SummaryOrderDetails;
-/* Must be kept in sync with SummaryOrder. */
-static const SummaryOrderDetails summary_order_details[] = {
+/* Must be kept in sync with summary_mutex_order_details. */
+typedef enum {
+ MUTEX_ORDER_ID = 0,
+ MUTEX_ORDER_N_LOCKED,
+ MUTEX_ORDER_N_READ_LOCKED,
+ MUTEX_ORDER_N_CONTENDED,
+ MUTEX_ORDER_N_READ_CONTENDED,
+ MUTEX_ORDER_N_OWNER_CHANGED,
+ MUTEX_ORDER_NSEC_LOCKED_TOTAL,
+ MUTEX_ORDER_NSEC_LOCKED_MAX,
+ MUTEX_ORDER_NSEC_LOCKED_AVG,
+ MUTEX_ORDER_NSEC_READ_LOCKED_TOTAL,
+ MUTEX_ORDER_NSEC_READ_LOCKED_MAX,
+ MUTEX_ORDER_NSEC_READ_LOCKED_AVG,
+ MUTEX_ORDER_NSEC_CONTENDED_TOTAL,
+ MUTEX_ORDER_NSEC_CONTENDED_AVG,
+ MUTEX_ORDER_NSEC_READ_CONTENDED_TOTAL,
+ MUTEX_ORDER_NSEC_READ_CONTENDED_AVG,
+} SummaryMutexOrder;
+#define MUTEX_ORDER_INVALID MUTEX_ORDER_NSEC_READ_CONTENDED_AVG + 1 /* first invalid order */
+
+/* Must be kept in sync with SummaryMutexOrder. */
+static const SummaryOrderDetails summary_mutex_order_details[] = {
{ "id", "mutex number" },
{ "n-locked", "(write) lock count" },
{ "n-read-locked", "(read) lock count" },
@@ -203,9 +246,46 @@ static const SummaryOrderDetails summary_order_details[] = {
{ "nsec-read-contended-avg", "average time (read) contended" },
};
-static SummaryOrder summary_order = ORDER_N_CONTENDED;
+static SummaryMutexOrder summary_mutex_order = MUTEX_ORDER_N_CONTENDED;
+
+static SummaryMutexOrder summary_mutex_order_from_command(const char *command);
+
+/* Must be kept in sync with summary_cond_order_details. */
+typedef enum {
+ COND_ORDER_ID = 0,
+ COND_ORDER_N_WAIT,
+ COND_ORDER_N_SIGNAL,
+ COND_ORDER_N_BROADCAST,
+ COND_ORDER_N_WAIT_CONTENDED,
+ COND_ORDER_N_SIGNAL_CONTENDED,
+ COND_ORDER_NSEC_WAIT_TOTAL,
+ COND_ORDER_NSEC_WAIT_MAX,
+ COND_ORDER_NSEC_WAIT_AVG,
+ COND_ORDER_NSEC_WAIT_CONTENDED_TOTAL,
+ COND_ORDER_NSEC_WAIT_CONTENDED_MAX,
+ COND_ORDER_NSEC_WAIT_CONTENDED_AVG,
+} SummaryCondOrder;
+#define COND_ORDER_INVALID COND_ORDER_NSEC_WAIT_CONTENDED_AVG + 1 /* first invalid order */
+
+/* Must be kept in sync with SummaryCondOrder. */
+static const SummaryOrderDetails summary_cond_order_details[] = {
+ { "id", "condition variable number" },
+ { "n-wait", "wait count" },
+ { "n-signal", "signal count" },
+ { "n-broadcast", "broadcast count" },
+ { "n-wait-contended", "wait contention count" },
+ { "n-signal-contended", "signal contention count" },
+ { "nsec-wait-total", "total wait time" },
+ { "nsec-wait-max", "maximum wait time" },
+ { "nsec-wait-avg", "average wait time" },
+ { "nsec-wait-contended-total", "total contended wait time" },
+ { "nsec-wait-contended-max", "maximum contended wait time" },
+ { "nsec-wait-contended-avg", "average contended wait time" },
+};
+
+static SummaryCondOrder summary_cond_order = COND_ORDER_N_WAIT_CONTENDED;
-static SummaryOrder summary_order_from_command(const char *command);
+static SummaryCondOrder summary_cond_order_from_command(const char *command);
static void setup(void) __attribute ((constructor));
static void shutdown(void) __attribute ((destructor));
@@ -321,6 +401,10 @@ static void load_functions(void) {
/* There's some kind of weird incompatibility problem causing
* pthread_cond_timedwait() to freeze if we don't ask for this
* explicit version of these functions */
+ LOAD_FUNC_VERSIONED(pthread_cond_init, "GLIBC_2.3.2");
+ LOAD_FUNC_VERSIONED(pthread_cond_destroy, "GLIBC_2.3.2");
+ LOAD_FUNC_VERSIONED(pthread_cond_signal, "GLIBC_2.3.2");
+ LOAD_FUNC_VERSIONED(pthread_cond_broadcast, "GLIBC_2.3.2");
LOAD_FUNC_VERSIONED(pthread_cond_wait, "GLIBC_2.3.2");
LOAD_FUNC_VERSIONED(pthread_cond_timedwait, "GLIBC_2.3.2");
@@ -388,6 +472,12 @@ static void setup(void) {
else
frames_max = t;
+ t = show_n_wait_min;
+ if (parse_env("MUTRACE_WAIT_MIN", &t) < 0)
+ fprintf(stderr, "mutrace: WARNING: Failed to parse $MUTRACE_WAIT_MIN.\n");
+ else
+ show_n_wait_min = t;
+
t = show_n_locked_min;
if (parse_env("MUTRACE_LOCKED_MIN", &t) < 0)
fprintf(stderr, "mutrace: WARNING: Failed to parse $MUTRACE_LOCKED_MIN.\n");
@@ -424,13 +514,22 @@ static void setup(void) {
else
show_n_max = t;
- s = getenv("MUTRACE_SUMMARY_ORDER");
+ s = getenv("MUTRACE_SUMMARY_MUTEX_ORDER");
+ if (s != NULL) {
+ t = summary_mutex_order_from_command(s);
+ if (t == MUTEX_ORDER_INVALID)
+ fprintf(stderr, "mutrace: WARNING: Failed to parse $MUTRACE_SUMMARY_MUTEX_ORDER.\n");
+ else
+ summary_mutex_order = t;
+ }
+
+ s = getenv("MUTRACE_SUMMARY_COND_ORDER");
if (s != NULL) {
- t = summary_order_from_command(s);
- if (t == ORDER_INVALID)
- fprintf(stderr, "mutrace: WARNING: Failed to parse $MUTRACE_SUMMARY_ORDER.\n");
+ t = summary_cond_order_from_command(s);
+ if (t == COND_ORDER_INVALID)
+ fprintf(stderr, "mutrace: WARNING: Failed to parse $MUTRACE_SUMMARY_COND_ORDER.\n");
else
- summary_order = t;
+ summary_cond_order = t;
}
if (getenv("MUTRACE_TRAP"))
@@ -439,6 +538,7 @@ static void setup(void) {
if (getenv("MUTRACE_TRACK_RT"))
track_rt = true;
+ /* Set up the mutex hash table. */
alive_mutexes = calloc(hash_size, sizeof(struct mutex_info*));
assert(alive_mutexes);
@@ -454,6 +554,22 @@ static void setup(void) {
assert(r == 0);
}
+ /* Set up the cond hash table. */
+ alive_conds = calloc(hash_size, sizeof(struct cond_info*));
+ assert(alive_conds);
+
+ dead_conds = calloc(hash_size, sizeof(struct cond_info*));
+ assert(dead_conds);
+
+ conds_lock = malloc(hash_size * sizeof(pthread_mutex_t));
+ assert(conds_lock);
+
+ for (m = conds_lock, last = conds_lock+hash_size; m < last; m++) {
+ r = real_pthread_mutex_init(m, NULL);
+
+ assert(r == 0);
+ }
+
/* Listen for SIGUSR1 and print out a summary of what's happened so far
* when we receive it. */
sigusr_action.sa_handler = sigusr1_cb;
@@ -486,26 +602,58 @@ static unsigned long rwlock_hash(pthread_rwlock_t *rwlock) {
return u % hash_size;
}
-static void lock_hash_mutex(unsigned u) {
+static unsigned long cond_hash(pthread_cond_t *cond) {
+ unsigned long u;
+
+ u = (unsigned long) cond;
+ u /= sizeof(void*);
+
+ return u % hash_size;
+}
+
+static void lock_hash(pthread_mutex_t *lock_array, unsigned u) {
int r;
- r = real_pthread_mutex_trylock(mutexes_lock + u);
+ r = real_pthread_mutex_trylock(lock_array + u);
if (UNLIKELY(r == EBUSY)) {
__sync_fetch_and_add(&n_self_contended, 1);
- r = real_pthread_mutex_lock(mutexes_lock + u);
+ r = real_pthread_mutex_lock(lock_array + u);
}
assert(r == 0);
}
-static void unlock_hash_mutex(unsigned u) {
+static void unlock_hash(pthread_mutex_t *lock_array, unsigned u) {
int r;
- r = real_pthread_mutex_unlock(mutexes_lock + u);
+ r = real_pthread_mutex_unlock(lock_array + u);
assert(r == 0);
}
+#define lock_hash_mutex(u) lock_hash(mutexes_lock, u)
+#define unlock_hash_mutex(u) unlock_hash(mutexes_lock, u)
+
+#define lock_hash_cond(u) lock_hash(conds_lock, u)
+#define unlock_hash_cond(u) unlock_hash(conds_lock, u)
+
+#define _ORDER_CASE(TYPE, UCASE, lcase) \
+case TYPE##_ORDER_##UCASE: \
+ if (a->lcase != b->lcase) \
+ return a->lcase - b->lcase; \
+ break;
+#define _ORDER_CASE_AVG(TYPE, UCASE, lcase, divisor) \
+case TYPE##_ORDER_##UCASE: { \
+ double a_avg = a->lcase / a->divisor, \
+ b_avg = b->lcase / b->divisor; \
+ if (!doubles_equal(a_avg, b_avg)) \
+ return ((a_avg - b_avg) < 0.0) ? -1 : 1; \
+ break; \
+}
+#define STATIC_ORDER(lcase) \
+if (a->lcase != b->lcase) \
+ return a->lcase - b->lcase
+
static int mutex_info_compare(const void *_a, const void *_b) {
const struct mutex_info
*a = *(const struct mutex_info**) _a,
@@ -513,20 +661,9 @@ static int mutex_info_compare(const void *_a, const void *_b) {
/* Order by the user's chosen ordering first, then fall back to a static
* ordering. */
- switch (summary_order) {
- #define ORDER_CASE(UCASE, lcase) \
- case ORDER_##UCASE: \
- if (a->lcase != b->lcase) \
- return a->lcase - b->lcase; \
- break;
- #define ORDER_CASE_AVG(UCASE, lcase, divisor) \
- case ORDER_##UCASE: { \
- double a_avg = a->lcase / a->divisor, \
- b_avg = b->lcase / b->divisor; \
- if (!doubles_equal(a_avg, b_avg)) \
- return ((a_avg - b_avg) < 0.0) ? -1 : 1; \
- break; \
- }
+ switch (summary_mutex_order) {
+ #define ORDER_CASE(UCASE, lcase) _ORDER_CASE(MUTEX, UCASE, lcase)
+ #define ORDER_CASE_AVG(UCASE, lcase, divisor) _ORDER_CASE_AVG(MUTEX, UCASE, lcase, divisor)
ORDER_CASE(ID, id)
ORDER_CASE(N_LOCKED, n_locked[WRITE])
@@ -553,21 +690,60 @@ static int mutex_info_compare(const void *_a, const void *_b) {
}
/* Fall back to a static ordering. */
- #define STATIC_ORDER(lcase) \
- if (a->lcase != b->lcase) \
- return a->lcase - b->lcase
-
STATIC_ORDER(n_contended[WRITE]);
STATIC_ORDER(n_owner_changed);
STATIC_ORDER(n_locked[WRITE]);
STATIC_ORDER(nsec_locked_max[WRITE]);
- #undef STATIC_ORDER
+ /* Let's make the output deterministic */
+ return a - b;
+}
+
+static int cond_info_compare(const void *_a, const void *_b) {
+ const struct cond_info
+ *a = *(const struct cond_info**) _a,
+ *b = *(const struct cond_info**) _b;
+
+ /* Order by the user's chosen ordering first, then fall back to a static
+ * ordering. */
+ switch (summary_cond_order) {
+ #define ORDER_CASE(UCASE, lcase) _ORDER_CASE(COND, UCASE, lcase)
+ #define ORDER_CASE_AVG(UCASE, lcase, divisor) _ORDER_CASE_AVG(COND, UCASE, lcase, divisor)
+
+ ORDER_CASE(ID, id)
+ ORDER_CASE(N_WAIT, n_wait)
+ ORDER_CASE(N_SIGNAL, n_signal)
+ ORDER_CASE(N_BROADCAST, n_broadcast)
+ ORDER_CASE(N_WAIT_CONTENDED, n_wait_contended)
+ ORDER_CASE(N_SIGNAL_CONTENDED, n_signal_contended)
+ ORDER_CASE(NSEC_WAIT_TOTAL, nsec_wait_total)
+ ORDER_CASE(NSEC_WAIT_MAX, nsec_wait_max)
+ ORDER_CASE_AVG(NSEC_WAIT_AVG, nsec_wait_total, n_wait)
+ ORDER_CASE(NSEC_WAIT_CONTENDED_TOTAL, nsec_wait_contended_total)
+ ORDER_CASE(NSEC_WAIT_CONTENDED_MAX, nsec_wait_contended_max)
+ ORDER_CASE_AVG(NSEC_WAIT_CONTENDED_AVG, nsec_wait_contended_total, n_wait_contended)
+ default:
+ /* Should never be reached. */
+ assert(0);
+
+ #undef ORDER_CASE_AVG
+ #undef ORDER_CASE
+ }
+
+ /* Fall back to a static ordering. */
+ STATIC_ORDER(n_wait_contended);
+ STATIC_ORDER(n_wait);
+ STATIC_ORDER(nsec_wait_total);
+ STATIC_ORDER(n_signal);
/* Let's make the output deterministic */
return a - b;
}
+#undef STATIC_ORDER
+#undef ORDER_CASE_AVG
+#undef ORDER_CASE
+
static bool mutex_info_show(struct mutex_info *mi) {
/* Mutexes used by real-time code are always noteworthy */
@@ -592,6 +768,17 @@ static bool mutex_info_show(struct mutex_info *mi) {
return true;
}
+static bool cond_info_show(struct cond_info *ci) {
+ /* Condition variables used by real-time code are always noteworthy */
+ if (ci->realtime)
+ return true;
+
+ if (ci->n_wait < show_n_wait_min)
+ return false;
+
+ return true;
+}
+
static bool mutex_info_dump(struct mutex_info *mi) {
char *stacktrace_str;
@@ -609,6 +796,23 @@ static bool mutex_info_dump(struct mutex_info *mi) {
return true;
}
+static bool cond_info_dump(struct cond_info *ci) {
+ char *stacktrace_str;
+
+ if (!cond_info_show(ci))
+ return false;
+
+ stacktrace_str = stacktrace_to_string(ci->stacktrace);
+
+ fprintf(stderr,
+ "\nCondvar #%u (0x%p) first referenced by:\n"
+ "%s", ci->id, ci->cond, stacktrace_str);
+
+ free(stacktrace_str);
+
+ return true;
+}
+
static char mutex_type_name(int type) {
switch (type) {
@@ -699,20 +903,52 @@ static bool mutex_info_stat(struct mutex_info *mi) {
return true;
}
-static SummaryOrder summary_order_from_command(const char *command) {
+static bool cond_info_stat(struct cond_info *ci) {
+ if (!cond_info_show(ci))
+ return false;
+
+ fprintf(stderr,
+ "%8u %8u %8u %8u %12.3f %13.3f %12.3f %c%c\n",
+ ci->id,
+ ci->n_wait,
+ ci->n_signal + ci->n_broadcast,
+ ci->n_wait_contended,
+ (double) ci->nsec_wait_total / 1000000.0,
+ (double) ci->nsec_wait_contended_total / 1000000.0,
+ (double) ci->nsec_wait_contended_total / ci->n_wait / 1000000.0,
+ ci->broken ? '!' : (ci->dead ? 'x' : '-'),
+ track_rt ? (ci->realtime ? 'R' : '-') : '.');
+
+ return true;
+}
+
+static SummaryMutexOrder summary_mutex_order_from_command(const char *command) {
+ unsigned int i;
+
+ for (i = 0; i < MUTEX_ORDER_INVALID; i++) {
+ if (strcmp(command, summary_mutex_order_details[i].command) == 0) {
+ return i;
+ }
+ }
+
+ return MUTEX_ORDER_INVALID;
+}
+
+static SummaryCondOrder summary_cond_order_from_command(const char *command) {
unsigned int i;
- for (i = 0; i < ORDER_INVALID; i++) {
- if (strcmp(command, summary_order_details[i].command) == 0) {
- return ORDER_ID;
+ for (i = 0; i < COND_ORDER_INVALID; i++) {
+ if (strcmp(command, summary_cond_order_details[i].command) == 0) {
+ return i;
}
}
- return ORDER_INVALID;
+ return COND_ORDER_INVALID;
}
static void show_summary_internal(void) {
- struct mutex_info *mi, **table;
+ struct mutex_info *mi, **mutex_table;
+ struct cond_info *ci, **cond_table;
unsigned n, u, i, m;
uint64_t t;
long n_cpus;
@@ -723,6 +959,7 @@ static void show_summary_internal(void) {
"\n"
"mutrace: Showing statistics for process %s (PID: %lu).\n", get_prname(), (unsigned long) getpid());
+ /* Mutexes. */
n = 0;
for (u = 0; u < hash_size; u++) {
lock_hash_mutex(u);
@@ -743,26 +980,26 @@ static void show_summary_internal(void) {
fprintf(stderr,
"mutrace: %u mutexes used.\n", n);
- table = malloc(sizeof(struct mutex_info*) * n);
+ mutex_table = malloc(sizeof(struct mutex_info*) * n);
i = 0;
for (u = 0; u < hash_size; u++) {
for (mi = alive_mutexes[u]; mi; mi = mi->next) {
mi->id = i;
- table[i++] = mi;
+ mutex_table[i++] = mi;
}
for (mi = dead_mutexes[u]; mi; mi = mi->next) {
mi->id = i;
- table[i++] = mi;
+ mutex_table[i++] = mi;
}
}
assert(i == n);
- qsort(table, n, sizeof(table[0]), mutex_info_compare);
+ qsort(mutex_table, n, sizeof(mutex_table[0]), mutex_info_compare);
for (i = n, m = 0; i > 0 && (show_n_max <= 0 || m < show_n_max); i--)
- m += mutex_info_dump(table[i - 1]) ? 1 : 0;
+ m += mutex_info_dump(mutex_table[i - 1]) ? 1 : 0;
if (m > 0) {
fprintf(stderr,
@@ -770,10 +1007,10 @@ static void show_summary_internal(void) {
"mutrace: Showing %u mutexes in order of %s:\n"
"\n"
" Mutex # Locked Changed Cont. cont.Time[ms] tot.Time[ms] avg.Time[ms] Flags\n",
- m, summary_order_details[summary_order].ui_string);
+ m, summary_mutex_order_details[summary_mutex_order].ui_string);
for (i = n, m = 0; i > 0 && (show_n_max <= 0 || m < show_n_max); i--)
- m += mutex_info_stat(table[i - 1]) ? 1 : 0;
+ m += mutex_info_stat(mutex_table[i - 1]) ? 1 : 0;
if (i < n)
@@ -797,18 +1034,100 @@ static void show_summary_internal(void) {
if (!track_rt)
fprintf(stderr,
"\n"
- "mutrace: Note that the flags column R is only valid in --track-rt mode!\n");
+ "mutrace: Note that the flags column R is only valid in --track-rt mode!\n\n");
} else
fprintf(stderr,
"\n"
- "mutrace: No mutex contended according to filtering parameters.\n");
+ "mutrace: No mutex contended according to filtering parameters.\n\n");
- free(table);
+ free(mutex_table);
for (u = 0; u < hash_size; u++)
unlock_hash_mutex(u);
+ /* Condition variables. */
+ n = 0;
+ for (u = 0; u < hash_size; u++) {
+ lock_hash_cond(u);
+
+ for (ci = alive_conds[u]; ci; ci = ci->next)
+ n++;
+
+ for (ci = dead_conds[u]; ci; ci = ci->next)
+ n++;
+ }
+
+ if (n <= 0) {
+ fprintf(stderr,
+ "mutrace: No condition variables used.\n");
+ return;
+ }
+
+ fprintf(stderr,
+ "mutrace: %u condition variables used.\n", n);
+
+ cond_table = malloc(sizeof(struct cond_info*) * n);
+
+ i = 0;
+ for (u = 0; u < hash_size; u++) {
+ for (ci = alive_conds[u]; ci; ci = ci->next) {
+ ci->id = i;
+ cond_table[i++] = ci;
+ }
+
+ for (ci = dead_conds[u]; ci; ci = ci->next) {
+ ci->id = i;
+ cond_table[i++] = ci;
+ }
+ }
+ assert(i == n);
+
+ qsort(cond_table, n, sizeof(cond_table[0]), cond_info_compare);
+
+ for (i = n, m = 0; i > 0 && (show_n_max <= 0 || m < show_n_max); i--)
+ m += cond_info_dump(cond_table[i - 1]) ? 1 : 0;
+
+ if (m > 0) {
+ fprintf(stderr,
+ "\n"
+ "mutrace: Showing %u condition variables in order of %s:\n"
+ "\n"
+ " Cond # Waits Signals Cont. tot.Time[ms] cont.Time[ms] avg.Time[ms] Flags\n",
+ m, summary_cond_order_details[summary_cond_order].ui_string);
+
+ for (i = n, m = 0; i > 0 && (show_n_max <= 0 || m < show_n_max); i--)
+ m += cond_info_stat(cond_table[i - 1]) ? 1 : 0;
+
+
+ if (i < n)
+ fprintf(stderr,
+ " ... ... ... ... ... ... ... ||\n");
+ else
+ fprintf(stderr,
+ " ||\n");
+
+ fprintf(stderr,
+ " /|\n"
+ " State: x = dead, ! = inconsistent /\n"
+ " Use: R = used in realtime thread \n");
+
+ if (!track_rt)
+ fprintf(stderr,
+ "\n"
+ "mutrace: Note that the flags column R is only valid in --track-rt mode!\n");
+
+ } else
+ fprintf(stderr,
+ "\n"
+ "mutrace: No condition variable contended according to filtering parameters.\n");
+
+ free(cond_table);
+
+ for (u = 0; u < hash_size; u++)
+ unlock_hash_cond(u);
+
+ /* Footer. */
fprintf(stderr,
"\n"
"mutrace: Total runtime is %0.3f ms.\n", (double) t / 1000000.0);
@@ -826,11 +1145,17 @@ static void show_summary_internal(void) {
"\n"
"mutrace: Results for SMP with %li processors.\n", n_cpus);
- if (n_broken > 0)
+ if (n_broken_mutexes > 0)
fprintf(stderr,
"\n"
"mutrace: WARNING: %u inconsistent mutex uses detected. Results might not be reliable.\n"
- "mutrace: Fix your program first!\n", n_broken);
+ "mutrace: Fix your program first!\n", n_broken_mutexes);
+
+ if (n_broken_conds > 0)
+ fprintf(stderr,
+ "\n"
+ "mutrace: WARNING: %u inconsistent condition variable uses detected. Results might not be reliable.\n"
+ "mutrace: Fix your program first!\n", n_broken_conds);
if (n_collisions > 0)
fprintf(stderr,
@@ -1161,7 +1486,7 @@ static void mutex_lock(pthread_mutex_t *mutex, bool busy, uint64_t nsec_contende
mi = mutex_info_acquire(mutex);
if (mi->n_lock_level > 0 && mi->type != PTHREAD_MUTEX_RECURSIVE) {
- __sync_fetch_and_add(&n_broken, 1);
+ __sync_fetch_and_add(&n_broken_mutexes, 1);
mi->broken = true;
if (raise_trap)
@@ -1293,7 +1618,7 @@ static void mutex_unlock(pthread_mutex_t *mutex) {
mi = mutex_info_acquire(mutex);
if (mi->n_lock_level <= 0) {
- __sync_fetch_and_add(&n_broken, 1);
+ __sync_fetch_and_add(&n_broken_mutexes, 1);
mi->broken = true;
if (raise_trap)
@@ -1326,33 +1651,306 @@ int pthread_mutex_unlock(pthread_mutex_t *mutex) {
return real_pthread_mutex_unlock(mutex);
}
+static struct cond_info *cond_info_add(unsigned long u, pthread_cond_t *cond) {
+ struct cond_info *ci;
+
+ /* Needs external locking */
+
+ if (alive_conds[u])
+ __sync_fetch_and_add(&n_collisions, 1);
+
+ ci = calloc(1, sizeof(struct cond_info));
+ assert(ci);
+
+ ci->cond = cond;
+ ci->stacktrace = generate_stacktrace();
+
+ ci->next = alive_conds[u];
+ alive_conds[u] = ci;
+
+ return ci;
+}
+
+static void cond_info_remove(unsigned u, pthread_cond_t *cond) {
+ struct cond_info *ci, *p;
+
+ /* Needs external locking */
+
+ for (ci = alive_conds[u], p = NULL; ci; p = ci, ci = ci->next)
+ if (ci->cond == cond)
+ break;
+
+ if (!ci)
+ return;
+
+ if (p)
+ p->next = ci->next;
+ else
+ alive_conds[u] = ci->next;
+
+ ci->dead = true;
+ ci->next = dead_conds[u];
+ dead_conds[u] = ci;
+}
+
+static struct cond_info *cond_info_acquire(pthread_cond_t *cond) {
+ unsigned long u;
+ struct cond_info *ci;
+
+ u = cond_hash(cond);
+ lock_hash_cond(u);
+
+ for (ci = alive_conds[u]; ci; ci = ci->next)
+ if (ci->cond == cond)
+ return ci;
+
+ return cond_info_add(u, cond);
+}
+
+static void cond_info_release(pthread_cond_t *cond) {
+ unsigned long u;
+
+ u = cond_hash(cond);
+ unlock_hash_cond(u);
+}
+
+int pthread_cond_init(pthread_cond_t *cond, const pthread_condattr_t *attr) {
+ int r;
+
+ if (UNLIKELY(!initialized && recursive)) {
+ static const pthread_cond_t template = PTHREAD_COND_INITIALIZER;
+ /* Now this is incredibly ugly. */
+
+ memcpy(cond, &template, sizeof(pthread_cond_t));
+ return 0;
+ }
+
+ load_functions();
+
+ r = real_pthread_cond_init(cond, attr);
+ if (r != 0)
+ return r;
+
+ if (LIKELY(initialized && !recursive)) {
+ unsigned long u;
+
+ recursive = true;
+ u = cond_hash(cond);
+ lock_hash_cond(u);
+
+ cond_info_remove(u, cond);
+ cond_info_add(u, cond);
+
+ unlock_hash_cond(u);
+ recursive = false;
+ }
+
+ return r;
+}
+
+int pthread_cond_destroy(pthread_cond_t *cond) {
+ assert(initialized || !recursive);
+
+ load_functions();
+
+ if (LIKELY(initialized && !recursive)) {
+ unsigned long u;
+
+ recursive = true;
+ u = cond_hash(cond);
+ lock_hash_cond(u);
+
+ cond_info_remove(u, cond);
+
+ unlock_hash_cond(u);
+ recursive = false;
+ }
+
+ return real_pthread_cond_destroy(cond);
+}
+
+static void cond_signal(pthread_cond_t *cond, bool is_broadcast) {
+ struct cond_info *ci;
+
+ if (UNLIKELY(!initialized || recursive))
+ return;
+
+ recursive = true;
+ ci = cond_info_acquire(cond);
+
+ if (ci->n_wait_level == 0) {
+ ci->n_signal_contended++;
+ } else {
+ /* If we're signalling the second-last thread which is waiting
+ * on the cond, calculate the total contention time (from the
+ * time the second thread first started waiting on the cond) and
+ * add it to the total.
+ *
+ * However, if we're broadcasting, don't sum up the contention
+ * time, since we assume that the threads will all now have
+ * useful work to do. */
+ if (ci->n_wait_level == 2 && !is_broadcast) {
+ uint64_t contention_time = nsec_now() - ci->nsec_timestamp;
+ ci->nsec_wait_contended_total += contention_time;
+
+ if (contention_time > ci->nsec_wait_contended_max)
+ ci->nsec_wait_contended_max = contention_time;
+ }
+ }
+
+ if (is_broadcast)
+ ci->n_broadcast++;
+ else
+ ci->n_signal++;
+
+ if (track_rt && !ci->realtime && is_realtime())
+ ci->realtime = true;
+
+ cond_info_release(cond);
+ recursive = false;
+}
+
+int pthread_cond_signal(pthread_cond_t *cond) {
+ int r;
+
+ if (UNLIKELY(!initialized && recursive)) {
+ assert(!threads_existing);
+ return 0;
+ }
+
+ load_functions();
+
+ r = real_pthread_cond_signal(cond);
+ if (UNLIKELY(r != 0))
+ return r;
+
+ cond_signal(cond, false);
+
+ return r;
+}
+
+int pthread_cond_broadcast(pthread_cond_t *cond) {
+ int r;
+
+ if (UNLIKELY(!initialized && recursive)) {
+ assert(!threads_existing);
+ return 0;
+ }
+
+ load_functions();
+
+ r = real_pthread_cond_broadcast(cond);
+ if (UNLIKELY(r != 0))
+ return r;
+
+ cond_signal(cond, true);
+
+ return r;
+}
+
+static void cond_wait_start(pthread_cond_t *cond, pthread_mutex_t *mutex) {
+ struct cond_info *ci;
+
+ if (UNLIKELY(!initialized || recursive))
+ return;
+
+ recursive = true;
+ ci = cond_info_acquire(cond);
+
+ /* Check the cond is always used with the same mutex. pthreads
+ * technically allows for different mutexes to be used sequentially
+ * with a given cond, but this seems error prone and probably always
+ * A Bad Idea. */
+ if (ci->mutex == NULL) {
+ ci->mutex = mutex;
+ } else if (ci->mutex != mutex) {
+ __sync_fetch_and_add(&n_broken_conds, 1);
+ ci->broken = true;
+
+ if (raise_trap)
+ DEBUG_TRAP;
+ }
+
+ if (ci->n_wait_level > 0)
+ ci->n_wait_contended++;
+
+ /* Iff we're the second thread to concurrently wait on this cond, start
+ * the contention timer. This timer will continue running until the
+ * second-last thread to be waiting on the cond is signalled. */
+ if (ci->n_wait_level == 1)
+ ci->nsec_timestamp = nsec_now();
+
+ ci->n_wait_level++;
+ ci->n_wait++;
+
+ if (track_rt && !ci->realtime && is_realtime())
+ ci->realtime = true;
+
+ cond_info_release(cond);
+ recursive = false;
+}
+
+static void cond_wait_finish(pthread_cond_t *cond, pthread_mutex_t *mutex, uint64_t wait_time) {
+ struct cond_info *ci;
+
+ if (UNLIKELY(!initialized || recursive))
+ return;
+
+ recursive = true;
+ ci = cond_info_acquire(cond);
+
+ ci->nsec_wait_total += wait_time;
+ if (wait_time > ci->nsec_wait_max)
+ ci->nsec_wait_max = wait_time;
+
+ ci->n_wait_level--;
+
+ cond_info_release(cond);
+ recursive = false;
+}
+
int pthread_cond_wait(pthread_cond_t *cond, pthread_mutex_t *mutex) {
int r;
+ uint64_t start_time, wait_time = 0;
assert(initialized || !recursive);
load_functions();
+ cond_wait_start(cond, mutex);
mutex_unlock(mutex);
+
+ start_time = nsec_now();
r = real_pthread_cond_wait(cond, mutex);
+ wait_time = nsec_now() - start_time;
/* Unfortunately we cannot distuingish mutex contention and
* the condition not being signalled here. */
mutex_lock(mutex, false, 0);
+ cond_wait_finish(cond, mutex, wait_time);
return r;
}
int pthread_cond_timedwait(pthread_cond_t *cond, pthread_mutex_t *mutex, const struct timespec *abstime) {
int r;
+ uint64_t start_time, wait_time = 0;
assert(initialized || !recursive);
load_functions();
+ cond_wait_start(cond, mutex);
mutex_unlock(mutex);
+
+ start_time = nsec_now();
r = real_pthread_cond_timedwait(cond, mutex, abstime);
+ wait_time = nsec_now() - start_time;
+
+ /* Unfortunately we cannot distuingish mutex contention and
+ * the condition not being signalled here. */
mutex_lock(mutex, false, 0);
+ cond_wait_finish(cond, mutex, wait_time);
return r;
}
@@ -1551,7 +2149,7 @@ static void rwlock_lock(pthread_rwlock_t *rwlock, LockType lock_type, bool busy,
mi = rwlock_info_acquire(rwlock);
if (mi->n_lock_level > 0 && lock_type == WRITE) {
- __sync_fetch_and_add(&n_broken, 1);
+ __sync_fetch_and_add(&n_broken_mutexes, 1);
mi->broken = true;
if (raise_trap)
@@ -1770,7 +2368,7 @@ static void rwlock_unlock(pthread_rwlock_t *rwlock) {
mi = rwlock_info_acquire(rwlock);
if (mi->n_lock_level <= 0) {
- __sync_fetch_and_add(&n_broken, 1);
+ __sync_fetch_and_add(&n_broken_mutexes, 1);
mi->broken = true;
if (raise_trap)
diff --git a/mutrace.in b/mutrace.in
index 9bfabe1..e88f07d 100755
--- a/mutrace.in
+++ b/mutrace.in
@@ -17,7 +17,7 @@
# You should have received a copy of the GNU Lesser General Public
# License along with mutrace. If not, see <http://www.gnu.org/licenses/>.
-if ! TEMP=`getopt -o +ardh --long hash-size:,frames:,locked-min:,owner-changed-min:,contended-min:,max:,order:,trap,help,all,debug-info -n mutrace -- "$@"` ; then
+if ! TEMP=`getopt -o +ardh --long hash-size:,frames:,locked-min:,owner-changed-min:,contended-min:,max:,mutex-order:,cond-order:,trap,help,all,debug-info -n mutrace -- "$@"` ; then
exit 1
fi
@@ -57,8 +57,13 @@ while : ; do
shift 2
;;
- --order)
- export MUTRACE_SUMMARY_ORDER="$2"
+ --mutex-order)
+ export MUTRACE_SUMMARY_MUTEX_ORDER="$2"
+ shift 2
+ ;;
+
+ --cond-order)
+ export MUTRACE_SUMMARY_COND_ORDER="$2"
shift 2
;;
@@ -99,9 +104,14 @@ OPTIONS:
--frames=INTEGER Set number of frames to show in stack traces
-d, --debug-info Make use of debug information in stack traces
--max=INTEGER Show this many mutexes at maximum
- --order=STRING Order the summary table by this column (see
- below for valid column names)
-
+ --mutex-order=STRING Order the summary table of mutexes by this
+ column (see below for valid column names)
+ --cond-order=STRING Order the summary table of condition variables
+ by this column (see below for valid column
+ names)
+
+ --wait-min=INTEGER Only show condition variables that have been
+ waited on at least this often
--locked-min=INTEGER Only show mutexes that have been locked at
least this often
--owner-changed-min=INTEGER Only show mutexes whose owning thread changed
@@ -117,7 +127,7 @@ OPTIONS:
inconsistency is detected (for use in
conjunction with gdb)
-ORDER COLUMN NAMES:
+MUTEX ORDER COLUMN NAMES:
id Mutex number
n-locked Total number of times mutex was locked for
writing
@@ -144,6 +154,30 @@ ORDER COLUMN NAMES:
nsec-read-contended-total Total time mutex was contended for reading
nsec-read-contended-avg Average time mutex was continuously contended
for reading
+
+CONDITION VARIABLE ORDER COLUMN NAMES:
+ id Condition variable number
+ n-wait Total number of times condition variable was
+ waited on (inc. timed waits)
+ n-signal Total number of times condition variable was
+ signalled
+ n-broadcast Total number of times condition variable was
+ broadcasted
+ n-wait-contended Total number of times condition variable was
+ concurrently waited on by multiple threads
+ n-signal-contended Total number of times condition variable was
+ signalled with no threads waiting
+ nsec-wait-total Total time condition variable was waited on
+ nsec-wait-max Maximum time condition variable was
+ continuously waited on
+ nsec-wait-avg Average time condition variable was
+ continuously waited on
+ nsec-wait-contended-total Total time condition variable was waited on
+ by multiple threads before being signalled
+ nsec-wait-contended-max Maximum time condition variable was waited on
+ by multiple threads
+ nsec-wait-contended-avg Average time condition variable was waited on
+ by multiple threads
EOF
exit 0
;;