I generated the output below by running firefox on my x220 with a
patched librthread. The diff I used is attached and uses some builtins
to see which _spinlock() calls are *really* contended.
The result is interesting.
<_rthread_mutex_lock+0x58> correspond to the line 108 of rthread_sync.c:
...
_rthread_debug(5, "%p: mutex_lock %p\n", (void *)self, (void *)mutex);
_spinlock(&mutex->lock);
if (mutex->owner == NULL && TAILQ_EMPTY(&mutex->lockers)) {
...
<pthread_cond_timedwait+0x363> correspond to the line 395 of the same file:
...
if (self->blocking_cond == NULL) {
_spinunlock(&cond->lock);
_spinlock(&mutex->lock);
continue;
}
...
<pthread_cond_wait+0x202> corresponds to the line 527:
...
_spinlock(&cond->lock);
if (self->blocking_cond == NULL) {
_spinunlock(&cond->lock);
...
0x13da768ac960 called yield() 100 times from <pthread_mutex_unlock+0x85>
0x13d9d855b900 called yield() 100 times from <pthread_mutex_unlock+0x85>
0x13da41b80900 called yield() 100 times from <_rthread_mutex_lock+0x1c6>
0x13d9f5cebb00 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da768ac960 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da8a19d900 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da8a19de00 called yield() 100 times from <pthread_cond_timedwait+0x363>
0x13da04988d00 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da8a19d900 called yield() 200 times from <_rthread_mutex_lock+0x58>
0x13da8a19d900 called yield() 300 times from <_rthread_mutex_lock+0x58>
0x13da8a19de00 called yield() 200 times from <pthread_cond_timedwait+0x363>
0x13da04988d00 called yield() 200 times from <_rthread_mutex_lock+0x58>
0x13da8a19d900 called yield() 400 times from <_rthread_mutex_lock+0x58>
0x13da8a19d900 called yield() 500 times from <_rthread_mutex_lock+0x58>
0x13da8a19de00 called yield() 300 times from <pthread_cond_timedwait+0x363>
0x13da04988d00 called yield() 300 times from <_rthread_mutex_lock+0x58>
0x13da8a19de00 called yield() 400 times from <pthread_cond_timedwait+0x363>
0x13da04988d00 called yield() 400 times from <_rthread_mutex_lock+0x58>
0x13da8a19de00 called yield() 500 times from <pthread_cond_timedwait+0x363>
0x13da04988d00 called yield() 500 times from <_rthread_mutex_lock+0x58>
0x13da8a19de00 called yield() 600 times from <pthread_cond_timedwait+0x363>
0x13da04988d00 called yield() 600 times from <_rthread_mutex_lock+0x58>
0x13da8a19de00 called yield() 700 times from <pthread_cond_timedwait+0x363>
0x13da04988d00 called yield() 700 times from <_rthread_mutex_lock+0x58>
0x13da8a19de00 called yield() 800 times from <pthread_cond_timedwait+0x363>
0x13da04988d00 called yield() 800 times from <_rthread_mutex_lock+0x58>
0x13da8a19de00 called yield() 900 times from <pthread_cond_timedwait+0x363>
0x13da04988d00 called yield() 900 times from <_rthread_mutex_lock+0x58>
0x13da8a19de00 called yield() 1000 times from <pthread_cond_timedwait+0x363>
0x13da04988d00 called yield() 1000 times from <_rthread_mutex_lock+0x58>
0x13da8a19de00 called yield() 1100 times from <pthread_cond_timedwait+0x363>
0x13da04988d00 called yield() 1100 times from <_rthread_mutex_lock+0x58>
0x13da8a19de00 called yield() 1200 times from <pthread_cond_timedwait+0x363>
0x13da04988d00 called yield() 1200 times from <_rthread_mutex_lock+0x58>
0x13d9d855b900 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13d9d855b900 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da9f5a3400 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13d9d855b900 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13d9d855b900 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da9f5a3400 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13dab6e24400 called yield() 100 times from <pthread_cond_wait+0x202>
0x13dab6e24400 called yield() 200 times from <pthread_cond_wait+0x202>
0x13dab6e24400 called yield() 300 times from <pthread_cond_wait+0x202>
0x13d9d855b900 called yield() 100 times from <pthread_mutex_unlock+0x85>
0x13d9d855b900 called yield() 100 times from <pthread_mutex_unlock+0x85>
0x13d9d855b900 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13d9d855b900 called yield() 100 times from <pthread_mutex_unlock+0x85>
0x13d9c6e7b800 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da768ac960 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13d9f5456900 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da768ac960 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da41b7f100 called yield() 100 times from <_rthread_mutex_lock+0x1c6>
0x13d9d855b900 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13d9f5cebb00 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da768ac960 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13daab203400 called yield() 100 times from <pthread_mutex_unlock+0x85>
0x13da768ac960 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da768ac960 called yield() 200 times from <_rthread_mutex_lock+0x58>
0x13da768ac960 called yield() 300 times from <_rthread_mutex_lock+0x58>
0x13d9d855b900 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da8a19d900 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da8a19d900 called yield() 200 times from <_rthread_mutex_lock+0x58>
0x13da768ac960 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da8a19de00 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da8a19d900 called yield() 100 times from <_rthread_mutex_lock+0x1c6>
0x13da8a19de00 called yield() 200 times from <_rthread_mutex_lock+0x58>
0x13da8a19de00 called yield() 300 times from <_rthread_mutex_lock+0x58>
0x13da8a19de00 called yield() 400 times from <_rthread_mutex_lock+0x58>
0x13da8a19d900 called yield() 200 times from <_rthread_mutex_lock+0x1c6>
0x13dab6e24400 called yield() 100 times from <pthread_cond_wait+0x202>
0x13dab6e24400 called yield() 200 times from <pthread_cond_wait+0x202>
0x13dab6e24400 called yield() 300 times from <pthread_cond_wait+0x202>
0x13dab6e24400 called yield() 400 times from <pthread_cond_wait+0x202>
0x13dab6e24400 called yield() 500 times from <pthread_cond_wait+0x202>
0x13dab6e24400 called yield() 600 times from <pthread_cond_wait+0x202>
0x13dab6e24400 called yield() 700 times from <pthread_cond_wait+0x202>
0x13da768ac960 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da04988d00 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da768ac960 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da04988d00 called yield() 100 times from <pthread_mutex_unlock+0x85>
0x13da18d77d00 called yield() 100 times from <pthread_mutex_unlock+0x85>
0x13d9e7359200 called yield() 100 times from <pthread_cond_wait+0x202>
0x13d9e7359200 called yield() 200 times from <pthread_cond_wait+0x202>
0x13d9e7359200 called yield() 300 times from <pthread_cond_wait+0x202>
0x13d9f5cebb00 called yield() 100 times from <_rthread_mutex_lock+0x1c6>
0x13da8a19de00 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da8a19de00 called yield() 200 times from <_rthread_mutex_lock+0x58>
0x13da8a19de00 called yield() 300 times from <_rthread_mutex_lock+0x58>
0x13da8a19de00 called yield() 400 times from <_rthread_mutex_lock+0x58>
0x13da8a19de00 called yield() 500 times from <_rthread_mutex_lock+0x58>
0x13da8a19de00 called yield() 600 times from <_rthread_mutex_lock+0x58>
0x13da8a19de00 called yield() 700 times from <_rthread_mutex_lock+0x58>
0x13da8a19de00 called yield() 800 times from <_rthread_mutex_lock+0x58>
0x13da8a19de00 called yield() 900 times from <_rthread_mutex_lock+0x58>
0x13da8a19de00 called yield() 1000 times from <_rthread_mutex_lock+0x58>
0x13d9e7359200 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13d9d855b900 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da768ac960 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da260fba00 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13d9d855b900 called yield() 100 times from <pthread_mutex_unlock+0x85>
0x13dab6e24400 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13d9d855b900 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13d9d855b900 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13d9d855b900 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13d9f5456900 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13d9f5cebb00 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da768ac960 called yield() 100 times from <pthread_mutex_unlock+0x85>
0x13da768ac960 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da04988d00 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da41b7f100 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da8a19de00 called yield() 100 times from <_rthread_mutex_lock+0x1c6>
0x13da8a19de00 called yield() 200 times from <_rthread_mutex_lock+0x1c6>
0x13da8a19de00 called yield() 300 times from <_rthread_mutex_lock+0x58>
0x13da41b7f100 called yield() 200 times from <_rthread_mutex_lock+0x1c6>
0x13da41b80900 called yield() 100 times from <pthread_mutex_unlock+0x85>
0x13da768ac960 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da04988d00 called yield() 100 times from <_rthread_mutex_lock+0x1c6>
0x13d9d855b900 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13d9d855b900 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13dab6e24400 called yield() 100 times from <pthread_cond_wait+0x202>
0x13dab6e24400 called yield() 100 times from <pthread_cond_wait+0x202>
0x13da16183500 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da04988d00 called yield() 100 times from <_rthread_mutex_lock+0x1c6>
0x13da41b80900 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13d9d855b900 called yield() 100 times from <pthread_mutex_unlock+0x85>
0x13daab203400 called yield() 100 times from <pthread_mutex_unlock+0x85>
0x13da768ac960 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da41b80900 called yield() 100 times from <_rthread_mutex_lock+0x1c6>
0x13dab6e24400 called yield() 100 times from <_rthread_mutex_lock+0x1c6>
0x13d9d855b900 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da260fbf00 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13daab203400 called yield() 100 times from <pthread_mutex_unlock+0x85>
0x13da41b80900 called yield() 100 times from <_rthread_mutex_lock+0x1c6>
0x13da3c083500 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da04988d00 called yield() 100 times from <pthread_mutex_unlock+0x85>
0x13da260fbf00 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da41b80900 called yield() 100 times from <pthread_mutex_unlock+0x85>
0x13dab6e24400 called yield() 100 times from <pthread_mutex_unlock+0x85>
0x13da768ac960 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13d9f8c49800 called yield() 100 times from <pthread_mutex_unlock+0x85>
0x13da768ac960 called yield() 100 times from <_rthread_mutex_lock+0x58>
0x13da768ac960 called yield() 100 times from <pthread_mutex_unlock+0x85>
0x13da8a19de00 called yield() 100 times from <pthread_mutex_unlock+0x85>
Index: rthread.c
===================================================================
RCS file: /cvs/src/lib/librthread/rthread.c,v
retrieving revision 1.88
diff -u -p -r1.88 rthread.c
--- rthread.c 20 Mar 2016 02:30:28 -0000 1.88
+++ rthread.c 22 Mar 2016 17:30:03 -0000
@@ -72,14 +72,41 @@ struct pthread_attr _rthread_attr_defaul
.sched_inherit = PTHREAD_INHERIT_SCHED,
};
+void print_frame(void *);
+
+void
+print_frame(void *addr)
+{
+ Dl_info dlinfo;
+ char *sym;
+
+ if (addr == NULL || dladdr(addr, &dlinfo) == 0)
+ return;
+
+ sym = (char *)dlinfo.dli_sname;
+ if (sym == NULL)
+ sym = "???";
+ fprintf(stderr, " <%s+0x%lx>\n", sym, addr - dlinfo.dli_saddr);
+}
+
/*
* internal support functions
*/
void
_spinlock(volatile struct _spinlock *lock)
{
- while (_atomic_lock(&lock->ticket))
+ pthread_t self = pthread_self();
+ int i = 0;
+
+ while (_atomic_lock(&lock->ticket)) {
+ if ((++i % 100) == 0) {
+ fprintf(stderr, "%p called yield() %d times from",
+ self, i);
+ print_frame(__builtin_return_address(0));
+ }
+
sched_yield();
+ }
}
int
Index: rthread_sync.c
===================================================================
RCS file: /cvs/src/lib/librthread/rthread_sync.c,v
retrieving revision 1.39
diff -u -p -r1.39 rthread_sync.c
--- rthread_sync.c 1 Jun 2013 23:06:26 -0000 1.39
+++ rthread_sync.c 22 Mar 2016 17:15:45 -0000
@@ -33,6 +33,9 @@
static struct _spinlock static_init_lock = _SPINLOCK_UNLOCKED;
+int
+_rthread_mutex_lock(pthread_mutex_t *, int, const struct timespec *);
+
/*
* mutexen
*/
@@ -80,7 +83,7 @@ pthread_mutex_destroy(pthread_mutex_t *m
return (0);
}
-static int
+int
_rthread_mutex_lock(pthread_mutex_t *mutexp, int trywait,
const struct timespec *abstime)
{
