lock contention tracking slimmed down

The output has changed from a terribly wide table to an enormously long list (just the generic way the statistics code prints data).

Quoted 1 line · Martin Peschke

The output has changed from a terribly wide table to an enormously long list (just the generic way the statistics code prints data).

Sigh, why dont you _ask_ before doing such stuff?

It is a terribly wide table because that makes it easily greppable

but still watchable in one chunk in a sufficiently zoomed out xterm.

Please preserve this output format

, quite some work went into it - NACK :-(

Quoted 1 line · Ingo Molnar

, quite some work went into it - NACK :-(

Considering the amount of code.. ;-) I am sorry.

But seriously, did you consider using some user space tool or script to format this stuff the way you like it - similar to the way the powertop tool reshuffles timer_stats data found in a proc file, for example?

There are roughly about 400 locks in a normal kernel for a desktop. The list is rather cumbersome anyways so, IMO, it really should be handled by parsing tools, etc... There could be more properties attached to each lock especially if you intend to get this to work on -rt which need more things reported.

Quoted 5 lines · Bill Huey (hui)

There are roughly about 400 locks in a normal kernel for a desktop. The list is rather cumbersome anyways so, IMO, it really should be handled by parsing tools, etc... There could be more properties attached to each lock especially if you intend to get this to work on -rt which need more things reported.

Adding stuff to an already wide table in a readable fashion is more difficult than making a list longer.

Do mean I might submit this stuff for -rt?

Quoted 1 line · Martin Peschke

Do mean I might submit this stuff for -rt?

Firstly, submit cleanup patches that _do not change the output_. If you have any output changes, do it as a separate patch, ontop of the cleanup patch. Mixing material changes and cleanups into a single patch is a basic patch submission mistake that will only earn you NACKs.

However, I don't understand why all of this
is so heavy weight when the current measurements that Peter makes is completely sufficient for any reasonable purpose I can think of at the moment.

What's this stuff with labels about ?

It's important to get the points of contention so that the greater kernel group can fix this issues and not log statistics for the purpose of logging it. The original purpose should not be ignore when working on this stuff.

By the way, what's the purpose of all of this stuff ? like what do you intend to do with it over the long haul ?

Firstly, submit cleanup patches that _do not change the output_. If you have any output changes, do it as a separate patch, ontop of the cleanup patch. Mixing material changes and cleanups into a single patch is a basic patch submission mistake that will only earn you NACKs.

Quoted 6 lines · Ingo Molnar

Quoted 2 lines · Martin Peschke

The output has changed from a terribly wide table to an enormously long list (just the generic way the statistics code prints data).

Sigh, why dont you _ask_ before doing such stuff?

A nice diffstat is always worth a try, isn't it?
And I see other reasons for code sharing.
Ah, and doing it has been actually quite simple once I had figured out what the original code does. :-)

Quoted 1 line

It is a terribly wide table because that makes it easily greppable

If one looks for contentions of "xtime_lock" within my enormously long list, they could issue:

grep -e "xtime_lock contentions" data

and get

xtime_lock contentions 0x17bd2 3327 account_ticks+0x96/0x184 xtime_lock contentions other 0

for example.

So how is this worse?

Quoted 21 lines · Martin Peschke

Quoted 4 lines · Ingo Molnar

Quoted 1 line · Martin Peschke

The output has changed from a terribly wide table to an enormously long list (just the generic way the statistics code prints data).

Sigh, why dont you _ask_ before doing such stuff?

A nice diffstat is always worth a try, isn't it?
And I see other reasons for code sharing.
Ah, and doing it has been actually quite simple once I had figured out what the original code does. :-)

Quoted 1 line

It is a terribly wide table because that makes it easily greppable

If one looks for contentions of "xtime_lock" within my enormously long list, they could issue:

grep -e "xtime_lock contentions" data

and get

xtime_lock contentions 0x17bd2 3327 account_ticks+0x96/0x184 xtime_lock contentions other 0

Quoted 3 lines

for example.

So how is this worse?

How will you find the 5 most contended locks with 1 grep?

It used to be:
grep ":" /proc/lock_stat | head -n 5

lock stat is more about finding who is bad than examining a particular lock (of course in the process of fixing that lock, that does become interesting).

Admittedly this gives you the top five contention points, [...]

if the infrastructure your are advocating does not allow us to keep the existing output then it's simply not flexible enough.

