2.6.19-rt14 slowdown compared to 2.6.19

Yes, 64-bit kernel was used.

Volanomark and Re-Aim7 ran close to 0% idle time for 2.6.19 kernel. Idle time
increase significantly for Volanomark (to 60% idle) and Re-Aim7 (to 20% idle)
with the rt kernel. For netperf, the system was 60% idle for both 2.6.19 and rt kernel and changes in idle time was not significant.

Turning off PREEMPT_RT for 2.6.20-rc2-rt0 kernel restored most the performance of Volanaomark
and Re-Aim7. Idle time is close to 0%. So the benchmarks with large number of threads are affected more by PREEMPT_RT.

For netperf TCP streaming, the performance improved from 40% down to 20% down from 2.6.20-rc2 kernel. There is only a server and a client process
for netperf. The underlying reason for the change in performance is probably different.

Thanks for the pointer. Will let you know of any relevant traces.

Thanks.

Tim

Tim,

	http://mmlinux.sourceforge.net/public/patch-2.6.20-rc2-rt2.lock_stat.patch

You can also apply this patch to get more precise statistics down to the lock. For example:

...

	[50, 30, 279 :: 1, 0]		{tty_ldisc_try, -, 0}
	[5, 5, 0 :: 19, 0]		{alloc_super, fs/super.c, 76}
	[5, 5, 3 :: 1, 0]		{__free_pages_ok, -, 0}
	[5728, 862, 156 :: 2, 0]		{journal_init_common, fs/jbd/journal.c, 667}
	[594713, 79020, 4287 :: 60818, 0]		{inode_init_once, fs/inode.c, 193}
	[602, 0, 0 :: 1, 0]		{lru_cache_add_active, -, 0}
	[63, 5, 59 :: 1, 0]		{lookup_mnt, -, 0}
	[6425, 378, 103 :: 24, 0]		{initialize_tty_struct, drivers/char/tty_io.c, 3530}
	[6708, 1, 225 :: 1, 0]		{file_move, -, 0}
	[67, 8, 15 :: 1, 0]		{do_lookup, -, 0}
	[69, 0, 0 :: 1, 0]		{exit_mmap, -, 0}
	[7, 0, 0 :: 1, 0]		{uart_set_options, drivers/serial/serial_core.c, 1876}
	[76, 0, 0 :: 1, 0]		{get_zone_pcp, -, 0}
	[7777, 5, 9 :: 1, 0]		{as_work_handler, -, 0}
	[8689, 0, 0 :: 15, 0]		{create_workqueue_thread, kernel/workqueue.c, 474}
	[89, 7, 6 :: 195, 0]		{sighand_ctor, kernel/fork.c, 1474}
	@contention events = 1791177
	@found = 21

Is the output from /proc/lock_stat/contention. First column is the number of contention that will results in a full block of the task, second is the number of times the mutex owner is active on a per cpu run queue the scheduler and third is the number of times Steve Rostedt's ownership handoff code averted a full block. Peter Zijlstra used it initially during his files_lock work.

Overhead of the patch is very low since it is only recording stuff in the slow path of the rt-mutex implementation.

Writing to that file clears all of the stats for a fresh run with a benchmark. This should give a precise point at which any contention would happen in -rt. In general, -rt should do about as well as the stock kernel minus the overhead of interrupt threads.

Since the last release, I've added checks for whether the task is running as "current" on a run queue to see if adaptive spins would be useful in -rt.

These new stats show that only a small percentage of events would benefit from the use of adaptive spins in front of a rt- mutex. Any implementation of it would have little impact on the system. It's not the mechanism but the raw MP work itself that contributes to the good MP performance of Linux.

Apply and have fun.

bill

your patch looks pretty ok to me in principle. A couple of suggestions to make it more mergable:

- instead of BUG_ON()s please use DEBUG_LOCKS_WARN_ON() and make sure the code is never entered again if one assertion has been triggered. Pass down a return result of '0' to signal failure. See kernel/lockdep.c about how to do this. One thing we dont need are bugs in instrumentation bringing down a machine.

