2 Palacios lock-checking framework
6 #include <linux/kernel.h>
7 #include <linux/kthread.h>
8 #include <linux/spinlock.h>
9 #include <linux/sort.h>
10 #include <linux/timer.h>
11 #include <linux/time.h>
15 #include "lockcheck.h"
18 // Number of outputs possible before output stops
19 // set to zero to remove the limit
20 #define OUTPUT_LIMIT 0
22 // Number of outputs to skip before
23 // printing and counting
27 // Whether or not to print these events
29 #define PRINT_LOCK_ALLOC 0
30 #define PRINT_LOCK_FREE 0
31 #define PRINT_LOCK_LOCK 0
32 #define PRINT_LOCK_UNLOCK 0
34 // How far up the stack to track the caller
37 // 2 => caller of v3_lock..
39 #define STEP_BACK_DEPTH_FIRST 1
40 #define STEP_BACK_DEPTH_LAST 4
41 #define STEP_BACK_DEPTH (STEP_BACK_DEPTH_LAST-STEP_BACK_DEPTH_FIRST+1)
43 // show when multiple locks are held simultaneously
44 // This is the minimum number
45 #define WARN_MULTIPLE_THRESHOLD 3
47 // Detect when last lock a processor holds is released
48 // but interrupts remain off, similarly for first acquire
49 #define CHECK_IRQ_LAST_RELEASE 0
50 #define CHECK_IRQ_FIRST_ACQUIRE 1
52 // Show hottest locks every this many locks or lock_irqsaves
53 // 0 indicates this should not be shown
54 #define HOT_LOCK_INTERVAL 100000
56 // How often the long lock timer checker should run
57 // And how long a lock needs to be held before it complains
58 // set to zero to deactivate
59 #define LONG_LOCK_INTERVAL_MS 10
60 #define LONG_LOCK_HELD_MS 20
63 // Whether lockcheck should lock its own data structures during an
64 // event (alloc, dealloc, lock, unlock, etc) and the subsequent
65 // checking. If this is off, it will only lock on a lock allocation,
66 // in order to assure each lock has a distinct slot. If this is off,
67 // lockcheck may miss problems (or see additional problems) due to
68 // internal race conditions. However, if it is on, lockcheck is
69 // essentially adding a global lock acuire to each lock operation in
70 // palacios, which will perturb palacios.
76 int inuse; // nonzero if this is in use
77 void *lock; // the lock
78 void *holder; // current thread holding it
79 u32 holdingcpu; // on which cpu it acquired it
80 void *allocator[STEP_BACK_DEPTH];
82 int lockcount; // how many times it's been locked/unlocked (lock=+1, unlock=-1)
83 int irqcount; // how many times interrupts have been turned off (+1/-1)
84 void *lastlocker[STEP_BACK_DEPTH];
86 void *lastunlocker[STEP_BACK_DEPTH];
88 void *lastirqlocker[STEP_BACK_DEPTH];
90 unsigned long lastlockflags; // their flags
91 unsigned long locktime;
93 void *lastirqunlocker[STEP_BACK_DEPTH]
94 ; // who last unlocked
95 unsigned long lastunlockflags; // their flags
96 int hotlockcount; // how many times it's been locked
100 // This lock is currently used only to control
101 // allocation of entries in the global state
102 static spinlock_t mylock;
103 static lockcheck_state_t state[NUM_LOCKS];
104 static lockcheck_state_t *sorted_state[NUM_LOCKS];
108 static int globallockcount=0;
110 static struct timer_list long_lock_timer;
113 #define DEBUG_OUTPUT(fmt, args...) \
116 if (numout>=OUTPUT_SKIP) { \
117 if (OUTPUT_LIMIT==0 ||(numout-OUTPUT_SKIP)<OUTPUT_LIMIT) { \
118 DEBUG(fmt, ##args); \
120 if ((numout-OUTPUT_SKIP)==OUTPUT_LIMIT) { \
121 DEBUG("LOCKCHECK: Output limit hit - no further printouts\n"); \
127 #define DEBUG_DUMPSTACK() \
129 if (numout>=OUTPUT_SKIP) { \
130 if (OUTPUT_LIMIT==0 || (numout-OUTPUT_SKIP)<OUTPUT_LIMIT) { \
137 #define LOCK_DECL unsigned long f
138 #define LOCK() spin_lock_irqsave(&mylock,f)
139 #define UNLOCK() spin_unlock_irqrestore(&mylock,f)
140 #define LOCK_ALLOC_DECL
142 #define UNLOCK_ALLOC()
147 #define LOCK_ALLOC_DECL unsigned long f
148 #define LOCK_ALLOC() spin_lock_irqsave(&mylock,f)
149 #define UNLOCK_ALLOC() spin_unlock_irqrestore(&mylock,f)
152 static void printlock(char *prefix, lockcheck_state_t *l);
155 u32 top; // next open slot 0..
156 void *lock[LOCK_STACK_DEPTH]; // the stack
157 char irq[LOCK_STACK_DEPTH]; // locked with irqsave?
158 char irqoff[LOCK_STACK_DEPTH]; // if so, what was the flag?
161 static DEFINE_PER_CPU(lock_stack_t, lock_stack);
163 static lockcheck_state_t *get_lock_entry(void)
166 lockcheck_state_t *l;
170 for (i=0;i<NUM_LOCKS;i++) {
187 static lockcheck_state_t *find_lock_entry(void *lock)
190 lockcheck_state_t *l;
192 for (i=0;i<NUM_LOCKS;i++) {
194 if (l->inuse && l->lock == lock) {
202 static void free_lock_entry(lockcheck_state_t *l)
208 static void lock_stack_print(void)
212 lock_stack_t *mystack = &(get_cpu_var(lock_stack));
213 u32 cpu = get_cpu(); put_cpu();
215 if ((mystack->top)>0) {
216 for (i=mystack->top; i>0;i--) {
217 snprintf(buf,64,"LOCK STACK (cpu=%u, index=%u, irq=%d, irqoff=%d)",cpu, i-1, (int)(mystack->irq[i-1]), (int)(mystack->irqoff[i-1]));
218 printlock(buf,find_lock_entry(mystack->lock[i-1]));
221 put_cpu_var(lock_stack);
225 static void lock_stack_lock(void *lock, char irq, unsigned long flags)
227 lock_stack_t *mystack = &(get_cpu_var(lock_stack));
228 u32 cpu = get_cpu(); put_cpu();
230 if (mystack->top>=(LOCK_STACK_DEPTH-1)) {
231 put_cpu_var(lock_stack);
232 DEBUG_OUTPUT("LOCKCHECK: Locking lock 0x%p on cpu %u exceeds stack limit of %d\n",lock,cpu,LOCK_STACK_DEPTH);
235 int oldtop = mystack->top;
236 mystack->lock[mystack->top] = lock;
237 mystack->irq[mystack->top] = irq;
238 mystack->irqoff[mystack->top] = irqs_disabled_flags(flags);
240 put_cpu_var(lock_stack);
241 if (CHECK_IRQ_FIRST_ACQUIRE && oldtop==0 && irqs_disabled_flags(flags) ) {
242 DEBUG_OUTPUT("LOCKCHECK: First lock on lock stack of processor %d but irqs were already disabled - stack trace follows\n", cpu);
251 static void lock_stack_unlock(void *lock, char irq, unsigned long flags)
253 lock_stack_t *mystack = &(get_cpu_var(lock_stack));
254 u32 cpu = get_cpu(); put_cpu();
256 if (mystack->top==0) {
257 put_cpu_var(lock_stack);
258 DEBUG_OUTPUT("LOCKCHECK: Unlocking lock 0x%p on cpu %u when lock stack is empty\n",lock,cpu);
260 if (mystack->lock[mystack->top-1] != lock) {
261 void *otherlock=mystack->lock[mystack->top-1];
262 put_cpu_var(lock_stack);
263 DEBUG_OUTPUT("LOCKCHECK: Unlocking lock 0x%p on cpu %u when top of stack is lock 0x%p\n",lock,cpu, otherlock);
266 if (irq!=mystack->irq[mystack->top-1]) {
267 char otherirq = mystack->irq[mystack->top-1];
268 put_cpu_var(lock_stack);
269 DEBUG_OUTPUT("LOCKCHECK: Unlocking lock 0x%p on cpu %u with irq=%d, but was locked with irq=%d\n",lock,cpu,irq,otherirq);
271 mystack = &(get_cpu_var(lock_stack));
273 put_cpu_var(lock_stack);
276 if (irqs_disabled_flags(flags)!=mystack->irqoff[mystack->top-1]) {
277 char otherirqoff = mystack->irqoff[mystack->top-1];
278 put_cpu_var(lock_stack);
279 DEBUG_OUTPUT("LOCKCHECK: Unlocking lock 0x%p on cpu %u sets irqoff=%d but the matching lock returned irqoff=%d\n", lock, cpu, irqs_disabled_flags(flags), otherirqoff);
281 mystack = &(get_cpu_var(lock_stack));
283 put_cpu_var(lock_stack);
285 // irq, and irq states match - good
287 put_cpu_var(lock_stack);
290 // !irq - we are good
292 put_cpu_var(lock_stack);
298 mystack = &(get_cpu_var(lock_stack));
299 if (mystack->top == 0) {
300 put_cpu_var(lock_stack);
301 if (CHECK_IRQ_LAST_RELEASE && irqs_disabled()) {
302 DEBUG_OUTPUT("LOCKCHECK: Lock stack on cpu %u is now empty, but irqs are still disabled! Stack trace follows\n", cpu);
306 put_cpu_var(lock_stack);
312 // pointers are to the pointers in the sorted_state array
313 int compare(const void *a, const void *b)
315 lockcheck_state_t *l = *((lockcheck_state_t **)a);
316 lockcheck_state_t *r = *((lockcheck_state_t **)b);
318 return -(l->hotlockcount - r->hotlockcount);
321 static void hot_lock_show(void)
327 for (i=0;i<NUM_LOCKS;i++) {
328 if (state[i].inuse) {
329 sorted_state[n]=&(state[i]);
334 sort(sorted_state,n,sizeof(lockcheck_state_t *),compare,NULL);
337 snprintf(buf,64,"HOT LOCK (%d of %d) %d acquires", i,n,sorted_state[i]->hotlockcount);
338 printlock(buf,sorted_state[i]);
343 static void hot_lock_lock(void *lock)
345 lockcheck_state_t *l = find_lock_entry(lock);
352 if (HOT_LOCK_INTERVAL && !(globallockcount % HOT_LOCK_INTERVAL )) {
353 DEBUG_OUTPUT("LOCKCHECK: Hot locks after %d acquires Follow\n",globallockcount);
359 #define hot_lock_unlock(X) // nothing for now
362 void long_lock_callback(unsigned long ignored)
364 // See if any lock has been held for too long
365 // then print all the locks if it has
367 // Note that this function does not lock because the
368 // idea is to try to catch a deadlock, which might
369 // imply that we are stalled waiting on our lock already
373 lockcheck_state_t *l;
380 for (i=0;i<NUM_LOCKS;i++) {
382 if (l->inuse && (l->irqcount>0 || l->lockcount>0)) {
383 if (jiffies_to_msecs(now-l->locktime)>LONG_LOCK_HELD_MS) {
390 DEBUG_OUTPUT("LOCKCHECK: LONG LOCK: %d locks have been held longer than %u ms - Dump of all held locks Follows\n",have,LONG_LOCK_HELD_MS);
392 for (i=0;i<NUM_LOCKS;i++) {
394 if (l->inuse && (l->irqcount>0 || l->lockcount>0)) {
395 snprintf(buf,64,"LONG LOCK (%d - %s)",
397 jiffies_to_msecs(now-l->locktime)>LONG_LOCK_HELD_MS ? "**OLD**" : "ok");
404 // reset the timer to run again
406 mod_timer(&long_lock_timer,jiffies+msecs_to_jiffies(LONG_LOCK_INTERVAL_MS));
411 void palacios_lockcheck_init()
413 memset(state,0,sizeof(lockcheck_state_t)*NUM_LOCKS);
414 spin_lock_init(&mylock);
416 #if LONG_LOCK_INTERVAL_MS>0
417 setup_timer(&long_lock_timer,long_lock_callback,0);
418 mod_timer(&long_lock_timer, jiffies + msecs_to_jiffies(LONG_LOCK_INTERVAL_MS));
421 DEBUG_OUTPUT("LOCKCHECK: LOCK CHECKING INITED (internal locking: %d, output limit: %d, output skip: %d)\n",LOCK_SELF,OUTPUT_LIMIT,OUTPUT_SKIP);
425 // This needs to be defined explictly since the intrinsic does not take a var
427 #define backtrace(t) \
428 t[0]=__builtin_return_address(STEP_BACK_DEPTH_FIRST); \
429 t[1]=__builtin_return_address(STEP_BACK_DEPTH_FIRST+1); \
430 t[2]=__builtin_return_address(STEP_BACK_DEPTH_FIRST+2); \
431 t[3]=__builtin_return_address(STEP_BACK_DEPTH_FIRST+3);
434 // For printing a backtrace
437 #define backtrace_format "%pS << %pS << %pS << %pS"
438 #define backtrace_expand(t) ((t)[0]),((t)[1]),((t)[2]),((t)[3])
441 static void clear_trace(void **trace)
445 for (i=0;i<STEP_BACK_DEPTH;i++) {
451 static void printlock(char *prefix, lockcheck_state_t *l)
453 if (!l || !(l->lock) ) {
454 DEBUG_OUTPUT("LOCKCHECK: %s: lock 0x%p BOGUS\n",prefix,l);
458 DEBUG_OUTPUT("LOCKCHECK: %s: lock 0x%p, holder %s on %u, allocator="
460 ", lockcount=%d, lastlocker="
464 ", irqcount=%d, lastirqlocker="
466 ", lastlockflags=%lu, lastirqunlocker="
468 ", lastunlockflags=%lu"
471 l->holder ? ((struct task_struct *)(l->holder))->comm : "none",
473 backtrace_expand(l->allocator),
475 backtrace_expand(l->lastlocker),
476 backtrace_expand(l->lastunlocker),
478 backtrace_expand(l->lastirqlocker),
480 backtrace_expand(l->lastirqunlocker),
482 (l->lockcount>0) || (l->irqcount>0) ? jiffies_to_msecs(jiffies-l->locktime) : 0);
491 static void find_multiple_locks_held(void)
495 lockcheck_state_t *l;
498 for (i=0;i<NUM_LOCKS;i++) {
500 if (l->inuse && l->lockcount>0) {
502 if (have>=WARN_MULTIPLE_THRESHOLD) {
508 if (have>=WARN_MULTIPLE_THRESHOLD) {
510 for (i=0;i<NUM_LOCKS;i++) {
512 if (l->inuse && l->lockcount>0) {
513 snprintf(buf,64,"MULTIPLE LOCKS HELD (%d)",have);
522 static void find_multiple_irqs_held(void)
526 lockcheck_state_t *l;
529 for (i=0;i<NUM_LOCKS;i++) {
531 if (l->inuse && l->irqcount>0) {
533 if (have>=WARN_MULTIPLE_THRESHOLD) {
539 if (have>=WARN_MULTIPLE_THRESHOLD) {
541 for (i=0;i<NUM_LOCKS;i++) {
543 if (l->inuse && l->irqcount>0) {
544 snprintf(buf,64,"MULTIPLE IRQS HELD (%d)",have);
554 void palacios_lockcheck_deinit()
557 lockcheck_state_t *l;
562 for (i=0;i<NUM_LOCKS;i++) {
565 printlock("ALLOCATED LOCK AT DEINIT",l);
566 if ((l->lockcount)) {
567 printlock("BAD LOCK COUNT AT DEINIT",l);
570 printlock("BAD IRQ COUNT AT DEINIT",l);
574 #if LONG_LOCK_INTERVAL_MS>0
575 del_timer(&long_lock_timer);
578 INFO("LOCKCHECK: DEINITED\n");
582 void palacios_lockcheck_alloc(void *lock)
584 lockcheck_state_t *l;
592 DEBUG_OUTPUT("LOCKCHECK: UNABLE TO ALLOCATE TRACKING DATA FOR LOCK 0x%p\n",lock);
595 backtrace(l->allocator);
596 l->lockcount=l->irqcount=0;
597 clear_trace(l->lastlocker);
598 clear_trace(l->lastunlocker);
599 clear_trace(l->lastirqlocker);
600 clear_trace(l->lastirqunlocker);
601 //INFO("LOCKCHECK: LOCK ALLOCATE 0x%p\n",lock);
603 printlock("NEW LOCK", l);
609 void palacios_lockcheck_free(void *lock)
611 lockcheck_state_t *l;
615 l=find_lock_entry(lock);
619 DEBUG_OUTPUT("LOCKCHECK: FREEING UNTRACKED LOCK 0x%p - stack trace follows\n",lock);
624 if ((l->lockcount)) {
625 printlock("BAD LOCK COUNT AT FREE",l);
629 printlock("BAD IRQ COUNT AT FREE",l);
633 printlock("FREE LOCK",l);
642 void palacios_lockcheck_lock(void *lock)
645 lockcheck_state_t *l;
650 l=find_lock_entry(lock);
654 DEBUG_OUTPUT("LOCKCHECK: LOCKING UNTRACKED LOCK 0x%p - stack follows\n",lock);
659 if (l->lockcount!=0) {
660 printlock("BAD LOCKCOUNT AT LOCK - stack follows",l);
663 if (l->irqcount!=0) {
664 printlock("BAD IRQCOUNT AT LOCK - stack follows",l);
670 l->holdingcpu=get_cpu(); put_cpu();
672 backtrace(l->lastlocker);
674 find_multiple_locks_held();
676 lock_stack_lock(lock,0,0);
687 void palacios_lockcheck_unlock(void *lock)
690 lockcheck_state_t *l;
694 l=find_lock_entry(lock);
698 DEBUG_OUTPUT("LOCKCHECK: UNLOCKING UNTRACKED LOCK 0x%p - stack follows\n",lock);
703 if (l->lockcount!=1) {
704 printlock("LOCKCHECK: BAD LOCKCOUNT AT UNLOCK - stack follows",l);
707 if (l->irqcount!=0) {
708 printlock("LOCKCHECK: BAD IRQCOUNT AT UNLOCK - stack follows",l);
712 lock_stack_unlock(lock,0,0);
714 hot_lock_unlock(lock);
719 backtrace(l->lastunlocker);
721 #if PRINT_LOCK_UNLOCK
722 printlock("UNLOCK",l);
729 void palacios_lockcheck_lock_irqsave(void *lock,unsigned long flags)
732 lockcheck_state_t *l;
736 l=find_lock_entry(lock);
740 DEBUG_OUTPUT("LOCKCHECK: IRQ LOCKING UNTRACKED LOCK 0x%p - stack follows\n",lock);
745 if (l->lockcount!=0) {
746 printlock("BAD LOCKCOUNT AT IRQ LOCK - stack follows",l);
749 if (l->irqcount!=0) {
750 printlock("BAD IRQCOUNT AT IRQ LOCK - stack follows",l);
756 l->holdingcpu=get_cpu(); put_cpu();
757 l->lastlockflags=flags;
759 backtrace(l->lastirqlocker);
761 find_multiple_irqs_held();
763 lock_stack_lock(lock,1,flags);
768 printlock("LOCK_IRQSAVE",l);
778 // This is separated into two components to avoid a race between
779 // the underlying spin_unlock_irqrestore and the next lockcheck_lock_irqsave
780 // If simply record the state after the unlock, we might see that the
781 // irqcount has already increased. Therefore, we will acquire the
782 // lockchecker lock in _pre and release it in _post. Note that when
783 // we release the lock in _post, we restore the flags provided by the
784 // code under test - NOT our original flags
786 // unlock_pre() - stores flags, takes mylock discard flags
787 // At this point, a lockcheck_lock cannot enter, since it's stuck on mylock
788 // spinunlock - restores lock, restores original flags
789 // unlock_post() - restores mylock WITH orig flags
791 void palacios_lockcheck_unlock_irqrestore_pre(void *lock,unsigned long flags)
795 LOCK(); // flags are discarded
796 // at this point, the actual spin unlock can run
797 // if another thread hits lockcheck_irqsave at this point, it
798 // will block on mylock
801 void palacios_lockcheck_unlock_irqrestore_post(void *lock,unsigned long flags)
804 lockcheck_state_t *l;
807 // when we unlock, want to restore the flags *the user wants*
811 // Note that we DO NOT take mylock here, since we already took it in
814 l=find_lock_entry(lock);
817 UNLOCK(); // release any waiting threads on lockcheck_lock_irqsave
818 DEBUG_OUTPUT("LOCKCHECK: IRQ UNLOCKING UNTRACKED LOCK 0x%p - stack follows\n",lock);
823 if (l->lockcount!=0) {
824 printlock("LOCKCHECK: BAD LOCKCOUNT AT IRQ UNLOCK - stack follows",l);
827 if (l->irqcount!=1) {
828 printlock("LOCKCHECK: BAD IRQCOUNT AT IRQ UNLOCK - stack follows",l);
835 l->lastunlockflags = flags;
837 lock_stack_unlock(lock,1,flags);
839 hot_lock_unlock(lock);
841 backtrace(l->lastirqunlocker);
843 #if PRINT_LOCK_UNLOCK
844 printlock("UNLOCK_IRQRESTORE",l);
846 UNLOCK(); // release any waiting threads on lockcheck_lock_irqsave