Why on earth are you even arguing about this?
A "cleanup" should not change the output, simple as that.
Do a patch that has the _same_ output and then we can
see whether it's a good patch. You made the same mistake with your /proc/timer_stats cleanups.

I dont like NACK-ing patches but you seem to be missing the basic precondition of cleanups: no functional effect to the code, and certainly no change in output.

- lock_time_inc() vs. statistic_add_util()

Quoted 1 line · Martin Peschke

- lock_time_inc() vs. statistic_add_util()

please fix the coding style in lib/statistic.c. It's full of:

{
        unsigned long long i;
        if (value <= stat->u.histogram.range_min)
                return 0;

put a newline after variable sections.

and:

        on_each_cpu(_statistic_barrier, NULL, 0, 1);
        return 0;

preferably use a newline before 'return' statements as well. (this is not always necessary, but in the above case it looks better)

Signed-off-by Martin Peschke <[email protected]>

---

 include/linux/lockdep.h |   35 ++---
 kernel/lockdep.c        |  122 ++-----------------
 kernel/lockdep_proc.c   |  294 +++++++-----------------------------------------
 3 files changed, 76 insertions(+), 375 deletions(-)

Index: linux/kernel/lockdep.c
===================================================================

kernel/lockdep.c +14 -0

@@ -37,6 +37,7 @@
 #include <linux/debug_locks.h>
 #include <linux/irqflags.h>
 #include <linux/utsname.h>
+#include <linux/statistic.h>
 
 #include <asm/sections.h>
 

@@ -119,93 +120,9 @@ unsigned long nr_lock_classes;
 static struct lock_class lock_classes[MAX_LOCKDEP_KEYS];
 
 #ifdef CONFIG_LOCK_STAT
 static void lock_release_holdtime(struct held_lock *hlock)
 {
+	struct statistic *stat = hlock->class->stat;
 	s64 holdtime;
 
 	if (!lock_stat)

@@ -213,12 +130,10 @@ static void lock_release_holdtime(struct
 
 	holdtime = sched_clock() - hlock->holdtime_stamp;
 
 	if (hlock->read)
+		statistic_inc(stat, LOCK_STAT_HOLD_READ, holdtime);
 	else
+		statistic_inc(stat, LOCK_STAT_HOLD_WRITE, holdtime);
 }
 #else
 static inline void lock_release_holdtime(struct held_lock *hlock)

@@ -2745,9 +2660,8 @@ __lock_contended(struct lockdep_map *loc
 {
 	struct task_struct *curr = current;
 	struct held_lock *hlock, *prev_hlock;
 	unsigned int depth;
+	int i;
 
 	depth = curr->lockdep_depth;
 	if (DEBUG_LOCKS_WARN_ON(!depth))

@@ -2761,22 +2675,15 @@ __lock_contended(struct lockdep_map *loc
 		 */
 		if (prev_hlock && prev_hlock->irq_context != hlock->irq_context)
 			break;
+		if (hlock->instance == lock) {
+			hlock->waittime_stamp = sched_clock();
+			_statistic_inc(hlock->class->stat, LOCK_STAT_CONT, ip);
+			return;
+		}
 		prev_hlock = hlock;
 	}
 	print_lock_contention_bug(curr, lock, ip);
 	return;
 }
 
 static void

@@ -2784,7 +2691,7 @@ __lock_acquired(struct lockdep_map *lock
 {
 	struct task_struct *curr = current;
 	struct held_lock *hlock, *prev_hlock;
+	struct statistic *stat;
 	unsigned int depth;
 	u64 now;
 	s64 waittime;

@@ -2817,12 +2724,11 @@ found_it:
 	waittime = now - hlock->waittime_stamp;
 	hlock->holdtime_stamp = now;
 
+	stat = hlock->class->stat;
 	if (hlock->read)
+		_statistic_inc(stat, LOCK_STAT_WAIT_READ, waittime);
 	else
+		_statistic_inc(stat, LOCK_STAT_WAIT_WRITE, waittime);
 }
 
 void lock_contended(struct lockdep_map *lock, unsigned long ip)

Index: linux/include/linux/lockdep.h
===================================================================

include/linux/lockdep.h +14 -0

@@ -17,6 +17,7 @@ struct lockdep_map;
 #include <linux/list.h>
 #include <linux/debug_locks.h>
 #include <linux/stacktrace.h>
+#include <linux/statistic.h>
 
 /*
  * Lock-class usage-state bits:

@@ -72,6 +73,17 @@ struct lock_class_key {
 	struct lockdep_subclass_key	subkeys[MAX_LOCKDEP_SUBCLASSES];
 };
 
+#ifdef CONFIG_LOCK_STAT
+enum lock_stat_enum {
+	LOCK_STAT_CONT,
+	LOCK_STAT_WAIT_READ,
+	LOCK_STAT_WAIT_WRITE,
+	LOCK_STAT_HOLD_READ,
+	LOCK_STAT_HOLD_WRITE,
+	_LOCK_STAT_NUMBER
+};
+#endif
+
 /*
  * The lock-class itself:
  */

@@ -117,30 +129,11 @@ struct lock_class {
 	int				name_version;
 
 #ifdef CONFIG_LOCK_STAT
+	struct statistic		stat[_LOCK_STAT_NUMBER];
+	struct statistic_coll		stat_coll;
 #endif
 };
 
 /*
  * Map the lock object (the lock instance) to the lock-class object.
  * This is embedded into specific lock instances:

Index: linux/kernel/lockdep_proc.c
===================================================================

kernel/lockdep_proc.c +47 -0

@@ -349,260 +349,64 @@ static const struct file_operations proc
 };
 
 #ifdef CONFIG_LOCK_STAT
+struct statistic_info lock_stat_info[_LOCK_STAT_NUMBER] = {
+	[LOCK_STAT_CONT] = {
+		.name	  = "contentions",
+		.x_unit	  = "instruction_pointer",
+		.y_unit	  = "occurrence",
+		.defaults = "type=sparse entries=4",
+		.flags	  = STATISTIC_FLAGS_LABEL,
+	},
+	[LOCK_STAT_WAIT_READ] = {
+		.name	  = "wait_read",
+		.x_unit	  = "nanoseconds",
+		.y_unit	  = "occurrence",
+		.defaults = "type=utilisation",
+	},
+	[LOCK_STAT_WAIT_WRITE] = {
+		.name	  = "wait_write",
+		.x_unit	  = "nanoseconds",
+		.y_unit	  = "occurrence",
+		.defaults = "type=utilisation",
+	},
+	[LOCK_STAT_HOLD_READ] = {
+		.name	  = "hold_read",
+		.x_unit	  = "nanoseconds",
+		.y_unit	  = "occurrence",
+		.defaults = "type=utilisation",
+	},
+	[LOCK_STAT_HOLD_WRITE] = {
+		.name	  = "hold_write",
+		.x_unit	  = "nanoseconds",
+		.y_unit	  = "occurrence",
+		.defaults = "type=utilisation",
 	}
 };
 
+struct statistic_ui lock_stat_ui;
 
+static void lock_stat_label(struct statistic_coll *coll, int i,
+			    void *key, char *buf, int size)
+{
+	sprint_symbol(buf, *(unsigned long *)key);
 }
 
+static void lock_stat_init(void)
 {
 	struct lock_class *class;
+	statistic_create(&lock_stat_ui, "lockstat");
+	list_for_each_entry(class, &all_lock_classes, lock_entry) {
+		class->stat_coll.stat = class->stat;
+		class->stat_coll.info = lock_stat_info;
+		class->stat_coll.number  = _LOCK_STAT_NUMBER;
+		class->stat_coll.label = lock_stat_label;
+		strncpy(class->stat_coll.name, class->name,
+			STATISTIC_COLL_NAME_SIZE - 1);
+		statistic_attach(&class->stat_coll, &lock_stat_ui);
 	}
 }
+#endif
 
 static int __init lockdep_proc_init(void)
 {

I'm confused as to where the class->stat objects are initialised? Is that done in lock_stat_init()? If so, then you have a bug.

Quoted 4 lines · Peter Zijlstra

Quoted 3 lines · Martin Peschke

Quoted 2 lines · Peter Zijlstra

I'm confused as to where the class->stat objects are initialised? Is that done in lock_stat_init()? If so, then you have a bug.

Quoted 8 lines

Quoted 6 lines

static struct lock_class lock_classes[MAX_LOCKDEP_KEYS];

I assume this gets us class structures containing all zeros, doesn't it? Then class->stat is zeros as well, which is handled by lib/statistics. (In this case, data gathering hasn't been turned on yet, and statistic_inc() and similar functions don't access other areas of struct statistic.)

Who eventually calls percpu_alloc?

There is a small state machine calling percpu_alloc when users do

echo state=on > /debug/statistics/lockdep/definition

So data gathering is off by default.

It might make sense to allow "state=on" as a default. Then allocation would be done in the context of statistic_attach().

Quoted 12 lines · Martin Peschke

Quoted 11 lines · Peter Zijlstra

Quoted 9 lines · Martin Peschke

Quoted 2 lines · Peter Zijlstra

I'm confused as to where the class->stat objects are initialised? Is that done in lock_stat_init()? If so, then you have a bug.

static struct lock_class lock_classes[MAX_LOCKDEP_KEYS];

I assume this gets us class structures containing all zeros, doesn't it? Then class->stat is zeros as well, which is handled by lib/statistics. (In this case, data gathering hasn't been turned on yet, and statistic_inc() and similar functions don't access other areas of struct statistic.)

Who eventually calls percpu_alloc?

Quoted 8 lines

There is a small state machine calling percpu_alloc when users do

echo state=on > /debug/statistics/lockdep/definition

So data gathering is off by default.

It might make sense to allow "state=on" as a default. Then allocation would be done in the context of statistic_attach().

Right, the problem here is that you iterate over all_lock_classes once at init.

Contrary to what the name might suggest, it are not all possible classes, just all active ones. So you'll only attach the classes which have been used up until the init point. All other classes used later will never be initialized.

Quoted 25 lines · Peter Zijlstra

Quoted 12 lines · Martin Peschke

Quoted 11 lines · Peter Zijlstra

Quoted 9 lines · Martin Peschke

Quoted 2 lines · Peter Zijlstra

I'm confused as to where the class->stat objects are initialised? Is that done in lock_stat_init()? If so, then you have a bug.

static struct lock_class lock_classes[MAX_LOCKDEP_KEYS];

I assume this gets us class structures containing all zeros, doesn't it? Then class->stat is zeros as well, which is handled by lib/statistics. (In this case, data gathering hasn't been turned on yet, and statistic_inc() and similar functions don't access other areas of struct statistic.)

Who eventually calls percpu_alloc?

Quoted 8 lines

There is a small state machine calling percpu_alloc when users do

echo state=on > /debug/statistics/lockdep/definition

So data gathering is off by default.

It might make sense to allow "state=on" as a default. Then allocation would be done in the context of statistic_attach().

Right, the problem here is that you iterate over all_lock_classes once at init.

Quoted 4 lines

Contrary to what the name might suggest, it are not all possible classes, just all active ones. So you'll only attach the classes which have been used up until the init point. All other classes used later will never be initialized.

Ah..

Do you know where a class is setup for first use?

I guess it is feasible to move statistic initialisation to that place.

Is there a place where a class becomes unused again?

Quoted 22 lines · Martin Peschke

Quoted 21 lines · Peter Zijlstra

Quoted 20 lines · Martin Peschke

Quoted 11 lines · Peter Zijlstra

Quoted 9 lines · Martin Peschke

Quoted 2 lines · Peter Zijlstra

I'm confused as to where the class->stat objects are initialised? Is that done in lock_stat_init()? If so, then you have a bug.

static struct lock_class lock_classes[MAX_LOCKDEP_KEYS];

I assume this gets us class structures containing all zeros, doesn't it? Then class->stat is zeros as well, which is handled by lib/statistics. (In this case, data gathering hasn't been turned on yet, and statistic_inc() and similar functions don't access other areas of struct statistic.)

Who eventually calls percpu_alloc?

There is a small state machine calling percpu_alloc when users do

echo state=on > /debug/statistics/lockdep/definition

So data gathering is off by default.

It might make sense to allow "state=on" as a default. Then allocation would be done in the context of statistic_attach().

Quoted 7 lines

Quoted 7 lines

Right, the problem here is that you iterate over all_lock_classes once at init.

Contrary to what the name might suggest, it are not all possible classes, just all active ones. So you'll only attach the classes which have been used up until the init point. All other classes used later will never be initialized.

kernel/lockdep_proc.c +23 -0

+struct statistic_info lock_stat_info[_LOCK_STAT_NUMBER] = {
+	[LOCK_STAT_CONT] = {
+		.name	  = "contentions",
+		.x_unit	  = "instruction_pointer",
+		.y_unit	  = "occurrence",
+		.defaults = "type=sparse entries=4",
+		.flags	  = STATISTIC_FLAGS_LABEL,
+	},
+	[LOCK_STAT_WAIT_READ] = {
+		.name	  = "wait_read",
+		.x_unit	  = "nanoseconds",
+		.y_unit	  = "occurrence",
+		.defaults = "type=utilisation",
+	},
+	[LOCK_STAT_WAIT_WRITE] = {
+		.name	  = "wait_write",
+		.x_unit	  = "nanoseconds",
+		.y_unit	  = "occurrence",
+		.defaults = "type=utilisation",
+	},
+	[LOCK_STAT_HOLD_READ] = {
+		.name	  = "hold_read",
+		.x_unit	  = "nanoseconds",

Quoted 27 lines · Martin Peschke

kernel/lockdep_proc.c +27 -0

+struct statistic_info lock_stat_info[_LOCK_STAT_NUMBER] = {
+	[LOCK_STAT_CONT] = {
+		.name	  = "contentions",
+		.x_unit	  = "instruction_pointer",
+		.y_unit	  = "occurrence",
+		.defaults = "type=sparse entries=4",
+		.flags	  = STATISTIC_FLAGS_LABEL,
+	},
+	[LOCK_STAT_WAIT_READ] = {
+		.name	  = "wait_read",
+		.x_unit	  = "nanoseconds",
+		.y_unit	  = "occurrence",
+		.defaults = "type=utilisation",
+	},
+	[LOCK_STAT_WAIT_WRITE] = {
+		.name	  = "wait_write",
+		.x_unit	  = "nanoseconds",
+		.y_unit	  = "occurrence",
+		.defaults = "type=utilisation",
+	},
+	[LOCK_STAT_HOLD_READ] = {
+		.name	  = "hold_read",
+		.x_unit	  = "nanoseconds",
+		.y_unit	  = "occurrence",
+		.defaults = "type=utilisation",
+	},
+	[LOCK_STAT_HOLD_WRITE] = {

kernel/lockdep_proc.c static const struct file_operations proc

Quoted 6 lines

kernel/lockdep_proc.c +4 -0

+		.name	  = "hold_write",
+		.x_unit	  = "nanoseconds",
+		.y_unit	  = "occurrence",
+		.defaults = "type=utilisation",
 	}
 };

You're parsing strings in-kernel to setup data structures?

include/linux/lockdep.h +11 -0

+#ifdef CONFIG_LOCK_STAT
+enum lock_stat_enum {
+	LOCK_STAT_CONT,
+	LOCK_STAT_WAIT_READ,
+	LOCK_STAT_WAIT_WRITE,
+	LOCK_STAT_HOLD_READ,
+	LOCK_STAT_HOLD_WRITE,
+	_LOCK_STAT_NUMBER
+};
+#endif
+
 /*
  * The lock-class itself:
  */

we have around 1400 locks in the kernel, this would give 414400 per cpu.

vs the old code:

2048*(4*8) = 65536
+
2048*(4*4*8 + 4*8) = 327680 per cpu

worst case

I'm not convinced 300 lines less code is worth that extra bloat.

Quoted 15 lines · Martin Peschke

include/linux/lockdep.h +11 -0

+#ifdef CONFIG_LOCK_STAT
+enum lock_stat_enum {
+	LOCK_STAT_CONT,
+	LOCK_STAT_WAIT_READ,
+	LOCK_STAT_WAIT_WRITE,
+	LOCK_STAT_HOLD_READ,
+	LOCK_STAT_HOLD_WRITE,
+	_LOCK_STAT_NUMBER
+};
+#endif
+
 /*
  * The lock-class itself:
  */

include/linux/lockdep.h struct lock_class { · line 135

Quoted 8 lines

include/linux/lockdep.h +2 -1

@@ -117,30 +129,11 @@ struct lock_class {
 	int				name_version;
 
 #ifdef CONFIG_LOCK_STAT
-	unsigned long			contention_point[4];
+	struct statistic		stat[_LOCK_STAT_NUMBER];
+	struct statistic_coll		stat_coll;
 #endif
 };

sizeof(struct statistic_coll) = 16+64+8+8+4+8+8 = 116 sizeof(struct statistic) = 4+4+8+8+8+8+8+4+8+4+4 = 68
+ 8*NR_CPUS
+ kmalloc_size(obj)*nr_cpu_ids

4 objs with size 40, gives 4*64 = 256 * nr_cpu_ids

1 obj with size 32 + more

for 2048 total classes this gives:

2048 * (116+68) = 376832

for each active class this adds per cpu:

8+256+32+some = 296+

we have around 1400 locks in the kernel, this would give 414400 per cpu.

vs the old code:

2048*(4*8) = 65536
+
2048*(4*4*8 + 4*8) = 327680 per cpu

worst case

I'm not convinced 300 lines less code is worth that extra bloat.