- remove dead (#if 0) code

- Documentation/CodingStyle compliance - the code is not ugly per se but still looks a bit 'alien' - please try to make it look Linuxish, if i apply this we'll probably stick with it forever. This is the major reason i havent applied it yet.

- the xfs/wrap_lock change looks bogus - the lock is initialized already. What am i missing?

Ingo

I did some cleanup while reviewing the patch, nothing very exciting but it's an attempt to bring it more into the "Linuxish" scope .. I didn't compile it so be warned.

There lots of ifdef'd code under CONFIG_LOCK_STAT inside rtmutex.c I suspect it would be a benefit to move that all into a header and ifdef only in the header .

Daniel

---
 include/linux/lock_stat.h |   25 +++++++++++++++----------
 kernel/lock_stat.c        |   34 ++++++++++++++++++++++------------
 2 files changed, 37 insertions(+), 22 deletions(-)

Index: linux-2.6.19/include/linux/lock_stat.h
===================================================================
@@ -26,9 +26,9 @@
 #include <asm/atomic.h>
 
 typedef struct lock_stat {
-	char	function[KSYM_NAME_LEN];
-	int	line;
-	char	*file;
+	char			function[KSYM_NAME_LEN];
+	int			line;
+	char			*file;
 
 	atomic_t		ncontended;
 	atomic_t		nhandoff;

@@ -52,7 +52,7 @@ struct task_struct;
 #define LOCK_STAT_INIT(field)
 #define LOCK_STAT_INITIALIZER(field) { 			\
 		__FILE__, __FUNCTION__, __LINE__,	\
-		ATOMIC_INIT(0), LIST_HEAD_INIT(field)}
+		ATOMIC_INIT(0), LIST_HEAD_INIT(field) }
 
 #define LOCK_STAT_NOTE			__FILE__, __FUNCTION__, __LINE__
 #define LOCK_STAT_NOTE_VARS		_file, _function, _line

@@ -84,9 +84,12 @@ extern void lock_stat_sys_init(void);
 
 #define lock_stat_is_initialized(o) ((unsigned long) (*o)->file)
 
-extern void lock_stat_note_contention(lock_stat_ref_t *ls, struct task_struct *owner, unsigned long ip, int handoff);
+extern void lock_stat_note_contention(lock_stat_ref_t *ls,
+				      struct task_struct *owner,
+				      unsigned long ip, int handoff);
 extern void lock_stat_print(void);
-extern void lock_stat_scoped_attach(lock_stat_ref_t *_s, LOCK_STAT_NOTE_PARAM_DECL);
+extern void lock_stat_scoped_attach(lock_stat_ref_t *_s,
+				    LOCK_STAT_NOTE_PARAM_DECL);
 
 #define ksym_strcmp(a, b) strncmp(a, b, KSYM_NAME_LEN)
 #define ksym_strcpy(a, b) strncpy(a, b, KSYM_NAME_LEN)

@@ -102,10 +105,11 @@ static inline char * ksym_strdup(const c
 
 #define LS_INIT(name, h) {				\
 	/*.function,*/ .file = h, .line = 1,		\
-	.nhandoff = ATOMIC_INIT(0), .ntracked = 0, .ncontended = ATOMIC_INIT(0),	\
+	.nhandoff = ATOMIC_INIT(0), .ntracked = 0,	\
+	.ncontended = ATOMIC_INIT(0),			\
 	.list_head = LIST_HEAD_INIT(name.list_head),	\
-	.rb_node.rb_left = NULL, .rb_node.rb_left = NULL \
-	}
+	.rb_node.rb_left = NULL,			\
+	.rb_node.rb_left = NULL }			\
 
 #define DECLARE_LS_ENTRY(name)				\
 	extern struct lock_stat _lock_stat_##name##_entry

