summaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
-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
;;