@@ -114,7 +118,8 @@ static inline char * ksym_strdup(const c
 */
 
 #define DEFINE_LS_ENTRY(name)				\
-	struct lock_stat _lock_stat_##name##_entry = LS_INIT(_lock_stat_##name##_entry, #name "_string")
+	struct lock_stat _lock_stat_##name##_entry = 	\
+		LS_INIT(_lock_stat_##name##_entry, #name "_string")
 
 DECLARE_LS_ENTRY(d_alloc);
 DECLARE_LS_ENTRY(eventpoll_init_file);

Index: linux-2.6.19/kernel/lock_stat.c
===================================================================
@@ -71,7 +71,9 @@ static char null_string[]		= "";
 static char static_string[]		= "-";
 static char special_static_string[]	= "-";
 
-struct lock_stat _lock_stat_null_entry	= LS_INIT(_lock_stat_null_entry,   null_string);
+struct lock_stat _lock_stat_null_entry	=
+	LS_INIT(_lock_stat_null_entry, null_string);
+
 EXPORT_SYMBOL(_lock_stat_null_entry);
 
 static DEFINE_LS_ENTRY(inline);		/* lock_stat_inline_entry	*/

@@ -111,10 +113,12 @@ static DEFINE_LS_ENTRY(tcp_init_1);
 static DEFINE_LS_ENTRY(tcp_init_2);
 */
 
-/* I should never have to create more entries that this since I audited the kernel
- * and found out that there are only ~1500 or so places in the kernel where these
- * rw/spinlocks are initialized. Use the initialization points as a hash value to
- * look up the backing objects */
+/*
+ * I should never have to create more entries that this since I audited the
+ * kernel and found out that there are only ~1500 or so places in the kernel
+ * where these rw/spinlocks are initialized. Use the initialization points as a
+ * hash value to look up the backing objects
+ */
 
 #define MAGIC_ENTRIES 1600
 

@@ -156,7 +160,7 @@ void lock_stat_sys_init(void)
 	int i;
 
 	for (i = 0; i < MAGIC_ENTRIES; ++i) {
-		s = (struct lock_stat *) kmalloc(sizeof(struct lock_stat), GFP_KERNEL);
+		s = kmalloc(sizeof(struct lock_stat), GFP_KERNEL);
 
 		if (s) {
 			lock_stat_init(s);

@@ -182,7 +186,8 @@ void lock_stat_sys_init(void)
 }
 
 static
-struct lock_stat *lock_stat_allocate_object(void) {
+struct lock_stat *lock_stat_allocate_object(void)
+{
 	unsigned long flags;
 
 	spin_lock_irqsave(&free_store_lock, flags);

@@ -208,7 +213,8 @@ struct lock_stat *lock_stat_allocate_obj
  * Comparision, greater to/less than or equals. zero is equals.
  * Suitable for ordered insertion into a tree
  *
- * The (entry - object) order of comparison is switched from the parameter definition
+ * The (entry - object) order of comparison is switched from the parameter
+ * definition
  */
 static
 int lock_stat_compare_objs(struct lock_stat *a, struct lock_stat *b)

@@ -254,7 +260,8 @@ void lock_stat_print_hash(struct lock_st
 }
 
 static
-void lock_stat_print_entry(struct seq_file *seq, struct lock_stat *o) {
+void lock_stat_print_entry(struct seq_file *seq, struct lock_stat *o)
+{
 	seq_printf(seq, "[%d, %d, %d :: %d, %d]\t\t{%s, %s, %d}\n",
 						atomic_read(&o->ncontended),
 						atomic_read(&o->nspinnable),

@@ -282,7 +289,8 @@ void lock_stat_rbtree_db_zero(void) {
 }
 
 static
-void _lock_stat_rbtree_db_zero(struct rb_node *node) {
+void _lock_stat_rbtree_db_zero(struct rb_node *node)
+{
 
 	struct lock_stat *o = container_of(node, struct lock_stat, rb_node);
 

@@ -295,12 +303,14 @@ void _lock_stat_rbtree_db_zero(struct rb
 }
 
 static
-void lock_stat_rbtree_db_print(struct seq_file *seq) {
+void lock_stat_rbtree_db_print(struct seq_file *seq)
+{
 	_lock_stat_rbtree_db_print(seq, lock_stat_rbtree_db.rb_node, 0);
 }
 
 static
-void _lock_stat_rbtree_db_print(struct seq_file *seq, struct rb_node *node, int level) {
+void _lock_stat_rbtree_db_print(struct seq_file *seq, struct rb_node *node, int level)
+{
 
 	struct lock_stat *o = container_of(node, struct lock_stat, rb_node);
 

Ingo and Daniel,

I'll try and make it more Linuxish. It's one of the reasons why I posted it since I knew it would need some kind of help in that arena and I've been in need of feedback regarding it. Originally, I picked a style that made what I was doing extremely obvious and clear to facilitate development which is the rationale behind it.

I'll make those changes and we can progressively pass it back and forth to see if this passes.

bill

I'm using a non-fatal error checking instead of BUG_ON. BUG_ON was a more aggressive way that I use to find problem initiallly.

Done.

I reformatted most of the patch to be 80 column limited. I simplified a number of names, but I'm open to suggestions and patches to how to go about this. Much of this code was a style experiment, but now I have to make this more mergable.

Correct. This has been removed.

I've applied Daniel Walker's changes as well.

Patch here:

	http://mmlinux.sourceforge.net/public/patch-2.6.20-rc2-rt2.2.lock_stat.patch

bill

http://mmlinux.sourceforge.net/public/patch-2.6.20-rc2-rt2.2.lock_stat.p
atch

This version is much better and ran stablely.

If I'm reading the output correctly, the locks are listed by their initialization point (function, file and line # that a lock is initialized).
That's good information to identify the lock.

However, it will be more useful if there is information about where the locking
was initiated from and who was trying to obtain the lock.

Tim

Yes, that's correct.

Good to know that. What did the output reveal ?

It can be extended by pid/futex for userspace app that has yet to be done. It might require changes to glibc or a some kind of dynamic tracing to communicate to kernel space information about that lock. There are other kernel uses as well. It's just a basic mechanisms for a variety of uses. This patch has some LTT and Dtrace-isms to it.

What's your intended use again summarized ? futex contention ? I'll read the first posting again.

It would add quite a bit more overhead, but it could be done with lockdep directly I believe in conjunction with this patch. However, it should be specific enough though that a kernel code examination at the key points of all users of the lock would show where the problem places are as well as users.

bill

Earlier I used latency_trace and figured that there was read contention on mm->mmap_sem during call to _rt_down_read by java threads when I was running volanomark. That caused the slowdown of the rt kernel
compared to non-rt kernel. The output from lock_stat confirm that mm->map_sem was indeed the most heavily contended lock.

Tim

Can you sort the output ("sort -n" what ever..) and post it without the zeroed entries ?

I'm curious about how that statistical spike compares to the rest of the system activity. I'm sure that'll get the attention of Peter as well and maybe he'll do something about it ? :)

bill

Here's the lockstat trace. You can cross reference it with my earlier post.
http://marc.theaimsgroup.com/?l=linux-kernel&m=116743637422465&w=2

The contention happened on mm->mmap_sem shared
by the java threads during futex_wake's invocation of _rt_down_read.

Tim

@contention events = 247149
@failure_events = 146
@lookup_failed_scope = 175
@lookup_failed_static = 43
@static_found = 16
[1, 113, 77 -- 32768, 0] {tcp_init, net/ipv4/tcp.c, 2426}
[2, 759, 182 -- 1, 0] {lock_kernel, -, 0}
[13, 0, 7 -- 4, 0] {kmem_cache_free, -, 0}
[25, 3564, 9278 -- 1, 0] {lock_timer_base, -, 0}
[56, 9528, 24552 -- 3, 0] {init_timers_cpu, kernel/timer.c,
1842}
[471, 52845, 17682 -- 10448, 0] {sock_lock_init, net/core/sock.c,
817}
[32251, 9024, 242 -- 256, 0] {init, kernel/futex.c, 2781}
[173724, 11899638, 9886960 -- 11194, 0] {mm_init, kernel/fork.c,
369}

...

Thanks, the numbers look a bit weird in that the first column should have a bigger number of events than that second column since it is a special case subset. Looking at the lock_stat_note() code should show that to be the case. Did you make a change to the output ?

I can't tell which are "steal", actively running or overall contention stats against the lock from your output.

Thanks

bill

Also, the output is weird in that the "contention_events" should be a total of all of the events in the first three columns. Clearly the number is wrong and I don't know if the text output was mangled or if that's accurate and my code is buggy. I have yet to see it give me data like that yet in my set up.

The fourth and fifth columns are the number of times this lock was initialized inline by a function like spin_lock_init(). It might have a correspondence to clone() calls.

bill

No, I did not change the output. I did reset to the contention content

by doing echo "0" > /proc/lock_stat/contention.

I noticed that the first column get reset but not the second column. So the reset code probably need to be checked.

Tim

This should have the fix.

	http://mmlinux.sf.net/public/patch-2.6.20-rc2-rt2.3.lock_stat.patch

If you can rerun it and post the results, it'll hopefully show the behavior of that lock acquisition better.

Thanks

bill

http://mmlinux.sf.net/public/patch-2.6.20-rc2-rt2.3.lock_stat.patch

Here's the run with fix to produce correct statistics.

Tim

@contention events = 848858
@failure_events = 10
@lookup_failed_scope = 175
@lookup_failed_static = 47
@static_found = 17
[2, 0, 0 -- 1, 0] {journal_init_common, fs/jbd/journal.c,
667}
[2, 0, 0 -- 31, 0] {blk_init_queue_node, block/ll_rw_blk.c,
1910}
[2, 0, 0 -- 31, 0] {create_workqueue_thread,
kernel/workqueue.c, 474}

[3, 3, 2 -- 16384, 0]           {tcp_init, net/ipv4/tcp.c, 2426}
[4, 4, 1 -- 1, 0]               {lock_kernel, -, 0}
[19, 0, 0 -- 1, 0]              {kmem_cache_alloc, -, 0}
[25, 0, 0 -- 1, 0]              {kfree, -, 0}
[49, 0, 0 -- 2, 0]              {kmem_cache_free, -, 0}
[69, 38, 176 -- 1, 0]           {lock_timer_base, -, 0}
[211, 117, 517 -- 3, 0]         {init_timers_cpu, kernel/timer.c, 1842}

[1540, 778, 365 -- 7326, 0] {sock_lock_init,
net/core/sock.c, 817}
[112584, 150, 6 -- 256, 0] {init, kernel/futex.c, 2781}
[597012, 183895, 136277 -- 9546, 0] {mm_init, kernel/fork.c,
369}

...

Interesting. The second column means that those can be adaptively spun on to prevent the blocking from happening. That's roughly 1/3rd of the blocking events that happen (second/first). Something like that would help out, but the problem is that contention on that lock in the first place.

Also, Linux can do a hell of a lot of context switches per second. Is the number of total contentions (top figure) in that run consistent with the performance degradation ? and how much the reduction of those events by 1/3rd would help out with the benchmark ? Those are the questions in my mind at this moment.

bill

thanks. It's looking better, but there's still quite a bit of work left:

there's considerable amount of whitespace noise in it - lots of lines with space/tab at the end, lines with 8 spaces instead of tabs, etc.

comment style issues:

+/* To be use for avoiding the dynamic attachment of spinlocks at runtime
+ * by attaching it inline with the lock initialization function */

the proper multi-line style is:

/*
* To be used for avoiding the dynamic attachment of spinlocks at
* runtime by attaching it inline with the lock initialization function:
*/

(note i also fixed a typo in the one above)

more unused code:

+/*
+static DEFINE_LS_ENTRY(__pte_alloc);
+static DEFINE_LS_ENTRY(get_empty_filp);
+static DEFINE_LS_ENTRY(init_waitqueue_head);
...
+*/

these:

+static int lock_stat_inited = 0;

should not be initialized to 0, that is implicit for static variables.

weird alignment here:

+void lock_stat_init(struct lock_stat *oref)
+{

+       oref->function[0]       = 0;
+       oref->file      = NULL;
+       oref->line      = 0;

+
+ oref->ntracked = 0;

funky branching:

+ spin_lock_irqsave(&free_store_lock, flags);
+ if (!list_empty(&lock_stat_free_store)) {
+ struct list_head *e = lock_stat_free_store.next;
+ struct lock_stat *s;
+
+ s = container_of(e, struct lock_stat, list_head);
+ list_del(e);
+
+ spin_unlock_irqrestore(&free_store_lock, flags);
+
+ return s;
+ }
+ spin_unlock_irqrestore(&free_store_lock, flags);
+
+ return NULL;

that should be s = NULL in the function scope and a plain unlock and return s.

assignments mixed with arithmetics:

+static
+int lock_stat_compare_objs(struct lock_stat *x, struct lock_stat *y) +{
+ int a = 0, b = 0, c = 0;
+

+       (a = ksym_strcmp(x->function, y->function))     ||
+       (b = ksym_strcmp(x->file, y->file))             ||
+       (c = (x->line - y->line));

+
+ return a | b | c;

the usual (and more readable) style is to separate them out explicitly:

	a = ksym_strcmp(x->function, y->function);
	if (!a)
		return 0;
	b = ksym_strcmp(x->file, y->file);
	if (!b)
		return 0;

	return x->line == y->line;

(detail: this btw also fixes a bug in the function above AFAICS, in the a && !b case.)

also, i'm not fully convinced we want that x->function as a string. That makes comparisons alot slower. Why not make it a void *, and resolve to the name via kallsyms only when printing it in /proc, like lockdep does it?

no need to put dates into comments:

+ * Fri Oct 27 00:26:08 PDT 2006

then:

+ while (node)
+ {

proper style is:

+ while (node) {

this function definition:

+static
+void lock_stat_insert_object(struct lock_stat *o)

can be single-line. We make it multi-line only when needed.

these are only samples of the types of style problems still present in the code.

Ingo

These comments from me are before the hand merge I'm going to do tonight.

I fixed all of those I can find.

Removed.

I made this change.

Not sure what you mean here but I made the key comparison so that it would treat each struct field in most to least significant order evaluation. The old code worked fine. What you're seeing is the newer stuff.

I've made your suggested change, but I'm not done with it.

Done for all the instances I remember off hand.

I'm a bit of a space cadet so I might have missed something.

Latest patch here.

	http://finfin.is-a-geek.org/~billh/contention/patch-2.6.20-rc2-rt2.4.lock_stat.patch

I'm going to review and hand merge your changes to the older patch tonight.

Thanks for the comments.

bill

one more suggestion: please do diffs in -p1 (not in -p0) format.

Ingo

hm, most of the review feedback i gave has not been addressed in the patch above. So i did it myself: find below various fixups for problems i outlined plus for a few other problems as well (ontop of 2.3.lock_stat).

While it's now markedly better it's still not quite mergeable, for example the build fails quite spectacularly if LOCK_STAT is disabled in the .config.

Also, it would be nice to replace those #ifdef CONFIG_LOCK_STAT changes in rtmutex.c with some nice inline functions that do nothing on !CONFIG_LOCK_STAT.

but in general i'm positive about the direction this is heading, it just needs more work.

Ingo

---
 include/linux/eventpoll.h |    3 
 include/linux/lock_stat.h |   50 +-----
 include/linux/sched.h     |    3 
 kernel/futex.c            |    6 
 kernel/lock_stat.c        |  352 +++++++++++++++-------------------------------
 kernel/rtmutex.c          |    4 
 6 files changed, 139 insertions(+), 279 deletions(-)

Index: linux/include/linux/eventpoll.h
===================================================================
@@ -15,7 +15,6 @@
 #define _LINUX_EVENTPOLL_H
 
 #include <linux/types.h>
-#include <linux/lock_stat.h>
 
 
 /* Valid opcodes to issue to sys_epoll_ctl() */

@@ -46,6 +45,8 @@ struct epoll_event {
 
 #ifdef __KERNEL__
 
+#include <linux/lock_stat.h>
+
 /* Forward declarations to avoid compiler errors */
 struct file;
 

Index: linux/include/linux/sched.h
===================================================================
@@ -236,6 +236,9 @@ extern void sched_init(void);
 extern void sched_init_smp(void);
 extern void init_idle(struct task_struct *idle, int cpu);
 
+extern int task_on_rq(int cpu, struct task_struct *p);
+extern struct task_struct *get_task_on_rq(int cpu);
+
 extern cpumask_t nohz_cpu_mask;
 
 /*

Index: linux/kernel/futex.c
===================================================================
@@ -760,7 +760,8 @@ retry:
 		(*pi_state)->key = *key;
 
 		/* init the mutex without owner */
-		__rt_mutex_init(&(*pi_state)->pi_mutex, NULL);
+		__rt_mutex_init(&(*pi_state)->pi_mutex, NULL
+				__COMMA_LOCK_STAT_NOTE);
 	}
 
 	return 0;

@@ -2773,7 +2774,8 @@ retry:
 		(*pi_state)->key = *key;
 
 		/* init the mutex without owner */
-		__rt_mutex_init(&(*pi_state)->pi_mutex, NULL);
+		__rt_mutex_init(&(*pi_state)->pi_mutex, NULL
+				__COMMA_LOCK_STAT_NOTE);
 	}
 
 	return 0;

Index: linux/kernel/rtmutex.c
===================================================================
@@ -970,9 +970,6 @@ rt_mutex_slowlock(struct rt_mutex *lock,
 	int ret = 0, saved_lock_depth = -1;
 	struct rt_mutex_waiter waiter;
 	unsigned long flags;
-#ifdef CONFIG_LOCK_STAT
-	struct task_struct *owner;
-#endif
 
 	debug_rt_mutex_init_waiter(&waiter);
 	waiter.task = NULL;

@@ -1113,7 +1110,6 @@ rt_mutex_slowtrylock(struct rt_mutex *lo
 	unsigned long flags;
 	int ret = 0;
 #ifdef CONFIG_LOCK_STAT
-	struct task_struct *owner;
 	int type;
 #endif
 

Sorry, I've been siliently keeping your suggested change in my private repo without announcing it to the world. I'll reply to the old email in another message at length.

	http://mmlinux.sourceforge.net/public/patch-2.6.20-rc2-rt2.4.lock_stat.patch

I'll look into it. I've been focused on clean up and a couple of other things regard the stability of this patch. Making small changes in it tends to make the kernel crash hard and I suspect that it's an interaction problem with lockdep and that I need to turn lockdep off when hitting "lock stats" locks. I'm going to move to "__raw_..." locks...

Meanwhile please wait until I hand interpret and merge your changes to an older patch into my latest stuff. If it's takes too long, I suggest keeping out of the tree for a bit until I finish this round unless something is pressing for this to happen now like a mass change to the spinlock macros or something. I stalled a bit trying to get Peter Zijlstra an extra feature.

I'll look into it. Not sure what your choice in style is here and I'm open to suggestions. I'm also interested in a reduction of #define identifier length if you or somebody else has some kind of good convention to suggest.

Sorry, for the lag. Trying to juggle this and the current demands of my employeer contributed to this lag unfortunately.

bill

http://mmlinux.sourceforge.net/public/patch-2.6.20-rc2-rt2.lock_stat.pat
ch

Bill,

I'm having some problem getting this patch to run stablely. I'm encoutering errors like that in the trace that follow:

Thanks.
Tim

Unable to handle kernel NULL pointer dereference at 0000000000000008
RIP:
 [<ffffffff802cd6e4>] lock_stat_note_contention+0x12d/0x1c3
PGD 0
Oops: 0000 [1] PREEMPT SMP
CPU 1
Modules linked in: autofs4 sunrpc dm_mirror dm_mod video sbs i2c_ec dock

button battery ac uhci_hcd ehci_hcd i2dPid: 0, comm: swapper Not tainted 2.6.20-rc2-rt2 #4

RIP: 0010:[<ffffffff802cd6e4>]  [<ffffffff802cd6e4>]
lock_stat_note_contention+0x12d/0x1c3
RSP: 0018:ffff81013fdb3d28  EFLAGS: 00010097
RAX: ffff81013fd68018 RBX: ffff81013fd68000 RCX: 0000000000000000
RDX: ffffffff8026762e RSI: 0000000000000000 RDI: ffffffff8026762e
RBP: ffff81013fdb3df8 R08: ffff8100092bab60 R09: ffff8100092aafc8
R10: 0000000000000001 R11: 0000000000000000 R12: ffff81013fd68030
R13: 0000000000000000 R14: 0000000000000046 R15: 0000002728d5ecd0
FS:  0000000000000000(0000) GS:ffff81013fd078c0(0000)

knlGS:0000000000000000
CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b
CR2: 0000000000000008 CR3: 0000000000201000 CR4: 00000000000006e0 Process swapper (pid: 0, threadinfo ffff81013fdb2000, task ffff81013fdb14e0)

Stack:  0000000000000000 0000000200000001 0000000000000000
0000000000000000
 0000000000000000 0000000000000000 0000000000000100 000000000000000e
 000000000000000e 0000000000000000 0000000000000000 ffff8100092bc440
Call Trace:
 [<ffffffff802af471>] rt_mutex_slowtrylock+0x84/0x9b
 [<ffffffff80266909>] rt_mutex_trylock+0x2e/0x30
 [<ffffffff8026762e>] rt_spin_trylock+0x9/0xb
 [<ffffffff8029beef>] get_next_timer_interrupt+0x34/0x226
 [<ffffffff802a8b4d>] hrtimer_stop_sched_tick+0xb6/0x138
 [<ffffffff8024b1ce>] cpu_idle+0x1b/0xdd
 [<ffffffff80278edd>] start_secondary+0x2ed/0x2f9

---------------------------
| preempt count: 00000003 ]
| 3-level deep critical section nesting:
----------------------------------------
.. [<ffffffff8024b28a>] .... cpu_idle+0xd7/0xdd
.....[<ffffffff80278edd>] .. ( <= start_secondary+0x2ed/0x2f9)
.. [<ffffffff80267837>] .... __spin_lock_irqsave+0x18/0x42
.....[<ffffffff802af406>] .. ( <= rt_mutex_slowtrylock+0x19/0x9b)
.. [<ffffffff802678db>] .... __spin_trylock+0x14/0x4c
.....[<ffffffff80268540>] .. ( <= oops_begin+0x23/0x6f)

skipping trace printing on CPU#1 != -1

Code: 49 8b 45 08 8b 78 18 75 0d 49 8b 04 24 f0 ff 80 94 00 00 00
RIP  [<ffffffff802cd6e4>] lock_stat_note_contention+0x12d/0x1c3
 RSP <ffff81013fdb3d28>

CR2: 0000000000000008
<3>BUG: sleeping function called from invalid context swapper(0) at
kernel/rtmutex.c:1312
in_atomic():1 [00000002], irqs_disabled():1

Call Trace:
 [<ffffffff8026ec53>] dump_trace+0xbe/0x3cd
 [<ffffffff8026eff3>] show_trace+0x3a/0x58
 [<ffffffff8026f026>] dump_stack+0x15/0x17
 [<ffffffff8020b75e>] __might_sleep+0x103/0x10a
 [<ffffffff80266e44>] rt_mutex_lock_with_ip+0x1e/0xac
 [<ffffffff802aff07>] __rt_down_read+0x49/0x4d
 [<ffffffff802aff16>] rt_down_read+0xb/0xd
 [<ffffffff8029fc96>] blocking_notifier_call_chain+0x19/0x3f
 [<ffffffff80296301>] profile_task_exit+0x15/0x17
 [<ffffffff80215572>] do_exit+0x25/0x8de
 [<ffffffff8026a2c1>] do_page_fault+0x7d4/0x856
 [<ffffffff802681ad>] error_exit+0x0/0x84
 [<ffffffff802cd6e4>] lock_stat_note_contention+0x12d/0x1c3
 [<ffffffff802af471>] rt_mutex_slowtrylock+0x84/0x9b
 [<ffffffff80266909>] rt_mutex_trylock+0x2e/0x30
 [<ffffffff8026762e>] rt_spin_trylock+0x9/0xb
 [<ffffffff8029beef>] get_next_timer_interrupt+0x34/0x226
 [<ffffffff802a8b4d>] hrtimer_stop_sched_tick+0xb6/0x138
 [<ffffffff8024b1ce>] cpu_idle+0x1b/0xdd
 [<ffffffff80278edd>] start_secondary+0x2ed/0x2f9

Yes, those are the reason why I have some aggressive asserts in the code to try track down the problem. Try this:

http://mmlinux.sourceforge.net/public/patch-2.6.20-rc2-rt2.1.lock_stat.patch

It's got some cosmestic clean up in it to make it more Linux-ish instead of me trying to reinvent some kind of Smalltalk system in the kernel. I'm trying to address all of Ingo's complaints about the code so it's still a work in progress, namely the style issues (I'd like help/suggestions on that) and assert conventions.

It might the case that the lock isn't know to the lock stats code yet. It's got some technical overlap with lockdep in that a lock might not be known yet and is causing a crashing.

Try that patch and report back to me what happens.

bill

The stack trace and code examination reveals, if that structure in the timer code is used before it's initialized by the CPU bringup, it'll cause problems like that crash. I'll look at it later on tonight.

bill