Allow inlined spinlocks again V3

Hi Andrew,

since there were no objections to this patch set, would you mind picking it up for -mm? The patches are against current Linus' git head but also apply on top of the latest mmotm patch set.

===

This patch set allows to have inlined spinlocks again.

The rationale behind this is that function calls on at least s390 are expensive.

If one considers that server kernels are usually compiled with !CONFIG_PREEMPT a simple spin_lock is just a compare and swap loop. The extra overhead for a function call is significant.
With inlined spinlocks overall cpu usage gets reduced by 1%-5% on s390. These numbers were taken with some network benchmarks. However I expect any workload that calls frequently into the kernel and which grabs a few locks to perform better.

The implementation is straight forward: move the function bodies of the locking functions to static inline functions and place them in a header file.
Dependent on CONFIG_SPINLOCK_INLINE generate out-of-line or inlined locking functions.

The patches should be self explaining.

V2: rewritten from scratch - now also with readable code

V3: removed macro to generate out-of-line spinlock variants since that
would break ctags. As requested by Arnd Bergmann.

From: Heiko Carstens <[email protected]>

Move spinlock function bodies to header file by creating a static inline version of each variant.
Use the inline version on the out-of-line code. This shouldn't make any difference besides that the spinlock code can now be used to generate inlined spinlock code.

---
 include/linux/spinlock.h         |   18 +-
 include/linux/spinlock_api_smp.h |  263 +++++++++++++++++++++++++++++++++++++++
 kernel/spinlock.c                |  174 ++++---------------------
 3 files changed, 300 insertions(+), 155 deletions(-)

Index: linux-2.6/include/linux/spinlock_api_smp.h
===================================================================
@@ -60,4 +60,267 @@ void __lockfunc _read_unlock_irqrestore(
 void __lockfunc _write_unlock_irqrestore(rwlock_t *lock, unsigned long flags)
 							__releases(lock);
 
+static inline int __spin_trylock(spinlock_t *lock)
+{
+	preempt_disable();
+	if (_raw_spin_trylock(lock)) {
+		spin_acquire(&lock->dep_map, 0, 1, _RET_IP_);
+		return 1;
+	}
+	preempt_enable();
+	return 0;
+}
+
+static inline int __read_trylock(rwlock_t *lock)
+{
+	preempt_disable();
+	if (_raw_read_trylock(lock)) {
+		rwlock_acquire_read(&lock->dep_map, 0, 1, _RET_IP_);
+		return 1;
+	}
+	preempt_enable();
+	return 0;
+}
+
+static inline int __write_trylock(rwlock_t *lock)
+{
+	preempt_disable();
+	if (_raw_write_trylock(lock)) {
+		rwlock_acquire(&lock->dep_map, 0, 1, _RET_IP_);
+		return 1;
+	}
+	preempt_enable();
+	return 0;
+}
+
+/*
+ * If lockdep is enabled then we use the non-preemption spin-ops
+ * even on CONFIG_PREEMPT, because lockdep assumes that interrupts are
+ * not re-enabled during lock-acquire (which the preempt-spin-ops do):
+ */
+#if !defined(CONFIG_GENERIC_LOCKBREAK) || defined(CONFIG_DEBUG_LOCK_ALLOC)
+
+static inline void __read_lock(rwlock_t *lock)
+{
+	preempt_disable();
+	rwlock_acquire_read(&lock->dep_map, 0, 0, _RET_IP_);
+	LOCK_CONTENDED(lock, _raw_read_trylock, _raw_read_lock);
+}
+
+static inline unsigned long __spin_lock_irqsave(spinlock_t *lock)
+{
+	unsigned long flags;
+
+	local_irq_save(flags);
+	preempt_disable();
+	spin_acquire(&lock->dep_map, 0, 0, _RET_IP_);
+	/*
+	 * On lockdep we dont want the hand-coded irq-enable of
+	 * _raw_spin_lock_flags() code, because lockdep assumes
+	 * that interrupts are not re-enabled during lock-acquire:
+	 */
+#ifdef CONFIG_LOCKDEP
+	LOCK_CONTENDED(lock, _raw_spin_trylock, _raw_spin_lock);
+#else
+	_raw_spin_lock_flags(lock, &flags);
+#endif
+	return flags;
+}
+
+static inline void __spin_lock_irq(spinlock_t *lock)
+{
+	local_irq_disable();
+	preempt_disable();
+	spin_acquire(&lock->dep_map, 0, 0, _RET_IP_);
+	LOCK_CONTENDED(lock, _raw_spin_trylock, _raw_spin_lock);
+}
+
+static inline void __spin_lock_bh(spinlock_t *lock)
+{
+	local_bh_disable();
+	preempt_disable();
+	spin_acquire(&lock->dep_map, 0, 0, _RET_IP_);
+	LOCK_CONTENDED(lock, _raw_spin_trylock, _raw_spin_lock);
+}
+
+static inline unsigned long __read_lock_irqsave(rwlock_t *lock)
+{
+	unsigned long flags;
+
+	local_irq_save(flags);
+	preempt_disable();
+	rwlock_acquire_read(&lock->dep_map, 0, 0, _RET_IP_);
+	LOCK_CONTENDED_FLAGS(lock, _raw_read_trylock, _raw_read_lock,
+			     _raw_read_lock_flags, &flags);
+	return flags;
+}
+
+static inline void __read_lock_irq(rwlock_t *lock)
+{
+	local_irq_disable();
+	preempt_disable();
+	rwlock_acquire_read(&lock->dep_map, 0, 0, _RET_IP_);
+	LOCK_CONTENDED(lock, _raw_read_trylock, _raw_read_lock);
+}
+
+static inline void __read_lock_bh(rwlock_t *lock)
+{
+	local_bh_disable();
+	preempt_disable();
+	rwlock_acquire_read(&lock->dep_map, 0, 0, _RET_IP_);
+	LOCK_CONTENDED(lock, _raw_read_trylock, _raw_read_lock);
+}
+
+static inline unsigned long __write_lock_irqsave(rwlock_t *lock)
+{
+	unsigned long flags;
+
+	local_irq_save(flags);
+	preempt_disable();
+	rwlock_acquire(&lock->dep_map, 0, 0, _RET_IP_);
+	LOCK_CONTENDED_FLAGS(lock, _raw_write_trylock, _raw_write_lock,
+			     _raw_write_lock_flags, &flags);
+	return flags;
+}
+
+static inline void __write_lock_irq(rwlock_t *lock)
+{
+	local_irq_disable();
+	preempt_disable();
+	rwlock_acquire(&lock->dep_map, 0, 0, _RET_IP_);
+	LOCK_CONTENDED(lock, _raw_write_trylock, _raw_write_lock);
+}
+
+static inline void __write_lock_bh(rwlock_t *lock)
+{
+	local_bh_disable();
+	preempt_disable();
+	rwlock_acquire(&lock->dep_map, 0, 0, _RET_IP_);
+	LOCK_CONTENDED(lock, _raw_write_trylock, _raw_write_lock);
+}
+
+static inline void __spin_lock(spinlock_t *lock)
+{
+	preempt_disable();
+	spin_acquire(&lock->dep_map, 0, 0, _RET_IP_);
+	LOCK_CONTENDED(lock, _raw_spin_trylock, _raw_spin_lock);
+}
+
+static inline void __write_lock(rwlock_t *lock)
+{
+	preempt_disable();
+	rwlock_acquire(&lock->dep_map, 0, 0, _RET_IP_);
+	LOCK_CONTENDED(lock, _raw_write_trylock, _raw_write_lock);
+}
+
+#endif /* CONFIG_PREEMPT */
+
+static inline void __spin_unlock(spinlock_t *lock)
+{
+	spin_release(&lock->dep_map, 1, _RET_IP_);
+	_raw_spin_unlock(lock);
+	preempt_enable();
+}
+
+static inline void __write_unlock(rwlock_t *lock)
+{
+	rwlock_release(&lock->dep_map, 1, _RET_IP_);
+	_raw_write_unlock(lock);
+	preempt_enable();
+}
+
+static inline void __read_unlock(rwlock_t *lock)
+{
+	rwlock_release(&lock->dep_map, 1, _RET_IP_);
+	_raw_read_unlock(lock);
+	preempt_enable();
+}
+
+static inline void __spin_unlock_irqrestore(spinlock_t *lock,
+					    unsigned long flags)
+{
+	spin_release(&lock->dep_map, 1, _RET_IP_);
+	_raw_spin_unlock(lock);
+	local_irq_restore(flags);
+	preempt_enable();
+}
+
+static inline void __spin_unlock_irq(spinlock_t *lock)
+{
+	spin_release(&lock->dep_map, 1, _RET_IP_);
+	_raw_spin_unlock(lock);
+	local_irq_enable();
+	preempt_enable();
+}
+
+static inline void __spin_unlock_bh(spinlock_t *lock)
+{
+	spin_release(&lock->dep_map, 1, _RET_IP_);
+	_raw_spin_unlock(lock);
+	preempt_enable_no_resched();
+	local_bh_enable_ip((unsigned long)__builtin_return_address(0));
+}
+
+static inline void __read_unlock_irqrestore(rwlock_t *lock, unsigned long flags)
+{
+	rwlock_release(&lock->dep_map, 1, _RET_IP_);
+	_raw_read_unlock(lock);
+	local_irq_restore(flags);
+	preempt_enable();
+}
+
+static inline void __read_unlock_irq(rwlock_t *lock)
+{
+	rwlock_release(&lock->dep_map, 1, _RET_IP_);
+	_raw_read_unlock(lock);
+	local_irq_enable();
+	preempt_enable();
+}
+
+static inline void __read_unlock_bh(rwlock_t *lock)
+{
+	rwlock_release(&lock->dep_map, 1, _RET_IP_);
+	_raw_read_unlock(lock);
+	preempt_enable_no_resched();
+	local_bh_enable_ip((unsigned long)__builtin_return_address(0));
+}
+
+static inline void __write_unlock_irqrestore(rwlock_t *lock,
+					     unsigned long flags)
+{
+	rwlock_release(&lock->dep_map, 1, _RET_IP_);
+	_raw_write_unlock(lock);
+	local_irq_restore(flags);
+	preempt_enable();
+}
+
+static inline void __write_unlock_irq(rwlock_t *lock)
+{
+	rwlock_release(&lock->dep_map, 1, _RET_IP_);
+	_raw_write_unlock(lock);
+	local_irq_enable();
+	preempt_enable();
+}
+
+static inline void __write_unlock_bh(rwlock_t *lock)
+{
+	rwlock_release(&lock->dep_map, 1, _RET_IP_);
+	_raw_write_unlock(lock);
+	preempt_enable_no_resched();
+	local_bh_enable_ip((unsigned long)__builtin_return_address(0));
+}
+
+static inline int __spin_trylock_bh(spinlock_t *lock)
+{
+	local_bh_disable();
+	preempt_disable();
+	if (_raw_spin_trylock(lock)) {
+		spin_acquire(&lock->dep_map, 0, 1, _RET_IP_);
+		return 1;
+	}
+	preempt_enable_no_resched();
+	local_bh_enable_ip((unsigned long)__builtin_return_address(0));
+	return 0;
+}
+
 #endif /* __LINUX_SPINLOCK_API_SMP_H */

Index: linux-2.6/include/linux/spinlock.h
===================================================================
@@ -143,15 +143,6 @@ static inline void smp_mb__after_lock(vo
  */
 #define spin_unlock_wait(lock)	__raw_spin_unlock_wait(&(lock)->raw_lock)
 
-/*
- * Pull the _spin_*()/_read_*()/_write_*() functions/declarations:
- */
-#if defined(CONFIG_SMP) || defined(CONFIG_DEBUG_SPINLOCK)
-# include <linux/spinlock_api_smp.h>
-#else
-# include <linux/spinlock_api_up.h>
-#endif
-
 #ifdef CONFIG_DEBUG_SPINLOCK
  extern void _raw_spin_lock(spinlock_t *lock);
 #define _raw_spin_lock_flags(lock, flags) _raw_spin_lock(lock)

@@ -380,4 +371,13 @@ extern int _atomic_dec_and_lock(atomic_t
  */
 #define spin_can_lock(lock)	(!spin_is_locked(lock))
 
+/*
+ * Pull the _spin_*()/_read_*()/_write_*() functions/declarations:
+ */
+#if defined(CONFIG_SMP) || defined(CONFIG_DEBUG_SPINLOCK)
+# include <linux/spinlock_api_smp.h>
+#else
+# include <linux/spinlock_api_up.h>
+#endif
+
 #endif /* __LINUX_SPINLOCK_H */

From: Heiko Carstens <[email protected]>

Add new config option SPINLOCK_INLINE and some defines which depend on it in order to generate inlined spinlock code instead of out-of-line code.
Avoiding function calls for spinlocks gives 1%-5% less cpu usage on network benchmarks on s390.

Architectures must select HAVE_SPINLOCK_INLINE_SUPPORT to enable this config option.

---
 include/linux/spinlock_api_smp.h |   35 +++++++++++++++++++++++++++++++++++
 kernel/spinlock.c                |    4 ++++
 lib/Kconfig.debug                |   14 ++++++++++++++
 3 files changed, 53 insertions(+)

Index: linux-2.6/include/linux/spinlock_api_smp.h
===================================================================
@@ -19,6 +19,8 @@ int in_lock_functions(unsigned long addr
 
 #define assert_spin_locked(x)	BUG_ON(!spin_is_locked(x))
 
+#ifndef CONFIG_SPINLOCK_INLINE
+
 void __lockfunc _spin_lock(spinlock_t *lock)		__acquires(lock);
 void __lockfunc _spin_lock_nested(spinlock_t *lock, int subclass)
 							__acquires(lock);

@@ -60,6 +62,39 @@ void __lockfunc _read_unlock_irqrestore(
 void __lockfunc _write_unlock_irqrestore(rwlock_t *lock, unsigned long flags)
 							__releases(lock);
 
+#else /* CONFIG_HAVE_SPINLOCK_INLINE_SUPPORT */
+
+#define _spin_trylock(lock)	  __spin_trylock(lock)
+#define _read_trylock(lock)	  __read_trylock(lock)
+#define _write_trylock(lock)	  __write_trylock(lock)
+#define _read_lock(lock)	  __read_lock(lock)
+#define _spin_lock_irqsave(lock)  __spin_lock_irqsave(lock)
+#define _spin_lock_irq(lock)	  __spin_lock_irq(lock)
+#define _spin_lock_bh(lock)	  __spin_lock_bh(lock)
+#define _read_lock_irqsave(lock)  __read_lock_irqsave(lock)
+#define _read_lock_irq(lock)	  __read_lock_irq(lock)
+#define _read_lock_bh(lock)	  __read_lock_bh(lock)
+#define _write_lock_irqsave(lock) __write_lock_irqsave(lock)
+#define _write_lock_irq(lock)	  __write_lock_irq(lock)
+#define _write_lock_bh(lock)	  __write_lock_bh(lock)
+#define _spin_lock(lock)	  __spin_lock(lock)
+#define _write_lock(lock)	  __write_lock(lock)
+#define _spin_unlock(lock)	  __spin_unlock(lock)
+#define _write_unlock(lock)	  __write_unlock(lock)
+#define _read_unlock(lock)	  __read_unlock(lock)
+#define _spin_unlock_irq(lock)	  __spin_unlock_irq(lock)
+#define _spin_unlock_bh(lock)	  __spin_unlock_bh(lock)
+#define _read_unlock_irq(lock)	  __read_unlock_irq(lock)
+#define _read_unlock_bh(lock)	  __read_unlock_bh(lock)
+#define _write_unlock_irq(lock)	  __write_unlock_irq(lock)
+#define _write_unlock_bh(lock)	  __write_unlock_bh(lock)
+#define _spin_trylock_bh(lock)	  __spin_trylock_bh(lock)
+#define _spin_unlock_irqrestore(lock, flags)  __spin_unlock_irqrestore(lock, flags)
+#define _read_unlock_irqrestore(lock, flags)  __read_unlock_irqrestore(lock, flags)
+#define _write_unlock_irqrestore(lock, flags) __write_unlock_irqrestore(lock, flags)
+
+#endif /* CONFIG_HAVE_SPINLOCK_INLINE_SUPPORT */
+
 static inline int __spin_trylock(spinlock_t *lock)
 {
 	preempt_disable();

Index: linux-2.6/lib/Kconfig.debug
===================================================================
@@ -879,6 +879,20 @@ config SYSCTL_SYSCALL_CHECK
 	  to properly maintain and use. This enables checks that help
 	  you to keep things correct.
 
+config HAVE_SPINLOCK_INLINE_SUPPORT
+	bool
+
+config SPINLOCK_INLINE
+	bool "Inline spinlock code"
+	depends on HAVE_SPINLOCK_INLINE_SUPPORT
+	depends on !DEBUG_SPINLOCK
+	depends on SMP && !PREEMPT
+	help
+	  Select this option if you want to have inlined spinlock code instead
+	  of an out of line implementation.
+	  This will generate a larger kernel image. On some architectures this
+	  increases performance.
+
 source mm/Kconfig.debug
 source kernel/trace/Kconfig
 

Index: linux-2.6/kernel/spinlock.c
===================================================================
@@ -21,6 +21,8 @@
 #include <linux/debug_locks.h>
 #include <linux/module.h>
 
+#ifndef CONFIG_SPINLOCK_INLINE
+
 int __lockfunc _spin_trylock(spinlock_t *lock)
 {
 	return __spin_trylock(lock);

@@ -320,6 +322,8 @@ int __lockfunc _spin_trylock_bh(spinlock
 }
 EXPORT_SYMBOL(_spin_trylock_bh);
 
+#endif /* CONFIG_HAVE_SPINLOCK_INLINE_SUPPORT */
+
 notrace int in_lock_functions(unsigned long addr)
 {
 	/* Linker adds these: start and end of __lockfunc functions */

From: Heiko Carstens <[email protected]>

---
 arch/s390/Kconfig |    1 +
 1 file changed, 1 insertion(+)

Index: linux-2.6/arch/s390/Kconfig
===================================================================
@@ -93,6 +93,7 @@ config S390
 	select HAVE_KRETPROBES
 	select HAVE_KVM if 64BIT
 	select HAVE_ARCH_TRACEHOOK
+	select HAVE_SPINLOCK_INLINE_SUPPORT
 	select INIT_ALL_POSSIBLE
 	select HAVE_PERF_COUNTERS
 	select GENERIC_ATOMIC64 if !64BIT

I'm not convinced this is the right approach.

The thing is, CONFIG_SPINLOCK_INLINE doesn't look like the right thing to do. On x86, for example, functions calls are usually quite cheap, and it may well make sense to keep 'spin_lock()' out-of-line, especially once you start doing things like playing with the softirq counts or interrupts.

At the same time, the special case of spin *unlock* is generally just a single (small) instruction on x86, so that one almost certainly is worth inlining - at least as long as it's not one of the softirq ones.

In other words, I think your hammer is too large. If you want to inline the lock functions, you should _not_ make this a single "everything or nothing" thing.

Have you tried to determine which kinds of spinlocks you care most about? With networking, I guess the softirq-safe ones (and perhaps the irq ones) are pretty common, but maybe even there it's really just a couple of cases.

Now, there is one advantage to inlining that I really like - and that I personally have missed from the days when we used to always do it:
profiling. Inlining the spinlocks tends to do _wonders_ for showing exactly which spinlock ends up being the contention cases for certain loads.

So there are advantages outside of the "size vs speed" kind of things, but at the same time I do suspect that the disadvantages mean that we really should make this be something where an architecture can specify things at a finer granularity. Perhaps by using per-symbol defines (ie have the <asm/spinlock.h> file do things like

	#define __spin_lock_is_small
	#define __spin_unlock_is_small

kind of things for the particular sequences that are worth inlining.

Linus

We've got a new tool to determine that kind of information though:
perf + call-graph profiling.

This is how it works and how it can be used. Say we want to profile 'bw_tcp' from lmbench. The traditional way is to record a flat profile:

aldebaran:~/l> perf record -f ./bw_pipe
Pipe bandwidth: 4607.33 MB/sec
[ perf record: Captured and wrote 2.503 MB perf.data (~109368 samples) ]

and then to view the flat profile:

aldebaran:~/l> perf report
# Samples: 109331
#

 # Overhead  Command             Shared Object  Symbol
 # ........  .......  ........................  ......
 #
    39.61%  bw_pipe  [kernel]                  [k] copy_user_generic_string
    19.32%  bw_pipe  ./bw_pipe                 [.] enough_duration
     6.21%  bw_pipe  [kernel]                  [k] mutex_spin_on_owner
     3.54%  bw_pipe  ./bw_pipe                 [.] two_op
     3.54%  bw_pipe  ./bw_pipe                 [.] one_op
     2.79%  bw_pipe  [kernel]                  [k] get_page_from_freelist
     2.16%  bw_pipe  [kernel]                  [k] ia32_sysenter_target
     1.91%  bw_pipe  [kernel]                  [k] pipe_read
     1.83%  bw_pipe  [kernel]                  [k] pipe_write
     1.63%  bw_pipe  [kernel]                  [k] free_hot_cold_page
     1.21%  bw_pipe  [kernel]                  [k] put_page
     1.19%  bw_pipe  [kernel]                  [k] __alloc_pages_nodemask
     0.99%  bw_pipe  [kernel]                  [k] anon_pipe_buf_release
     0.74%  bw_pipe  [kernel]                  [k] get_pageblock_flags_group

Annoyingly enough, mutex_spin_on_owner() is in the profile but we have no idea what the parent function(s) are. (Plus there's no way we could reasonably inline mutex functions.) So we are stuck with guessing which of the many other functions above (or some other function which does not even get listed!) has that mutex spinning overhead.

But if you do the recording via call-graph traces:

aldebaran:~/l> perf record -g -f ./bw_pipe
Pipe bandwidth: 4432.75 MB/sec
[ perf record: Captured and wrote 7.550 MB perf.data (~329886 samples) ]

(note the -g/--graph option) And then view the profile via perf report, we get:

aldebaran:~/l> perf report -S _spin_lock

# symbol: _spin_lock
# Samples: 724
#
# Overhead Command Shared Object

 # ........  .......  ........................
 #
    98.34%  lat_tcp  [kernel]                
                |          
                |--31.74%-- ipt_do_table
                |          |          
                |          |--26.99%-- ipt_local_in_hook
                |          |          nf_iterate
                |          |          nf_hook_slow
                |          |          ip_local_deliver
                |          |          ip_rcv_finish
                |          |          ip_rcv
                |          |          netif_receive_skb
                |          |          process_backlog
                |          |          net_rx_action
                |          |          __do_softirq
                |          |          call_softirq
                |          |          do_softirq
                |          |          _local_bh_enable_ip
                |          |          local_bh_enable
                |          |          dev_queue_xmit
                |          |          ip_finish_output2
                |          |          ip_finish_output
                |          |          ip_output
                |          |          ip_local_out
                |          |          ip_queue_xmit
                |          |          tcp_transmit_skb
                |          |          tcp_write_xmit
                |          |          __tcp_push_pending_frames
                |          |          tcp_push
                |          |          tcp_sendmsg
                |          |          __sock_sendmsg
                |          |          sock_aio_write
                |          |          do_sync_write
                |          |          vfs_write
                |          |          sys_write
                |          |          sysenter_dispatch
                |          |          0xf7f50430
                |          |          0x5
                |          |          
                |          |--24.34%-- ipt_local_in_hook
                |          |          nf_iterate
                |          |          nf_hook_slow
                |          |          ip_local_deliver
                |          |          ip_rcv_finish
                |          |          ip_rcv
                |          |          netif_receive_skb
                |          |          process_backlog
                |          |          net_rx_action
                |          |          __do_softirq
                |          |          call_softirq
                |          |          do_softirq
                |          |          _local_bh_enable_ip
                |          |          local_bh_enable
                |          |          dev_queue_xmit
                |          |          ip_finish_output2
                |          |          ip_finish_output
                |          |          ip_output
                |          |          ip_local_out
                |          |          ip_queue_xmit
                |          |          tcp_transmit_skb
                |          |          tcp_write_xmit
                |          |          __tcp_push_pending_frames
                |          |          tcp_push
                |          |          tcp_sendmsg
                |          |          __sock_sendmsg
                |          |          sock_aio_write
                |          |          do_sync_write
                |          |          vfs_write
                |          |          sys_write
                |          |          sysenter_dispatch
                |          |          0xf7f50430
                |          |          0x5
                |          |          
                |          |--16.81%-- ipt_pre_routing_hook
                |          |          nf_iterate
                |          |          nf_hook_slow
                |          |          ip_rcv
                |          |          netif_receive_skb
                |          |          process_backlog
                |          |          net_rx_action
                |          |          __do_softirq
                |          |          call_softirq
                |          |          do_softirq
                |          |          _local_bh_enable_ip
                |          |          local_bh_enable
                |          |          dev_queue_xmit
                |          |          ip_finish_output2
                |          |          ip_finish_output
                |          |          ip_output
                |          |          ip_local_out
                |          |          ip_queue_xmit
                |          |          tcp_transmit_skb
                |          |          tcp_write_xmit
                |          |          __tcp_push_pending_frames
                |          |          tcp_push
                |          |          tcp_sendmsg
                |          |          __sock_sendmsg
                |          |          sock_aio_write
                |          |          do_sync_write
                |          |          vfs_write
                |          |          sys_write
                |          |          sysenter_dispatch
                |          |          0xf7f50430
                |          |          0x5
                |          |          
                |          |--11.95%-- ipt_post_routing_hook
                |          |          nf_iterate
                |          |          nf_hook_slow
                |          |          ip_output
                |          |          ip_local_out
                |          |          ip_queue_xmit
                |          |          tcp_transmit_skb
                |          |          tcp_write_xmit
                |          |          __tcp_push_pending_frames
                |          |          tcp_push
                |          |          tcp_sendmsg
                |          |          __sock_sendmsg
                |          |          sock_aio_write
                |          |          do_sync_write
                |          |          vfs_write
                |          |          sys_write
                |          |          sysenter_dispatch
                |          |          0xf7f50430
                |          |          0x5
                |          |          
                |          |--10.18%-- ipt_local_out_hook
                |          |          nf_iterate
                |          |          nf_hook_slow
                |          |          __ip_local_out
                |          |          ip_local_out
                |          |          ip_queue_xmit
                |          |          tcp_transmit_skb
                |          |          tcp_write_xmit
                |          |          __tcp_push_pending_frames
                |          |          tcp_push
                |          |          tcp_sendmsg
                |          |          __sock_sendmsg
                |          |          sock_aio_write
                |          |          do_sync_write
                |          |          vfs_write
                |          |          sys_write
                |          |          sysenter_dispatch
                |          |          0xf7f50430
                |          |          0x5
                |          |          
                |           --9.73%-- ipt_local_hook
                |                     nf_iterate
                |                     nf_hook_slow
                |                     __ip_local_out
                |                     ip_local_out
                |                     ip_queue_xmit
                |                     tcp_transmit_skb
                |                     tcp_write_xmit
                |                     __tcp_push_pending_frames
                |                     tcp_push
                |                     tcp_sendmsg
                |                     __sock_sendmsg
                |                     sock_aio_write
                |                     do_sync_write
                |                     vfs_write
                |                     sys_write
                |                     sysenter_dispatch
                |                     0xf7f50430
                |                     0x5
                |          
                |--31.46%-- __mod_timer
                |          mod_timer
                |          sk_reset_timer
                |          |          
                |          |--55.36%-- tcp_send_delayed_ack
                |          |          __tcp_ack_snd_check
                |          |          tcp_rcv_established
                |          |          tcp_v4_do_rcv
                |          |          tcp_prequeue_process
                |          |          tcp_recvmsg
                |          |          sock_common_recvmsg
                |          |          __sock_recvmsg
                |          |          sock_aio_read
                |          |          do_sync_read
                |          |          vfs_read
                |          |          sys_read
                |          |          sysenter_dispatch
                |          |          0xf7f50430
                |          |          0x5
                |          |          
                |           --44.64%-- tcp_v4_rcv
                |                     ip_local_deliver_finish
                |                     ip_local_deliver
                |                     ip_rcv_finish
                |                     ip_rcv
                |                     netif_receive_skb
                |                     process_backlog
                |                     net_rx_action
                |                     __do_softirq
                |                     call_softirq
                |                     do_softirq
                |                     _local_bh_enable_ip
                |                     local_bh_enable
                |                     dev_queue_xmit
                |                     ip_finish_output2
                |                     ip_finish_output
                |                     ip_output
                |                     ip_local_out
                |                     ip_queue_xmit
                |                     tcp_transmit_skb
                |                     tcp_write_xmit
                |                     __tcp_push_pending_frames
                |                     tcp_push
                |                     tcp_sendmsg
                |                     __sock_sendmsg
                |                     sock_aio_write
                |                     do_sync_write
                |                     vfs_write
                |                     sys_write
                |                     sysenter_dispatch
                |                     0xf7f50430
                |                     0x5
                |          
                |--21.21%-- task_rq_lock
                |          try_to_wake_up
                |          default_wake_function
                |          |          
                |          |--99.34%-- autoremove_wake_function
                |          |          __wake_up_common
                |          |          __wake_up
                |          |          tcp_v4_rcv
                |          |          ip_local_deliver_finish
                |          |          ip_local_deliver
                |          |          ip_rcv_finish
                |          |          ip_rcv
                |          |          netif_receive_skb
                |          |          process_backlog
                |          |          net_rx_action
                |          |          __do_softirq
                |          |          call_softirq
                |          |          do_softirq
                |          |          _local_bh_enable_ip
                |          |          local_bh_enable
                |          |          dev_queue_xmit
                |          |          ip_finish_output2
                |          |          ip_finish_output
                |          |          ip_output
                |          |          ip_local_out
                |          |          ip_queue_xmit
                |          |          tcp_transmit_skb
                |          |          tcp_write_xmit
                |          |          __tcp_push_pending_frames
                |          |          tcp_push
                |          |          tcp_sendmsg
                |          |          __sock_sendmsg
                |          |          sock_aio_write
                |          |          do_sync_write
                |          |          vfs_write
                |          |          sys_write
                |          |          sysenter_dispatch
                |          |          0xf7f50430
                |          |          0x5
                |          |          
                |           --0.66%-- pollwake
                |                     __wake_up_common
                |                     __wake_up
                |                     perf_counter_wakeup
                |                     perf_pending_counter
                |                     perf_counter_do_pending
                |                     smp_perf_pending_interrupt
                |                     perf_pending_interrupt
                |                     0xf7f50430
                |                     0x5
                |          
                |--5.06%-- tcp_v4_rcv
                |          ip_local_deliver_finish
                |          ip_local_deliver
                |          ip_rcv_finish
                |          ip_rcv
                |          netif_receive_skb
                |          process_backlog
                |          net_rx_action
                |          __do_softirq
                |          call_softirq
                |          do_softirq
                |          _local_bh_enable_ip
                |          local_bh_enable
                |          dev_queue_xmit
                |          ip_finish_output2
                |          ip_finish_output
                |          ip_output
                |          ip_local_out
                |          ip_queue_xmit
                |          tcp_transmit_skb
                |          tcp_write_xmit
                |          __tcp_push_pending_frames
                |          tcp_push
                |          tcp_sendmsg
                |          __sock_sendmsg
                |          sock_aio_write
                |          do_sync_write
                |          vfs_write
                |          sys_write
                |          sysenter_dispatch
                |          0xf7f50430
                |          0x5
                |          
                |--4.07%-- __perf_counter_sched_out
                |          perf_counter_task_sched_out
                |          schedule
                |          schedule_timeout
                |          sk_wait_data
                |          tcp_recvmsg
                |          sock_common_recvmsg
                |          __sock_recvmsg
                |          sock_aio_read
                |          do_sync_read
                |          vfs_read
                |          sys_read
                |          sysenter_dispatch
                |          0xf7f50430
                |          0x5
                |          
                |--1.40%-- ipt_local_hook
                |          nf_iterate
                |          nf_hook_slow
                |          __ip_local_out
                |          ip_local_out
                |          ip_queue_xmit
                |          tcp_transmit_skb
                |          tcp_write_xmit
                |          __tcp_push_pending_frames
                |          tcp_push
                |          tcp_sendmsg
                |          __sock_sendmsg
                |          sock_aio_write
                |          do_sync_write
                |          vfs_write
                |          sys_write
                |          sysenter_dispatch
                |          0xf7f50430
                |          0x5
                |          
                |--1.26%-- mod_timer
                |          sk_reset_timer
                |          |          
                |          |--66.67%-- tcp_send_delayed_ack
                |          |          __tcp_ack_snd_check
                |          |          tcp_rcv_established
                |          |          tcp_v4_do_rcv
                |          |          tcp_prequeue_process
                |          |          tcp_recvmsg
                |          |          sock_common_recvmsg
                |          |          __sock_recvmsg
                |          |          sock_aio_read
                |          |          do_sync_read
                |          |          vfs_read
                |          |          sys_read
                |          |          sysenter_dispatch
                |          |          0xf7f50430
                |          |          0x5
                |          |          
                |           --33.33%-- tcp_v4_rcv
                |                     ip_local_deliver_finish
                |                     ip_local_deliver
                |                     ip_rcv_finish
                |                     ip_rcv
                |                     netif_receive_skb
                |                     process_backlog
                |                     net_rx_action
                |                     __do_softirq
                |                     call_softirq
                |                     do_softirq
                |                     _local_bh_enable_ip
                |                     local_bh_enable
                |                     dev_queue_xmit
                |                     ip_finish_output2
                |                     ip_finish_output
                |                     ip_output
                |                     ip_local_out
                |                     ip_queue_xmit
                |                     tcp_transmit_skb
                |                     tcp_write_xmit
                |                     __tcp_push_pending_frames
                |                     tcp_push
                |                     tcp_sendmsg
                |                     __sock_sendmsg
                |                     sock_aio_write
                |                     do_sync_write
                |                     vfs_write
                |                     sys_write
                |                     sysenter_dispatch
                |                     0xf7f50430
                |                     0x5
                |          
                |--0.70%-- ipt_local_in_hook
                |          nf_iterate
                |          nf_hook_slow
                |          ip_local_deliver
                |          ip_rcv_finish
                |          ip_rcv
                |          netif_receive_skb
                |          process_backlog
                |          net_rx_action
                |          __do_softirq
                |          call_softirq
                |          do_softirq
                |          _local_bh_enable_ip
                |          local_bh_enable
                |          dev_queue_xmit
                |          ip_finish_output2
                |          ip_finish_output
                |          ip_output
                |          ip_local_out
                |          ip_queue_xmit
                |          tcp_transmit_skb
                |          tcp_write_xmit
                |          __tcp_push_pending_frames
                |          tcp_push
                |          tcp_sendmsg
                |          __sock_sendmsg
                |          sock_aio_write
                |          do_sync_write
                |          vfs_write
                |          sys_write
                |          sysenter_dispatch
                |          0xf7f50430
                |          0x5
                |          
                |--0.56%-- perf_counter_task_sched_out
                |          schedule
                |          schedule_timeout
                |          sk_wait_data
                |          tcp_recvmsg
                |          sock_common_recvmsg
                |          __sock_recvmsg
                |          sock_aio_read
                |          do_sync_read
                |          vfs_read
                |          sys_read
                |          sysenter_dispatch
                |          0xf7f50430
                |          0x5
                 --2.53%-- [...]

     1.66%     perf  [kernel]                
                |          
                |--25.00%-- journal_stop
                |          __ext3_journal_stop
                |          ext3_writeback_write_end
                |          generic_perform_write
                |          generic_file_buffered_write
                |          __generic_file_aio_write_nolock
                |          generic_file_aio_write
                |          ext3_file_write
                |          do_sync_write
                |          vfs_write
                |          sys_write
                |          system_call_fastpath
                |          __write_nocancel
                |          
                |--16.67%-- __perf_counter_sched_out
                |          perf_counter_task_sched_out
                |          schedule
                |          schedule_hrtimeout_range
                |          poll_schedule_timeout
                |          do_poll
                |          do_sys_poll
                |          sys_poll
                |          system_call_fastpath
                |          __GI___poll
                |          
                |--8.33%-- dup_mmap
                |          dup_mm
                |          copy_process
                |          do_fork
                |          sys_clone
                |          stub_clone
                |          fork
                |          __cmd_record
                |          
                |--8.33%-- hrtimer_interrupt
                |          smp_apic_timer_interrupt
                |          apic_timer_interrupt
                |          __write_nocancel
                |          
                |--8.33%-- journal_start
                |          ext3_journal_start_sb
                |          ext3_write_begin
                |          generic_perform_write
                |          generic_file_buffered_write
                |          __generic_file_aio_write_nolock
                |          generic_file_aio_write
                |          ext3_file_write
                |          do_sync_write
                |          vfs_write
                |          sys_write
                |          system_call_fastpath
                |          __write_nocancel
                |          
                |--8.33%-- create_empty_buffers
                |          __block_prepare_write
                |          block_write_begin
                |          ext3_write_begin
                |          generic_perform_write
                |          generic_file_buffered_write
                |          __generic_file_aio_write_nolock
                |          generic_file_aio_write
                |          ext3_file_write
                |          do_sync_write
                |          vfs_write
                |          sys_write
                |          system_call_fastpath
                |          __write_nocancel
                |          
                |--8.33%-- perf_counter_task_sched_out
                |          schedule
                |          schedule_hrtimeout_range
                |          poll_schedule_timeout
                |          do_poll
                |          do_sys_poll
                |          sys_poll
                |          system_call_fastpath
                |          __GI___poll
                |          
                |--8.33%-- ext3_alloc_branch
                |          ext3_get_blocks_handle
                |          ext3_get_block
                |          __block_prepare_write
                |          block_write_begin
                |          ext3_write_begin
                |          generic_perform_write
                |          generic_file_buffered_write
                |          __generic_file_aio_write_nolock
                |          generic_file_aio_write
                |          ext3_file_write
                |          do_sync_write
                |          vfs_write
                |          sys_write
                |          system_call_fastpath
                |          __write_nocancel
                |          
                 --8.33%-- start_this_handle
                           journal_start
                           ext3_journal_start_sb
                           ext3_write_begin
                           generic_perform_write
                           generic_file_buffered_write
                           __generic_file_aio_write_nolock
                           generic_file_aio_write
                           ext3_file_write
                           do_sync_write
                           vfs_write
                           sys_write
                           system_call_fastpath
                           __write_nocancel

the graph above (which is the sub-graph of the full graph, limited via the -S/--symbols option to all callchains that intersect with the _spin_lock symbol) details all the various code-paths that make use of _spin_lock(), and the weights (and relative weights) of those codepaths.

Note that this works for just about any locking primitive, and note how it's recursive. If we inlined spin_lock we'd only know this __mod_timer overhead:

                |--31.46%-- __mod_timer

but we wouldnt know the second level (which is interesting too):

                |          |--55.36%-- tcp_send_delayed_ack
                |           --44.64%-- tcp_v4_rcv

All in one, i think we should detach the issue of instrumentation and profiling from the issue of whether to inline or not. We should inline where it makes things faster. Our profiling tools are able to deal with it, independently of whether we inline or not.

Ingo

sorry - mail got trimmed due to a cut&paste mishap. Here's the missing bw_pipe profile:

# Samples: 81007
#

 # Overhead  Command             Shared Object  Symbol
 # ........  .......  ........................  ......

#

     7.60%  bw_pipe  [kernel]                  [k] mutex_spin_on_owner
                |          
                |--99.97%-- __mutex_lock_common
                |          __mutex_lock_slowpath
                |          mutex_lock
                |          |          
                |          |--98.46%-- pipe_write
                |          |          do_sync_write
                |          |          vfs_write
                |          |          sys_write
                |          |          sysenter_dispatch
                |          |          0xf7f4f430
                |          |          0x600000007
                |          |          
                |           --1.54%-- pipe_lock
                |                     pipe_wait
                |                     pipe_write
                |                     do_sync_write
                |                     vfs_write
                |                     sys_write
                |                     sysenter_dispatch
                |                     0xf7f4f430
                |                     0x600000007
                 --0.03%-- [...]

it shows that the mutex overhead is distributed between these two functions:

                |          |--98.46%-- pipe_write
                |           --1.54%-- pipe_lock

I also wanted to show a more complex example, how spin-lock overhead gets distributed in the networking stack, in a "lat_tcp localhost" workload:

It's all spinlock* variants that are frequently called (see also below).

Ok, that makes sense. I will post updated patches.

FWIW:
All of this started when we compared a 2.6.27 based distro kernel to a 2.6.16 based one. It turned out that 2.6.27 burns a lot more cpu cycles than 2.6.16 does for the same workloads.

As an example: we took a simple one connection ping pong network load. (client sends packet to server and waits until packet from server
returns and game starts again). It uses more cpu cycles on 2.6.27.

Using ftrace we figured out that on 2.6.27 it takes more than 500 function calls on the client for a single roundtrip while on 2.6.16 it took only ~230 calls.
Changing s390 from its own NOHZ code to the generic version did cost quite a few cycles. The idle entry and exit paths are much more expensive now. That's why you've seen Martin posting NOHZ/timer related patches lately.

But also quite a few functions that were inlined in 2.6.16 are out-of-line in 2.6.27. Reverting those changes did improve performance as well.

Since out of the ~500 function calls 60 are spin_[un]lock* calls it seemed worthwile inlining them. Which also improved things again.

Here are the function traces for 2.6.27 and 2.6.16:
(the timestamp output has been modified)

For 2.6.27:

# tracer: ftrace
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |

            perl-2581  [00] 28991519113889978 [+  125]: SyS_write <-sysc_noemu
            perl-2581  [00] 28991519113890103 [+  156]: fget_light <-SyS_write
            perl-2581  [00] 28991519113890259 [+  125]: vfs_write <-SyS_write
            perl-2581  [00] 28991519113890384 [+  156]: rw_verify_area <-vfs_write
            perl-2581  [00] 28991519113890540 [+  125]: security_file_permission <-rw_verify_area
            perl-2581  [00] 28991519113890665 [+   93]: apparmor_file_permission <-security_file_permission
            perl-2581  [00] 28991519113890759 [+  156]: aa_file_permission <-apparmor_file_permission
            perl-2581  [00] 28991519113890915 [+  125]: do_sync_write <-vfs_write
            perl-2581  [00] 28991519113891040 [+  125]: sock_aio_write <-do_sync_write
            perl-2581  [00] 28991519113891165 [+  125]: security_socket_sendmsg <-sock_aio_write
            perl-2581  [00] 28991519113891290 [+  125]: apparmor_socket_sendmsg <-security_socket_sendmsg
            perl-2581  [00] 28991519113891415 [+  125]: aa_revalidate_sk <-apparmor_socket_sendmsg
            perl-2581  [00] 28991519113891540 [+  125]: tcp_sendmsg <-sock_aio_write
            perl-2581  [00] 28991519113891665 [+  125]: lock_sock_nested <-tcp_sendmsg
            perl-2581  [00] 28991519113891790 [+  125]: _spin_lock_bh <-lock_sock_nested
            perl-2581  [00] 28991519113891915 [+  125]: local_bh_disable <-_spin_lock_bh
            perl-2581  [00] 28991519113892040 [+  187]: local_bh_enable <-lock_sock_nested
            perl-2581  [00] 28991519113892228 [+  125]: tcp_current_mss <-tcp_sendmsg
            perl-2581  [00] 28991519113892353 [+  156]: tcp_established_options <-tcp_current_mss
            perl-2581  [00] 28991519113892509 [+  125]: sk_stream_alloc_skb <-tcp_sendmsg
            perl-2581  [00] 28991519113892634 [+  125]: __alloc_skb <-sk_stream_alloc_skb
            perl-2581  [00] 28991519113892759 [+  156]: kmem_cache_alloc <-__alloc_skb
            perl-2581  [00] 28991519113892915 [+  281]: __kmalloc <-__alloc_skb
            perl-2581  [00] 28991519113893196 [+  125]: skb_put <-tcp_sendmsg
            perl-2581  [00] 28991519113893321 [+  125]: copy_from_user_mvcos_check <-tcp_sendmsg
            perl-2581  [00] 28991519113893446 [+  156]: copy_from_user_std <-copy_from_user_mvcos_check
            perl-2581  [00] 28991519113893603 [+  125]: __tcp_push_pending_frames <-tcp_sendmsg
            perl-2581  [00] 28991519113893728 [+  125]: tcp_init_tso_segs <-__tcp_push_pending_frames
            perl-2581  [00] 28991519113893853 [+  125]: tcp_set_skb_tso_segs <-tcp_init_tso_segs
            perl-2581  [00] 28991519113893978 [+  156]: tcp_transmit_skb <-__tcp_push_pending_frames
            perl-2581  [00] 28991519113894134 [+   93]: skb_clone <-tcp_transmit_skb
            perl-2581  [00] 28991519113894228 [+  125]: __skb_clone <-skb_clone
            perl-2581  [00] 28991519113894353 [+  156]: __copy_skb_header <-__skb_clone
            perl-2581  [00] 28991519113894509 [+  125]: tcp_established_options <-tcp_transmit_skb
            perl-2581  [00] 28991519113894634 [+  125]: skb_push <-tcp_transmit_skb
            perl-2581  [00] 28991519113894759 [+  156]: __tcp_select_window <-tcp_transmit_skb
            perl-2581  [00] 28991519113894915 [+  125]: tcp_options_write <-tcp_transmit_skb
            perl-2581  [00] 28991519113895040 [+  156]: tcp_v4_send_check <-tcp_transmit_skb
            perl-2581  [00] 28991519113895196 [+  125]: ip_queue_xmit <-tcp_transmit_skb
            perl-2581  [00] 28991519113895321 [+  156]: __sk_dst_check <-ip_queue_xmit
            perl-2581  [00] 28991519113895478 [+  125]: skb_push <-ip_queue_xmit
            perl-2581  [00] 28991519113895603 [+   93]: ip_local_out <-ip_queue_xmit
            perl-2581  [00] 28991519113895696 [+  156]: __ip_local_out <-ip_local_out
            perl-2581  [00] 28991519113895853 [+  125]: ip_output <-ip_local_out
            perl-2581  [00] 28991519113895978 [+  156]: ip_finish_output <-ip_output
            perl-2581  [00] 28991519113896134 [+  125]: skb_push <-ip_finish_output
            perl-2581  [00] 28991519113896259 [+  125]: dev_queue_xmit <-ip_finish_output
            perl-2581  [00] 28991519113896384 [+  125]: local_bh_disable <-dev_queue_xmit
            perl-2581  [00] 28991519113896509 [+  187]: _spin_lock <-dev_queue_xmit
            perl-2581  [00] 28991519113896696 [+  125]: pfifo_fast_enqueue <-dev_queue_xmit
            perl-2581  [00] 28991519113896821 [+  125]: __qdisc_run <-dev_queue_xmit
            perl-2581  [00] 28991519113896946 [+  156]: pfifo_fast_dequeue <-__qdisc_run
            perl-2581  [00] 28991519113897103 [+  125]: _spin_lock <-__qdisc_run
            perl-2581  [00] 28991519113897228 [+  187]: dev_hard_start_xmit <-__qdisc_run
            perl-2581  [00] 28991519113897415 [+  156]: qeth_l3_hard_start_xmit <-dev_hard_start_xmit
            perl-2581  [00] 28991519113897571 [+  125]: qeth_get_cast_type <-qeth_l3_hard_start_xmit
            perl-2581  [00] 28991519113897696 [+  156]: qeth_get_priority_queue <-qeth_l3_hard_start_xmit
            perl-2581  [00] 28991519113897853 [+  125]: skb_realloc_headroom <-qeth_l3_hard_start_xmit
            perl-2581  [00] 28991519113897978 [+  125]: pskb_copy <-skb_realloc_headroom
            perl-2581  [00] 28991519113898103 [+   93]: __alloc_skb <-pskb_copy
            perl-2581  [00] 28991519113898196 [+  187]: kmem_cache_alloc <-__alloc_skb
            perl-2581  [00] 28991519113898384 [+  218]: __kmalloc <-__alloc_skb
            perl-2581  [00] 28991519113898603 [+  156]: skb_put <-pskb_copy
            perl-2581  [00] 28991519113898759 [+   93]: copy_skb_header <-pskb_copy
            perl-2581  [00] 28991519113898853 [+  218]: __copy_skb_header <-copy_skb_header
            perl-2581  [00] 28991519113899071 [+  125]: skb_pull <-qeth_l3_hard_start_xmit
            perl-2581  [00] 28991519113899196 [+  125]: skb_push <-qeth_l3_hard_start_xmit
            perl-2581  [00] 28991519113899321 [+  156]: qeth_l3_fill_header <-qeth_l3_hard_start_xmit
            perl-2581  [00] 28991519113899478 [+  125]: qeth_get_elements_no <-qeth_l3_hard_start_xmit
            perl-2581  [00] 28991519113899603 [+  156]: qeth_do_send_packet <-qeth_l3_hard_start_xmit
            perl-2581  [00] 28991519113899759 [+  125]: skb_queue_tail <-qeth_do_send_packet
            perl-2581  [00] 28991519113899884 [+  125]: _spin_lock_irqsave <-skb_queue_tail
            perl-2581  [00] 28991519113900009 [+  156]: _spin_unlock_irqrestore <-skb_queue_tail
            perl-2581  [00] 28991519113900165 [+  187]: qeth_flush_buffers <-qeth_do_send_packet
            perl-2581  [00] 28991519113900353 [+  156]: do_QDIO <-qeth_flush_buffers
            perl-2581  [00] 28991519113900509 [+  156]: qdio_perf_stat_inc <-do_QDIO
            perl-2581  [00] 28991519113900665 [+  125]: qdio_kick_outbound_q <-do_QDIO
            perl-2581  [00] 28991519113900790 [+  812]: qdio_perf_stat_inc <-qdio_kick_outbound_q
            perl-2581  [00] 28991519113901603 [+  218]: __tasklet_schedule <-do_QDIO
            perl-2581  [00] 28991519113901821 [+  156]: dev_kfree_skb_any <-qeth_l3_hard_start_xmit
            perl-2581  [00] 28991519113901978 [+  125]: kfree_skb <-dev_kfree_skb_any
            perl-2581  [00] 28991519113902103 [+   93]: __kfree_skb <-kfree_skb
            perl-2581  [00] 28991519113902196 [+  125]: skb_release_all <-__kfree_skb
            perl-2581  [00] 28991519113902321 [+  156]: dst_release <-skb_release_all
            perl-2581  [00] 28991519113902478 [+   93]: sock_wfree <-skb_release_all
            perl-2581  [00] 28991519113902571 [+  187]: skb_release_data <-skb_release_all
            perl-2581  [00] 28991519113902759 [+  125]: __netif_schedule <-qeth_l3_hard_start_xmit
            perl-2581  [00] 28991519113902884 [+  156]: raise_softirq_irqoff <-__netif_schedule
            perl-2581  [00] 28991519113903040 [+  125]: _spin_lock <-__qdisc_run
            perl-2581  [00] 28991519113903165 [+  187]: local_bh_enable <-dev_queue_xmit
            perl-2581  [00] 28991519113903353 [+  156]: do_softirq <-local_bh_enable
            perl-2581  [00] 28991519113903509 [+   93]: __do_softirq <-do_softirq
            perl-2581  [00] 28991519113903603 [+   93]: account_system_vtime <-__do_softirq
            perl-2581  [00] 28991519113903696 [+  125]: account_system_time <-account_system_vtime
            perl-2581  [00] 28991519113903821 [+   93]: acct_update_integrals <-account_system_time
            perl-2581  [00] 28991519113903915 [+  187]: jiffies_to_timeval <-acct_update_integrals
            perl-2581  [00] 28991519113904103 [+  156]: net_tx_action <-__do_softirq
            perl-2581  [00] 28991519113904259 [+  125]: _spin_trylock <-net_tx_action
            perl-2581  [00] 28991519113904384 [+  125]: __qdisc_run <-net_tx_action
            perl-2581  [00] 28991519113904509 [+  156]: pfifo_fast_dequeue <-__qdisc_run
            perl-2581  [00] 28991519113904665 [+  187]: tasklet_action <-__do_softirq
            perl-2581  [00] 28991519113904853 [+   93]: qdio_outbound_processing <-tasklet_action
            perl-2581  [00] 28991519113904946 [+  187]: qdio_perf_stat_inc <-qdio_outbound_processing
            perl-2581  [00] 28991519113905134 [+  156]: mod_timer <-qdio_outbound_processing
            perl-2581  [00] 28991519113905290 [+  125]: __timer_stats_timer_set_start_info <-mod_timer
            perl-2581  [00] 28991519113905415 [+  125]: __mod_timer <-mod_timer
            perl-2581  [00] 28991519113905540 [+  125]: __timer_stats_timer_set_start_info <-__mod_timer
            perl-2581  [00] 28991519113905665 [+   93]: lock_timer_base <-__mod_timer
            perl-2581  [00] 28991519113905759 [+  156]: _spin_lock_irqsave <-lock_timer_base
            perl-2581  [00] 28991519113905915 [+  125]: internal_add_timer <-__mod_timer
            perl-2581  [00] 28991519113906040 [+  125]: _spin_unlock_irqrestore <-__mod_timer
            perl-2581  [00] 28991519113906165 [+  156]: qdio_perf_stat_inc <-qdio_outbound_processing
            perl-2581  [00] 28991519113906321 [+  125]: account_system_vtime <-__do_softirq
            perl-2581  [00] 28991519113906446 [+   62]: account_system_time <-account_system_vtime
            perl-2581  [00] 28991519113906509 [+  125]: acct_update_integrals <-account_system_time
            perl-2581  [00] 28991519113906634 [+  125]: jiffies_to_timeval <-acct_update_integrals
            perl-2581  [00] 28991519113906759 [+  156]: _local_bh_enable <-__do_softirq
            perl-2581  [00] 28991519113906915 [+  125]: tcp_event_new_data_sent <-__tcp_push_pending_frames
            perl-2581  [00] 28991519113907040 [+  125]: sk_reset_timer <-tcp_event_new_data_sent
            perl-2581  [00] 28991519113907165 [+   93]: mod_timer <-sk_reset_timer
            perl-2581  [00] 28991519113907259 [+  187]: __timer_stats_timer_set_start_info <-mod_timer
            perl-2581  [00] 28991519113907446 [+  156]: release_sock <-tcp_sendmsg
            perl-2581  [00] 28991519113907603 [+  125]: _spin_lock_bh <-release_sock
            perl-2581  [00] 28991519113907728 [+  125]: local_bh_disable <-_spin_lock_bh
            perl-2581  [00] 28991519113907853 [+  125]: _spin_unlock_bh <-release_sock
            perl-2581  [00] 28991519113907978 [+  187]: local_bh_enable_ip <-_spin_unlock_bh
            perl-2581  [00] 28991519113908165 [+   93]: dnotify_parent <-vfs_write
            perl-2581  [00] 28991519113908259 [+  156]: _spin_lock <-dnotify_parent
            perl-2581  [00] 28991519113908415 [+  156]: inotify_dentry_parent_queue_event <-vfs_write
            perl-2581  [00] 28991519113908571 [+  875]: inotify_inode_queue_event <-vfs_write
            perl-2581  [00] 28991519113909446 [+   93]: SyS_read <-sysc_noemu
            perl-2581  [00] 28991519113909540 [+  156]: fget_light <-SyS_read
            perl-2581  [00] 28991519113909696 [+  125]: vfs_read <-SyS_read
            perl-2581  [00] 28991519113909821 [+  125]: rw_verify_area <-vfs_read
            perl-2581  [00] 28991519113909946 [+  125]: security_file_permission <-rw_verify_area
            perl-2581  [00] 28991519113910071 [+  125]: apparmor_file_permission <-security_file_permission
            perl-2581  [00] 28991519113910196 [+  125]: aa_file_permission <-apparmor_file_permission
            perl-2581  [00] 28991519113910321 [+  156]: do_sync_read <-vfs_read
            perl-2581  [00] 28991519113910478 [+  125]: sock_aio_read <-do_sync_read
            perl-2581  [00] 28991519113910603 [+  125]: security_socket_recvmsg <-sock_aio_read
            perl-2581  [00] 28991519113910728 [+   93]: apparmor_socket_recvmsg <-security_socket_recvmsg
            perl-2581  [00] 28991519113910821 [+  156]: aa_revalidate_sk <-apparmor_socket_recvmsg
            perl-2581  [00] 28991519113910978 [+  125]: sock_common_recvmsg <-sock_aio_read
            perl-2581  [00] 28991519113911103 [+  125]: tcp_recvmsg <-sock_common_recvmsg
            perl-2581  [00] 28991519113911228 [+  125]: lock_sock_nested <-tcp_recvmsg
            perl-2581  [00] 28991519113911353 [+  125]: _spin_lock_bh <-lock_sock_nested
            perl-2581  [00] 28991519113911478 [+  125]: local_bh_disable <-_spin_lock_bh
            perl-2581  [00] 28991519113911603 [+  250]: local_bh_enable <-lock_sock_nested
            perl-2581  [00] 28991519113911853 [+  125]: tcp_cleanup_rbuf <-tcp_recvmsg
            perl-2581  [00] 28991519113911978 [+  125]: sk_wait_data <-tcp_recvmsg
            perl-2581  [00] 28991519113912103 [+  125]: prepare_to_wait <-sk_wait_data
            perl-2581  [00] 28991519113912228 [+  125]: _spin_lock_irqsave <-prepare_to_wait
            perl-2581  [00] 28991519113912353 [+  125]: _spin_unlock_irqrestore <-prepare_to_wait
            perl-2581  [00] 28991519113912478 [+  125]: release_sock <-sk_wait_data
            perl-2581  [00] 28991519113912603 [+  125]: _spin_lock_bh <-release_sock
            perl-2581  [00] 28991519113912728 [+  125]: local_bh_disable <-_spin_lock_bh
            perl-2581  [00] 28991519113912853 [+  125]: _spin_unlock_bh <-release_sock
            perl-2581  [00] 28991519113912978 [+  187]: local_bh_enable_ip <-_spin_unlock_bh
            perl-2581  [00] 28991519113913165 [+  125]: schedule_timeout <-sk_wait_data
            perl-2581  [00] 28991519113913290 [+  125]: schedule <-schedule_timeout
            perl-2581  [00] 28991519113913415 [+  125]: _spin_lock <-schedule
            perl-2581  [00] 28991519113913540 [+   93]: sched_clock_cpu <-schedule
            perl-2581  [00] 28991519113913634 [+  125]: sched_clock <-sched_clock_cpu
            perl-2581  [00] 28991519113913759 [+   93]: deactivate_task <-schedule
            perl-2581  [00] 28991519113913853 [+  125]: dequeue_task <-deactivate_task
            perl-2581  [00] 28991519113913978 [+   93]: dequeue_task_fair <-dequeue_task
            perl-2581  [00] 28991519113914071 [+   93]: dequeue_entity <-dequeue_task_fair
            perl-2581  [00] 28991519113914165 [+  156]: update_curr <-dequeue_entity
            perl-2581  [00] 28991519113914321 [+   93]: hrtick_start_fair <-dequeue_task_fair
            perl-2581  [00] 28991519113914415 [+  125]: put_prev_task_fair <-schedule
            perl-2581  [00] 28991519113914540 [+  125]: pick_next_task_fair <-schedule
            perl-2581  [00] 28991519113914665 [+   93]: pick_next_task_rt <-schedule
            perl-2581  [00] 28991519113914759 [+   93]: pick_next_task_fair <-schedule
            perl-2581  [00] 28991519113914853 [+  125]: pick_next_task_idle <-schedule
            perl-2581  [00] 28991519113914978 [+  218]: _spin_trylock <-tracing_record_cmdline
          <idle>-0     [00] 28991519113915196 [+  125]: finish_task_switch <-schedule
          <idle>-0     [00] 28991519113915321 [+   62]: account_vtime <-finish_task_switch
          <idle>-0     [00] 28991519113915384 [+   93]: account_user_time <-account_vtime
          <idle>-0     [00] 28991519113915478 [+   93]: acct_update_integrals <-account_user_time
          <idle>-0     [00] 28991519113915571 [+  125]: jiffies_to_timeval <-acct_update_integrals
          <idle>-0     [00] 28991519113915696 [+   93]: account_system_time <-account_vtime
          <idle>-0     [00] 28991519113915790 [+   93]: acct_update_integrals <-account_system_time
          <idle>-0     [00] 28991519113915884 [+  187]: jiffies_to_timeval <-acct_update_integrals
          <idle>-0     [00] 28991519113916071 [+  125]: tick_nohz_stop_sched_tick <-cpu_idle
          <idle>-0     [00] 28991519113916196 [+   93]: ktime_get <-tick_nohz_stop_sched_tick
          <idle>-0     [00] 28991519113916290 [+   93]: ktime_get_ts <-ktime_get
          <idle>-0     [00] 28991519113916384 [+   93]: getnstimeofday <-ktime_get_ts
          <idle>-0     [00] 28991519113916478 [+  125]: read_tod_clock <-getnstimeofday
          <idle>-0     [00] 28991519113916603 [+  156]: set_normalized_timespec <-ktime_get_ts
          <idle>-0     [00] 28991519113916759 [+   93]: get_next_timer_interrupt <-tick_nohz_stop_sched_tick
          <idle>-0     [00] 28991519113916853 [+  125]: _spin_lock <-get_next_timer_interrupt
          <idle>-0     [00] 28991519113916978 [+   93]: hrtimer_get_next_event <-get_next_timer_interrupt
          <idle>-0     [00] 28991519113917071 [+  125]: _spin_lock_irqsave <-hrtimer_get_next_event
          <idle>-0     [00] 28991519113917196 [+   93]: _spin_unlock_irqrestore <-hrtimer_get_next_event
          <idle>-0     [00] 28991519113917290 [+   93]: rcu_needs_cpu <-tick_nohz_stop_sched_tick
          <idle>-0     [00] 28991519113917384 [+  156]: rcu_pending <-rcu_needs_cpu
          <idle>-0     [00] 28991519113917540 [+   93]: select_nohz_load_balancer <-tick_nohz_stop_sched_tick
          <idle>-0     [00] 28991519113917634 [+   93]: hweight64 <-select_nohz_load_balancer
          <idle>-0     [00] 28991519113917728 [+  156]: hweight64 <-select_nohz_load_balancer
          <idle>-0     [00] 28991519113917884 [+   62]: hrtimer_start <-tick_nohz_stop_sched_tick
          <idle>-0     [00] 28991519113917946 [+   93]: lock_hrtimer_base <-hrtimer_start
          <idle>-0     [00] 28991519113918040 [+  125]: _spin_lock_irqsave <-lock_hrtimer_base
          <idle>-0     [00] 28991519113918165 [+   93]: __remove_hrtimer <-hrtimer_start
          <idle>-0     [00] 28991519113918259 [+  125]: rb_next <-__remove_hrtimer
          <idle>-0     [00] 28991519113918384 [+  125]: hrtimer_force_reprogram <-__remove_hrtimer
          <idle>-0     [00] 28991519113918509 [+   93]: tick_program_event <-hrtimer_force_reprogram
          <idle>-0     [00] 28991519113918603 [+   93]: tick_dev_program_event <-tick_program_event
          <idle>-0     [00] 28991519113918696 [+   93]: ktime_get <-tick_dev_program_event
          <idle>-0     [00] 28991519113918790 [+   93]: ktime_get_ts <-ktime_get
          <idle>-0     [00] 28991519113918884 [+   62]: getnstimeofday <-ktime_get_ts
          <idle>-0     [00] 28991519113918946 [+  125]: read_tod_clock <-getnstimeofday
          <idle>-0     [00] 28991519113919071 [+  125]: set_normalized_timespec <-ktime_get_ts
          <idle>-0     [00] 28991519113919196 [+   93]: clockevents_program_event <-tick_dev_program_event
          <idle>-0     [00] 28991519113919290 [+   93]: s390_next_event <-clockevents_program_event
          <idle>-0     [00] 28991519113919384 [+  156]: rb_erase <-__remove_hrtimer
          <idle>-0     [00] 28991519113919540 [+   93]: __timer_stats_hrtimer_set_start_info <-hrtimer_start
          <idle>-0     [00] 28991519113919634 [+   93]: enqueue_hrtimer <-hrtimer_start
          <idle>-0     [00] 28991519113919728 [+  125]: hrtimer_reprogram <-enqueue_hrtimer
          <idle>-0     [00] 28991519113919853 [+   62]: tick_program_event <-hrtimer_reprogram
          <idle>-0     [00] 28991519113919915 [+   93]: tick_dev_program_event <-tick_program_event
          <idle>-0     [00] 28991519113920009 [+   93]: ktime_get <-tick_dev_program_event
          <idle>-0     [00] 28991519113920103 [+   93]: ktime_get_ts <-ktime_get
          <idle>-0     [00] 28991519113920196 [+   62]: getnstimeofday <-ktime_get_ts
          <idle>-0     [00] 28991519113920259 [+  125]: read_tod_clock <-getnstimeofday
          <idle>-0     [00] 28991519113920384 [+  125]: set_normalized_timespec <-ktime_get_ts
          <idle>-0     [00] 28991519113920509 [+   62]: clockevents_program_event <-tick_dev_program_event
          <idle>-0     [00] 28991519113920571 [+  125]: s390_next_event <-clockevents_program_event
          <idle>-0     [00] 28991519113920696 [+  125]: rb_insert_color <-enqueue_hrtimer
          <idle>-0     [00] 28991519113920821 [+  156]: _spin_unlock_irqrestore <-hrtimer_start
          <idle>-0     [00] 28991519113920978 [+  125]: _spin_lock <-cpu_idle
          <idle>-0     [00] 28991519113921103 [+229750]: vtime_stop_cpu_timer <-cpu_idle
          <idle>-0     [00] 28991519114150853 [+   93]: do_IRQ <-io_return
          <idle>-0     [00] 28991519114150946 [+   62]: irq_enter <-do_IRQ
          <idle>-0     [00] 28991519114151009 [+  125]: idle_cpu <-irq_enter
          <idle>-0     [00] 28991519114151134 [+   93]: tick_nohz_stop_idle <-irq_enter
          <idle>-0     [00] 28991519114151228 [+   62]: ktime_get <-tick_nohz_stop_idle
          <idle>-0     [00] 28991519114151290 [+  125]: ktime_get_ts <-ktime_get
          <idle>-0     [00] 28991519114151415 [+   62]: getnstimeofday <-ktime_get_ts
          <idle>-0     [00] 28991519114151478 [+   93]: read_tod_clock <-getnstimeofday
          <idle>-0     [00] 28991519114151571 [+  125]: set_normalized_timespec <-ktime_get_ts
          <idle>-0     [00] 28991519114151696 [+   93]: account_system_vtime <-irq_enter
          <idle>-0     [00] 28991519114151790 [+   93]: account_system_time <-account_system_vtime
          <idle>-0     [00] 28991519114151884 [+  125]: acct_update_integrals <-account_system_time
          <idle>-0     [00] 28991519114152009 [+   93]: idle_cpu <-irq_enter
          <idle>-0     [00] 28991519114152103 [+   62]: tick_nohz_update_jiffies <-irq_enter
          <idle>-0     [00] 28991519114152165 [+   93]: ktime_get <-tick_nohz_update_jiffies
          <idle>-0     [00] 28991519114152259 [+   93]: ktime_get_ts <-ktime_get
          <idle>-0     [00] 28991519114152353 [+   62]: getnstimeofday <-ktime_get_ts
          <idle>-0     [00] 28991519114152415 [+   93]: read_tod_clock <-getnstimeofday
          <idle>-0     [00] 28991519114152509 [+  125]: set_normalized_timespec <-ktime_get_ts
          <idle>-0     [00] 28991519114152634 [+  125]: tick_do_update_jiffies64 <-tick_nohz_update_jiffies
          <idle>-0     [00] 28991519114152759 [+   62]: s390_idle_leave <-do_IRQ
          <idle>-0     [00] 28991519114152821 [+  125]: vtime_start_cpu_timer <-s390_idle_leave
          <idle>-0     [00] 28991519114152946 [+   93]: _spin_lock <-s390_idle_leave
          <idle>-0     [00] 28991519114153040 [+  250]: do_adapter_IO <-do_IRQ
          <idle>-0     [00] 28991519114153290 [+   93]: tiqdio_thinint_handler <-do_adapter_IO
          <idle>-0     [00] 28991519114153384 [+  156]: qdio_perf_stat_inc <-tiqdio_thinint_handler
          <idle>-0     [00] 28991519114153540 [+  250]: __tasklet_hi_schedule <-tiqdio_thinint_handler
          <idle>-0     [00] 28991519114153790 [+   93]: irq_exit <-do_IRQ
          <idle>-0     [00] 28991519114153884 [+   93]: account_system_vtime <-irq_exit
          <idle>-0     [00] 28991519114153978 [+   93]: account_system_time <-account_system_vtime
          <idle>-0     [00] 28991519114154071 [+   93]: acct_update_integrals <-account_system_time
          <idle>-0     [00] 28991519114154165 [+   93]: do_softirq <-irq_exit
          <idle>-0     [00] 28991519114154259 [+   93]: __do_softirq <-do_softirq
          <idle>-0     [00] 28991519114154353 [+   62]: account_system_vtime <-__do_softirq
          <idle>-0     [00] 28991519114154415 [+  125]: account_system_time <-account_system_vtime
          <idle>-0     [00] 28991519114154540 [+   93]: acct_update_integrals <-account_system_time
          <idle>-0     [00] 28991519114154634 [+   93]: tasklet_hi_action <-__do_softirq
          <idle>-0     [00] 28991519114154728 [+   93]: tiqdio_tasklet_fn <-tasklet_hi_action
          <idle>-0     [00] 28991519114154821 [+  218]: qdio_perf_stat_inc <-tiqdio_tasklet_fn
          <idle>-0     [00] 28991519114155040 [+  218]: __tasklet_schedule <-tiqdio_tasklet_fn
          <idle>-0     [00] 28991519114155259 [+  125]: tasklet_action <-__do_softirq
          <idle>-0     [00] 28991519114155384 [+   93]: tiqdio_inbound_processing <-tasklet_action
          <idle>-0     [00] 28991519114155478 [+   93]: qdio_perf_stat_inc <-tiqdio_inbound_processing
          <idle>-0     [00] 28991519114155571 [+  125]: qdio_sync_after_thinint <-tiqdio_inbound_processing
          <idle>-0     [00] 28991519114155696 [+   93]: qdio_siga_sync <-qdio_sync_after_thinint
          <idle>-0     [00] 28991519114155790 [+  125]: qdio_check_outbound_after_thinint <-tiqdio_inbound_processing
          <idle>-0     [00] 28991519114155915 [+  125]: __tasklet_schedule <-qdio_check_outbound_after_thinint
          <idle>-0     [00] 28991519114156040 [+  218]: qdio_inbound_q_moved <-tiqdio_inbound_processing
          <idle>-0     [00] 28991519114156259 [+   93]: qdio_kick_inbound_handler <-tiqdio_inbound_processing
          <idle>-0     [00] 28991519114156353 [+   93]: qdio_perf_stat_inc <-qdio_kick_inbound_handler
          <idle>-0     [00] 28991519114156446 [+  156]: qeth_l3_qdio_input_handler <-qdio_kick_inbound_handler
          <idle>-0     [00] 28991519114156603 [+  218]: qeth_core_get_next_skb <-qeth_l3_qdio_input_handler
          <idle>-0     [00] 28991519114156821 [+   62]: dev_alloc_skb <-qeth_core_get_next_skb
          <idle>-0     [00] 28991519114156884 [+  125]: __alloc_skb <-dev_alloc_skb
          <idle>-0     [00] 28991519114157009 [+   93]: kmem_cache_alloc <-__alloc_skb
          <idle>-0     [00] 28991519114157103 [+  187]: __kmalloc <-__alloc_skb
          <idle>-0     [00] 28991519114157290 [+  187]: skb_put <-qeth_core_get_next_skb
          <idle>-0     [00] 28991519114157478 [+   93]: eth_header <-qeth_l3_qdio_input_handler
          <idle>-0     [00] 28991519114157571 [+   93]: skb_push <-eth_header
          <idle>-0     [00] 28991519114157665 [+   93]: eth_type_trans <-qeth_l3_qdio_input_handler
          <idle>-0     [00] 28991519114157759 [+  125]: skb_pull <-eth_type_trans
          <idle>-0     [00] 28991519114157884 [+   93]: netif_rx <-qeth_l3_qdio_input_handler
          <idle>-0     [00] 28991519114157978 [+  125]: __napi_schedule <-netif_rx
          <idle>-0     [00] 28991519114158103 [+  125]: qeth_core_get_next_skb <-qeth_l3_qdio_input_handler
          <idle>-0     [00] 28991519114158228 [+  125]: qeth_queue_input_buffer <-qeth_l3_qdio_input_handler
          <idle>-0     [00] 28991519114158353 [+   62]: qdio_siga_sync_q <-tiqdio_inbound_processing
          <idle>-0     [00] 28991519114158415 [+  125]: qdio_siga_sync <-qdio_siga_sync_q
          <idle>-0     [00] 28991519114158540 [+   93]: get_buf_state <-tiqdio_inbound_processing
          <idle>-0     [00] 28991519114158634 [+   93]: qdio_stop_polling <-tiqdio_inbound_processing
          <idle>-0     [00] 28991519114158728 [+  125]: qdio_perf_stat_inc <-qdio_stop_polling
          <idle>-0     [00] 28991519114158853 [+   93]: qdio_siga_sync_q <-tiqdio_inbound_processing
          <idle>-0     [00] 28991519114158946 [+   93]: qdio_siga_sync <-qdio_siga_sync_q
          <idle>-0     [00] 28991519114159040 [+  156]: get_buf_state <-tiqdio_inbound_processing
          <idle>-0     [00] 28991519114159196 [+   93]: net_rx_action <-__do_softirq
          <idle>-0     [00] 28991519114159290 [+   93]: process_backlog <-net_rx_action
          <idle>-0     [00] 28991519114159384 [+  156]: netif_receive_skb <-process_backlog
          <idle>-0     [00] 28991519114159540 [+  125]: ip_rcv <-netif_receive_skb
          <idle>-0     [00] 28991519114159665 [+  125]: ip_rcv_finish <-ip_rcv
          <idle>-0     [00] 28991519114159790 [+  156]: ip_route_input <-ip_rcv_finish
          <idle>-0     [00] 28991519114159946 [+   62]: ip_local_deliver <-ip_rcv_finish
          <idle>-0     [00] 28991519114160009 [+   93]: ip_local_deliver_finish <-ip_local_deliver
          <idle>-0     [00] 28991519114160103 [+  125]: raw_local_deliver <-ip_local_deliver_finish
          <idle>-0     [00] 28991519114160228 [+   93]: tcp_v4_rcv <-ip_local_deliver_finish
          <idle>-0     [00] 28991519114160321 [+  125]: __inet_lookup_established <-tcp_v4_rcv
          <idle>-0     [00] 28991519114160446 [+  125]: _read_lock <-__inet_lookup_established
          <idle>-0     [00] 28991519114160571 [+   93]: sk_filter <-tcp_v4_rcv
          <idle>-0     [00] 28991519114160665 [+   93]: security_sock_rcv_skb <-sk_filter
          <idle>-0     [00] 28991519114160759 [+   62]: cap_socket_sock_rcv_skb <-security_sock_rcv_skb
          <idle>-0     [00] 28991519114160821 [+  125]: local_bh_disable <-sk_filter
          <idle>-0     [00] 28991519114160946 [+   93]: local_bh_enable <-sk_filter
          <idle>-0     [00] 28991519114161040 [+   93]: _spin_lock <-tcp_v4_rcv
          <idle>-0     [00] 28991519114161134 [+   93]: __wake_up <-tcp_v4_rcv
          <idle>-0     [00] 28991519114161228 [+   93]: _spin_lock_irqsave <-__wake_up
          <idle>-0     [00] 28991519114161321 [+   93]: __wake_up_common <-__wake_up
          <idle>-0     [00] 28991519114161415 [+   93]: autoremove_wake_function <-__wake_up_common
          <idle>-0     [00] 28991519114161509 [+   62]: default_wake_function <-autoremove_wake_function
          <idle>-0     [00] 28991519114161571 [+  125]: try_to_wake_up <-default_wake_function
          <idle>-0     [00] 28991519114161696 [+   62]: task_rq_lock <-try_to_wake_up
          <idle>-0     [00] 28991519114161759 [+  125]: _spin_lock <-task_rq_lock
          <idle>-0     [00] 28991519114161884 [+  125]: select_task_rq_fair <-try_to_wake_up
          <idle>-0     [00] 28991519114162009 [+   93]: sched_clock_cpu <-try_to_wake_up
          <idle>-0     [00] 28991519114162103 [+   93]: sched_clock <-sched_clock_cpu
          <idle>-0     [00] 28991519114162196 [+   93]: activate_task <-try_to_wake_up
          <idle>-0     [00] 28991519114162290 [+   93]: enqueue_task <-activate_task
          <idle>-0     [00] 28991519114162384 [+   93]: enqueue_task_fair <-enqueue_task
          <idle>-0     [00] 28991519114162478 [+   93]: enqueue_entity <-enqueue_task_fair
          <idle>-0     [00] 28991519114162571 [+   93]: update_curr <-enqueue_entity
          <idle>-0     [00] 28991519114162665 [+   93]: place_entity <-enqueue_entity
          <idle>-0     [00] 28991519114162759 [+   93]: account_scheduler_latency <-enqueue_entity
          <idle>-0     [00] 28991519114162853 [+   93]: __enqueue_entity <-enqueue_entity
          <idle>-0     [00] 28991519114162946 [+   93]: rb_insert_color <-__enqueue_entity
          <idle>-0     [00] 28991519114163040 [+  125]: hrtick_start_fair <-enqueue_task_fair
          <idle>-0     [00] 28991519114163165 [+   93]: check_preempt_curr_idle <-try_to_wake_up
          <idle>-0     [00] 28991519114163259 [+   62]: resched_task <-check_preempt_curr_idle
          <idle>-0     [00] 28991519114163321 [+  125]: _spin_unlock_irqrestore <-try_to_wake_up
          <idle>-0     [00] 28991519114163446 [+   93]: _spin_unlock_irqrestore <-__wake_up
          <idle>-0     [00] 28991519114163540 [+   93]: sk_reset_timer <-tcp_v4_rcv
          <idle>-0     [00] 28991519114163634 [+  125]: mod_timer <-sk_reset_timer
          <idle>-0     [00] 28991519114163759 [+  125]: __timer_stats_timer_set_start_info <-mod_timer
          <idle>-0     [00] 28991519114163884 [+  125]: __mod_timer <-mod_timer
          <idle>-0     [00] 28991519114164009 [+  125]: __timer_stats_timer_set_start_info <-__mod_timer
          <idle>-0     [00] 28991519114164134 [+  125]: lock_timer_base <-__mod_timer
          <idle>-0     [00] 28991519114164259 [+  125]: _spin_lock_irqsave <-lock_timer_base
          <idle>-0     [00] 28991519114164384 [+  125]: internal_add_timer <-__mod_timer
          <idle>-0     [00] 28991519114164509 [+  281]: _spin_unlock_irqrestore <-__mod_timer
          <idle>-0     [00] 28991519114164790 [+  156]: tasklet_action <-__do_softirq
          <idle>-0     [00] 28991519114164946 [+  125]: qdio_outbound_processing <-tasklet_action
          <idle>-0     [00] 28991519114165071 [+  250]: qdio_perf_stat_inc <-qdio_outbound_processing
          <idle>-0     [00] 28991519114165321 [+  187]: qeth_qdio_output_handler <-qdio_outbound_processing
          <idle>-0     [00] 28991519114165509 [+  125]: qeth_check_qdio_errors <-qeth_qdio_output_handler
          <idle>-0     [00] 28991519114165634 [+  125]: qeth_clear_output_buffer <-qeth_qdio_output_handler
          <idle>-0     [00] 28991519114165759 [+   93]: skb_dequeue <-qeth_clear_output_buffer
          <idle>-0     [00] 28991519114165853 [+  125]: _spin_lock_irqsave <-skb_dequeue
          <idle>-0     [00] 28991519114165978 [+  156]: _spin_unlock_irqrestore <-skb_dequeue
          <idle>-0     [00] 28991519114166134 [+  156]: dev_kfree_skb_any <-qeth_clear_output_buffer
          <idle>-0     [00] 28991519114166290 [+  125]: kfree_skb <-dev_kfree_skb_any
          <idle>-0     [00] 28991519114166415 [+  125]: __kfree_skb <-kfree_skb
          <idle>-0     [00] 28991519114166540 [+  125]: skb_release_all <-__kfree_skb
          <idle>-0     [00] 28991519114166665 [+  125]: dst_release <-skb_release_all
          <idle>-0     [00] 28991519114166790 [+  125]: skb_release_data <-skb_release_all
          <idle>-0     [00] 28991519114166915 [+  218]: kfree <-skb_release_data
          <idle>-0     [00] 28991519114167134 [+  156]: kmem_cache_free <-__kfree_skb
          <idle>-0     [00] 28991519114167290 [+  125]: skb_dequeue <-qeth_clear_output_buffer
          <idle>-0     [00] 28991519114167415 [+  125]: _spin_lock_irqsave <-skb_dequeue
          <idle>-0     [00] 28991519114167540 [+  125]: _spin_unlock_irqrestore <-skb_dequeue
          <idle>-0     [00] 28991519114167665 [+  312]: qeth_eddp_buf_release_contexts <-qeth_clear_output_buffer
          <idle>-0     [00] 28991519114167978 [+  156]: qeth_switch_to_nonpacking_if_needed <-qeth_qdio_output_handler
          <idle>-0     [00] 28991519114168134 [+  125]: __netif_schedule <-qeth_qdio_output_handler
          <idle>-0     [00] 28991519114168259 [+  156]: raise_softirq_irqoff <-__netif_schedule
          <idle>-0     [00] 28991519114168415 [+  125]: del_timer <-qdio_outbound_processing
          <idle>-0     [00] 28991519114168540 [+   93]: lock_timer_base <-del_timer
          <idle>-0     [00] 28991519114168634 [+  156]: _spin_lock_irqsave <-lock_timer_base
          <idle>-0     [00] 28991519114168790 [+  218]: _spin_unlock_irqrestore <-del_timer
          <idle>-0     [00] 28991519114169009 [+  187]: net_tx_action <-__do_softirq
          <idle>-0     [00] 28991519114169196 [+  125]: _spin_trylock <-net_tx_action
          <idle>-0     [00] 28991519114169321 [+  125]: __qdisc_run <-net_tx_action
          <idle>-0     [00] 28991519114169446 [+  156]: pfifo_fast_dequeue <-__qdisc_run
          <idle>-0     [00] 28991519114169603 [+   93]: account_system_vtime <-__do_softirq
          <idle>-0     [00] 28991519114169696 [+  125]: account_system_time <-account_system_vtime
          <idle>-0     [00] 28991519114169821 [+   93]: acct_update_integrals <-account_system_time
          <idle>-0     [00] 28991519114169915 [+  125]: _local_bh_enable <-__do_softirq
          <idle>-0     [00] 28991519114170040 [+  187]: idle_cpu <-irq_exit
          <idle>-0     [00] 28991519114170228 [+  125]: tick_nohz_restart_sched_tick <-cpu_idle
          <idle>-0     [00] 28991519114170353 [+   93]: tick_nohz_stop_idle <-tick_nohz_restart_sched_tick
          <idle>-0     [00] 28991519114170446 [+   93]: select_nohz_load_balancer <-tick_nohz_restart_sched_tick
          <idle>-0     [00] 28991519114170540 [+   93]: ktime_get <-tick_nohz_restart_sched_tick
          <idle>-0     [00] 28991519114170634 [+  125]: ktime_get_ts <-ktime_get
          <idle>-0     [00] 28991519114170759 [+   62]: getnstimeofday <-ktime_get_ts
          <idle>-0     [00] 28991519114170821 [+  156]: read_tod_clock <-getnstimeofday
          <idle>-0     [00] 28991519114170978 [+   93]: set_normalized_timespec <-ktime_get_ts
          <idle>-0     [00] 28991519114171071 [+  125]: tick_do_update_jiffies64 <-tick_nohz_restart_sched_tick
          <idle>-0     [00] 28991519114171196 [+   93]: hrtimer_cancel <-tick_nohz_restart_sched_tick
          <idle>-0     [00] 28991519114171290 [+   93]: hrtimer_try_to_cancel <-hrtimer_cancel
          <idle>-0     [00] 28991519114171384 [+   62]: lock_hrtimer_base <-hrtimer_try_to_cancel
          <idle>-0     [00] 28991519114171446 [+  125]: _spin_lock_irqsave <-lock_hrtimer_base
          <idle>-0     [00] 28991519114171571 [+   93]: __remove_hrtimer <-hrtimer_try_to_cancel
          <idle>-0     [00] 28991519114171665 [+   93]: rb_next <-__remove_hrtimer
          <idle>-0     [00] 28991519114171759 [+   93]: hrtimer_force_reprogram <-__remove_hrtimer
          <idle>-0     [00] 28991519114171853 [+   93]: tick_program_event <-hrtimer_force_reprogram
          <idle>-0     [00] 28991519114171946 [+   93]: tick_dev_program_event <-tick_program_event
          <idle>-0     [00] 28991519114172040 [+  125]: ktime_get <-tick_dev_program_event
          <idle>-0     [00] 28991519114172165 [+   62]: ktime_get_ts <-ktime_get
          <idle>-0     [00] 28991519114172228 [+   93]: getnstimeofday <-ktime_get_ts
          <idle>-0     [00] 28991519114172321 [+   93]: read_tod_clock <-getnstimeofday
          <idle>-0     [00] 28991519114172415 [+  156]: set_normalized_timespec <-ktime_get_ts
          <idle>-0     [00] 28991519114172571 [+   93]: clockevents_program_event <-tick_dev_program_event
          <idle>-0     [00] 28991519114172665 [+  125]: s390_next_event <-clockevents_program_event
          <idle>-0     [00] 28991519114172790 [+  125]: rb_erase <-__remove_hrtimer
          <idle>-0     [00] 28991519114172915 [+   93]: _spin_unlock_irqrestore <-hrtimer_try_to_cancel
          <idle>-0     [00] 28991519114173009 [+   93]: hrtimer_forward <-tick_nohz_restart_sched_tick
          <idle>-0     [00] 28991519114173103 [+  125]: hrtimer_start <-tick_nohz_restart_sched_tick
          <idle>-0     [00] 28991519114173228 [+   62]: lock_hrtimer_base <-hrtimer_start
          <idle>-0     [00] 28991519114173290 [+  125]: _spin_lock_irqsave <-lock_hrtimer_base
          <idle>-0     [00] 28991519114173415 [+   93]: __timer_stats_hrtimer_set_start_info <-hrtimer_start
          <idle>-0     [00] 28991519114173509 [+   93]: enqueue_hrtimer <-hrtimer_start
          <idle>-0     [00] 28991519114173603 [+   93]: hrtimer_reprogram <-enqueue_hrtimer
          <idle>-0     [00] 28991519114173696 [+   93]: tick_program_event <-hrtimer_reprogram
          <idle>-0     [00] 28991519114173790 [+   93]: tick_dev_program_event <-tick_program_event
          <idle>-0     [00] 28991519114173884 [+   62]: ktime_get <-tick_dev_program_event
          <idle>-0     [00] 28991519114173946 [+   93]: ktime_get_ts <-ktime_get
          <idle>-0     [00] 28991519114174040 [+   93]: getnstimeofday <-ktime_get_ts
          <idle>-0     [00] 28991519114174134 [+   93]: read_tod_clock <-getnstimeofday
          <idle>-0     [00] 28991519114174228 [+   93]: set_normalized_timespec <-ktime_get_ts
          <idle>-0     [00] 28991519114174321 [+  125]: clockevents_program_event <-tick_dev_program_event
          <idle>-0     [00] 28991519114174446 [+  125]: s390_next_event <-clockevents_program_event
          <idle>-0     [00] 28991519114174571 [+   93]: rb_insert_color <-enqueue_hrtimer
          <idle>-0     [00] 28991519114174665 [+  156]: _spin_unlock_irqrestore <-hrtimer_start
          <idle>-0     [00] 28991519114174821 [+  125]: schedule <-cpu_idle
          <idle>-0     [00] 28991519114174946 [+   93]: _spin_lock <-schedule
          <idle>-0     [00] 28991519114175040 [+  125]: sched_clock_cpu <-schedule
          <idle>-0     [00] 28991519114175165 [+  125]: sched_clock <-sched_clock_cpu
          <idle>-0     [00] 28991519114175290 [+   93]: put_prev_task_idle <-schedule
          <idle>-0     [00] 28991519114175384 [+   93]: pick_next_task_fair <-schedule
          <idle>-0     [00] 28991519114175478 [+   93]: set_next_entity <-pick_next_task_fair
          <idle>-0     [00] 28991519114175571 [+   93]: __dequeue_entity <-set_next_entity
          <idle>-0     [00] 28991519114175665 [+   93]: rb_next <-__dequeue_entity
          <idle>-0     [00] 28991519114175759 [+  125]: rb_erase <-__dequeue_entity
          <idle>-0     [00] 28991519114175884 [+  187]: hrtick_start_fair <-pick_next_task_fair
          <idle>-0     [00] 28991519114176071 [+  187]: _spin_trylock <-tracing_record_cmdline
            perl-2581  [00] 28991519114176259 [+  125]: finish_task_switch <-schedule
            perl-2581  [00] 28991519114176384 [+   93]: account_vtime <-finish_task_switch
            perl-2581  [00] 28991519114176478 [+   93]: account_user_time <-account_vtime
            perl-2581  [00] 28991519114176571 [+   93]: acct_update_integrals <-account_user_time
            perl-2581  [00] 28991519114176665 [+  125]: account_system_time <-account_vtime
            perl-2581  [00] 28991519114176790 [+  156]: acct_update_integrals <-account_system_time
            perl-2581  [00] 28991519114176946 [+  125]: lock_sock_nested <-sk_wait_data
            perl-2581  [00] 28991519114177071 [+  125]: _spin_lock_bh <-lock_sock_nested
            perl-2581  [00] 28991519114177196 [+  125]: local_bh_disable <-_spin_lock_bh
            perl-2581  [00] 28991519114177321 [+  187]: local_bh_enable <-lock_sock_nested
            perl-2581  [00] 28991519114177509 [+  156]: finish_wait <-sk_wait_data
            perl-2581  [00] 28991519114177665 [+  125]: tcp_prequeue_process <-tcp_recvmsg
            perl-2581  [00] 28991519114177790 [+  156]: local_bh_disable <-tcp_prequeue_process
            perl-2581  [00] 28991519114177946 [+  125]: tcp_v4_do_rcv <-tcp_prequeue_process
            perl-2581  [00] 28991519114178071 [+  125]: tcp_rcv_established <-tcp_v4_do_rcv
            perl-2581  [00] 28991519114178196 [+  156]: local_bh_enable <-tcp_rcv_established
            perl-2581  [00] 28991519114178353 [+  125]: skb_copy_datagram_iovec <-tcp_rcv_established
            perl-2581  [00] 28991519114178478 [+  125]: memcpy_toiovec <-skb_copy_datagram_iovec
            perl-2581  [00] 28991519114178603 [+  125]: copy_to_user_mvcos_check <-memcpy_toiovec
            perl-2581  [00] 28991519114178728 [+  187]: copy_to_user_std <-copy_to_user_mvcos_check
            perl-2581  [00] 28991519114178915 [+   93]: tcp_rcv_space_adjust <-tcp_rcv_established
            perl-2581  [00] 28991519114179009 [+  156]: local_bh_disable <-tcp_rcv_established
            perl-2581  [00] 28991519114179165 [+  125]: get_seconds <-tcp_rcv_established
            perl-2581  [00] 28991519114179290 [+  156]: tcp_event_data_recv <-tcp_rcv_established
            perl-2581  [00] 28991519114179446 [+  187]: tcp_ack <-tcp_rcv_established
            perl-2581  [00] 28991519114179634 [+  156]: __kfree_skb <-tcp_ack
            perl-2581  [00] 28991519114179790 [+   93]: skb_release_all <-__kfree_skb
            perl-2581  [00] 28991519114179884 [+  125]: dst_release <-skb_release_all
            perl-2581  [00] 28991519114180009 [+  156]: skb_release_data <-skb_release_all
            perl-2581  [00] 28991519114180165 [+  187]: kfree <-skb_release_data
            perl-2581  [00] 28991519114180353 [+  187]: kmem_cache_free <-__kfree_skb
            perl-2581  [00] 28991519114180540 [+  125]: tcp_rtt_estimator <-tcp_ack
            perl-2581  [00] 28991519114180665 [+  156]: bictcp_acked <-tcp_ack
            perl-2581  [00] 28991519114180821 [+   93]: bictcp_cong_avoid <-tcp_ack
            perl-2581  [00] 28991519114180915 [+  156]: tcp_is_cwnd_limited <-bictcp_cong_avoid
            perl-2581  [00] 28991519114181071 [+  125]: tcp_current_mss <-tcp_rcv_established
            perl-2581  [00] 28991519114181196 [+  125]: tcp_established_options <-tcp_current_mss
            perl-2581  [00] 28991519114181321 [+  125]: __tcp_push_pending_frames <-tcp_rcv_established
            perl-2581  [00] 28991519114181446 [+  125]: __tcp_ack_snd_check <-tcp_rcv_established
            perl-2581  [00] 28991519114181571 [+  125]: tcp_send_delayed_ack <-__tcp_ack_snd_check
            perl-2581  [00] 28991519114181696 [+  125]: sk_reset_timer <-tcp_send_delayed_ack
            perl-2581  [00] 28991519114181821 [+  125]: mod_timer <-sk_reset_timer
            perl-2581  [00] 28991519114181946 [+  125]: __timer_stats_timer_set_start_info <-mod_timer
            perl-2581  [00] 28991519114182071 [+   93]: __mod_timer <-mod_timer
            perl-2581  [00] 28991519114182165 [+  156]: __timer_stats_timer_set_start_info <-__mod_timer
            perl-2581  [00] 28991519114182321 [+   93]: lock_timer_base <-__mod_timer
            perl-2581  [00] 28991519114182415 [+  156]: _spin_lock_irqsave <-lock_timer_base
            perl-2581  [00] 28991519114182571 [+   93]: internal_add_timer <-__mod_timer
            perl-2581  [00] 28991519114182665 [+  156]: _spin_unlock_irqrestore <-__mod_timer
            perl-2581  [00] 28991519114182821 [+   93]: __kfree_skb <-tcp_rcv_established
            perl-2581  [00] 28991519114182915 [+  125]: skb_release_all <-__kfree_skb
            perl-2581  [00] 28991519114183040 [+  125]: dst_release <-skb_release_all
            perl-2581  [00] 28991519114183165 [+  125]: skb_release_data <-skb_release_all
            perl-2581  [00] 28991519114183290 [+  187]: kfree <-skb_release_data
            perl-2581  [00] 28991519114183478 [+  187]: kmem_cache_free <-__kfree_skb
            perl-2581  [00] 28991519114183665 [+  187]: local_bh_enable <-tcp_prequeue_process
            perl-2581  [00] 28991519114183853 [+  125]: tcp_cleanup_rbuf <-tcp_recvmsg
            perl-2581  [00] 28991519114183978 [+  156]: __tcp_select_window <-tcp_cleanup_rbuf
            perl-2581  [00] 28991519114184134 [+  125]: release_sock <-tcp_recvmsg
            perl-2581  [00] 28991519114184259 [+   93]: _spin_lock_bh <-release_sock
            perl-2581  [00] 28991519114184353 [+  125]: local_bh_disable <-_spin_lock_bh
            perl-2581  [00] 28991519114184478 [+  156]: _spin_unlock_bh <-release_sock
            perl-2581  [00] 28991519114184634 [+  218]: local_bh_enable_ip <-_spin_unlock_bh
            perl-2581  [00] 28991519114184853 [+  156]: dnotify_parent <-vfs_read
            perl-2581  [00] 28991519114185009 [+  125]: _spin_lock <-dnotify_parent
            perl-2581  [00] 28991519114185134 [+  125]: inotify_dentry_parent_queue_event <-vfs_read
            perl-2581  [00] 28991519114185259 [+ 1687]: inotify_inode_queue_event <-vfs_read

And this is for 2.6.16:

# tracer: ftrace
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |

           <...>-2804  [00] 28994586831213199 [+   93]: sys_write <-sysc_noemu
           <...>-2804  [00] 28994586831213292 [+  218]: fget_light <-sys_write
           <...>-2804  [00] 28994586831213511 [+  156]: apparmor_file_permission <-sys_write
           <...>-2804  [00] 28994586831213667 [+  125]: sock_aio_write <-sys_write
           <...>-2804  [00] 28994586831213792 [+  125]: dummy_socket_sendmsg <-sock_aio_write
           <...>-2804  [00] 28994586831213917 [+  125]: inet_sendmsg <-sock_aio_write
           <...>-2804  [00] 28994586831214042 [+   93]: tcp_sendmsg <-inet_sendmsg
           <...>-2804  [00] 28994586831214136 [+  125]: lock_sock <-tcp_sendmsg
           <...>-2804  [00] 28994586831214261 [+  125]: _spin_lock_bh <-lock_sock
           <...>-2804  [00] 28994586831214386 [+  125]: _spin_unlock_bh <-lock_sock
           <...>-2804  [00] 28994586831214511 [+  187]: local_bh_enable <-_spin_unlock_bh
           <...>-2804  [00] 28994586831214699 [+  156]: tcp_current_mss <-tcp_sendmsg
           <...>-2804  [00] 28994586831214855 [+  125]: __alloc_skb <-tcp_sendmsg
           <...>-2804  [00] 28994586831214980 [+  156]: kmem_cache_alloc <-__alloc_skb
           <...>-2804  [00] 28994586831215136 [+  218]: __kmalloc <-__alloc_skb
           <...>-2804  [00] 28994586831215355 [+  187]: memset <-__alloc_skb
           <...>-2804  [00] 28994586831215542 [+  125]: copy_from_user_mvcos_check <-tcp_sendmsg
           <...>-2804  [00] 28994586831215667 [+  218]: copy_from_user_std <-copy_from_user_mvcos_check
           <...>-2804  [00] 28994586831215886 [+  125]: __tcp_push_pending_frames <-tcp_sendmsg
           <...>-2804  [00] 28994586831216011 [+  125]: tcp_transmit_skb <-__tcp_push_pending_frames
           <...>-2804  [00] 28994586831216136 [+  156]: skb_clone <-tcp_transmit_skb
           <...>-2804  [00] 28994586831216292 [+  250]: memcpy <-skb_clone
           <...>-2804  [00] 28994586831216542 [+  156]: tcp_v4_send_check <-tcp_transmit_skb
           <...>-2804  [00] 28994586831216699 [+  187]: ip_queue_xmit <-tcp_transmit_skb
           <...>-2804  [00] 28994586831216886 [+  187]: ip_output <-ip_queue_xmit
           <...>-2804  [00] 28994586831217074 [+  125]: dev_queue_xmit <-ip_output
           <...>-2804  [00] 28994586831217199 [+  125]: _spin_lock <-dev_queue_xmit
           <...>-2804  [00] 28994586831217324 [+  125]: pfifo_fast_enqueue <-dev_queue_xmit
           <...>-2804  [00] 28994586831217449 [+  125]: __qdisc_run <-dev_queue_xmit
           <...>-2804  [00] 28994586831217574 [+  156]: pfifo_fast_dequeue <-__qdisc_run
           <...>-2804  [00] 28994586831217730 [+  125]: _spin_trylock <-__qdisc_run
           <...>-2804  [00] 28994586831217855 [+  156]: dev_hard_start_xmit <-__qdisc_run
           <...>-2804  [00] 28994586831218011 [+  250]: qeth_hard_start_xmit <-dev_hard_start_xmit
           <...>-2804  [00] 28994586831218261 [+  125]: qeth_fill_header <-qeth_hard_start_xmit
           <...>-2804  [00] 28994586831218386 [+  156]: memset <-qeth_fill_header
           <...>-2804  [00] 28994586831218542 [+  187]: memset <-qeth_fill_header
           <...>-2804  [00] 28994586831218730 [+  125]: skb_queue_tail <-qeth_hard_start_xmit
           <...>-2804  [00] 28994586831218855 [+  125]: _spin_lock_irqsave <-skb_queue_tail
           <...>-2804  [00] 28994586831218980 [+  156]: _spin_unlock_irqrestore <-skb_queue_tail
           <...>-2804  [00] 28994586831219136 [+  218]: qeth_flush_buffers <-qeth_hard_start_xmit
           <...>-2804  [00] 28994586831219355 [+  875]: do_QDIO <-qeth_flush_buffers
           <...>-2804  [00] 28994586831220230 [+   93]: mod_timer <-do_QDIO
           <...>-2804  [00] 28994586831220324 [+  187]: _spin_lock_irqsave <-mod_timer
           <...>-2804  [00] 28994586831220511 [+  187]: _spin_unlock_irqrestore <-mod_timer
           <...>-2804  [00] 28994586831220699 [+  125]: raise_softirq_irqoff <-qeth_hard_start_xmit
           <...>-2804  [00] 28994586831220824 [+  156]: _spin_lock <-__qdisc_run
           <...>-2804  [00] 28994586831220980 [+  125]: pfifo_fast_dequeue <-__qdisc_run
           <...>-2804  [00] 28994586831221105 [+  156]: local_bh_enable <-dev_queue_xmit
           <...>-2804  [00] 28994586831221261 [+  156]: do_softirq <-local_bh_enable
           <...>-2804  [00] 28994586831221417 [+   93]: account_system_vtime <-do_softirq
           <...>-2804  [00] 28994586831221511 [+   93]: account_system_time <-account_system_vtime
           <...>-2804  [00] 28994586831221605 [+  125]: acct_update_integrals <-account_system_time
           <...>-2804  [00] 28994586831221730 [+  156]: __do_softirq <-do_softirq
           <...>-2804  [00] 28994586831221886 [+  156]: net_tx_action <-__do_softirq
           <...>-2804  [00] 28994586831222042 [+  125]: _spin_trylock <-net_tx_action
           <...>-2804  [00] 28994586831222167 [+  125]: __qdisc_run <-net_tx_action
           <...>-2804  [00] 28994586831222292 [+  156]: pfifo_fast_dequeue <-__qdisc_run
           <...>-2804  [00] 28994586831222449 [+   93]: account_system_vtime <-do_softirq
           <...>-2804  [00] 28994586831222542 [+  125]: account_system_time <-account_system_vtime
           <...>-2804  [00] 28994586831222667 [+  156]: acct_update_integrals <-account_system_time
           <...>-2804  [00] 28994586831222824 [+  125]: sk_reset_timer <-__tcp_push_pending_frames
           <...>-2804  [00] 28994586831222949 [+  156]: mod_timer <-sk_reset_timer
           <...>-2804  [00] 28994586831223105 [+  125]: release_sock <-tcp_sendmsg
           <...>-2804  [00] 28994586831223230 [+   93]: _spin_lock_bh <-release_sock
           <...>-2804  [00] 28994586831223324 [+  156]: _spin_unlock_bh <-release_sock
           <...>-2804  [00] 28994586831223480 [+  187]: local_bh_enable <-_spin_unlock_bh
           <...>-2804  [00] 28994586831223667 [+   93]: dnotify_parent <-sys_write
           <...>-2804  [00] 28994586831223761 [+  125]: _spin_lock <-dnotify_parent
           <...>-2804  [00] 28994586831223886 [+  156]: inotify_dentry_parent_queue_event <-sys_write
           <...>-2804  [00] 28994586831224042 [+  812]: inotify_inode_queue_event <-sys_write
           <...>-2804  [00] 28994586831224855 [+   93]: sys_read <-sysc_noemu
           <...>-2804  [00] 28994586831224949 [+  187]: fget_light <-sys_read
           <...>-2804  [00] 28994586831225136 [+  125]: apparmor_file_permission <-sys_read
           <...>-2804  [00] 28994586831225261 [+  125]: sock_aio_read <-sys_read
           <...>-2804  [00] 28994586831225386 [+  156]: dummy_socket_recvmsg <-sock_aio_read
           <...>-2804  [00] 28994586831225542 [+   93]: sock_common_recvmsg <-sock_aio_read
           <...>-2804  [00] 28994586831225636 [+  125]: tcp_recvmsg <-sock_common_recvmsg
           <...>-2804  [00] 28994586831225761 [+  125]: lock_sock <-tcp_recvmsg
           <...>-2804  [00] 28994586831225886 [+  125]: _spin_lock_bh <-lock_sock
           <...>-2804  [00] 28994586831226011 [+  125]: _spin_unlock_bh <-lock_sock
           <...>-2804  [00] 28994586831226136 [+  250]: local_bh_enable <-_spin_unlock_bh
           <...>-2804  [00] 28994586831226386 [+  125]: sk_wait_data <-tcp_recvmsg
           <...>-2804  [00] 28994586831226511 [+  125]: prepare_to_wait <-sk_wait_data
           <...>-2804  [00] 28994586831226636 [+  156]: _spin_lock_irqsave <-prepare_to_wait
           <...>-2804  [00] 28994586831226792 [+  156]: _spin_unlock_irqrestore <-prepare_to_wait
           <...>-2804  [00] 28994586831226949 [+   93]: _spin_lock_bh <-sk_wait_data
           <...>-2804  [00] 28994586831227042 [+  125]: _spin_unlock_bh <-sk_wait_data
           <...>-2804  [00] 28994586831227167 [+  187]: local_bh_enable <-_spin_unlock_bh
           <...>-2804  [00] 28994586831227355 [+  125]: schedule_timeout <-sk_wait_data
           <...>-2804  [00] 28994586831227480 [+   93]: schedule <-schedule_timeout
           <...>-2804  [00] 28994586831227574 [+  156]: profile_hit <-schedule
           <...>-2804  [00] 28994586831227730 [+  156]: sched_clock <-schedule
           <...>-2804  [00] 28994586831227886 [+  281]: _spin_lock_irq <-schedule
          <idle>-0     [00] 28994586831228167 [+   93]: account_vtime <-schedule
          <idle>-0     [00] 28994586831228261 [+   93]: account_user_time <-account_vtime
          <idle>-0     [00] 28994586831228355 [+   93]: account_system_time <-account_vtime
          <idle>-0     [00] 28994586831228449 [+  218]: acct_update_integrals <-account_system_time
          <idle>-0     [00] 28994586831228667 [+   93]: notifier_call_chain <-cpu_idle
          <idle>-0     [00] 28994586831228761 [+   93]: nohz_idle_notify <-notifier_call_chain
          <idle>-0     [00] 28994586831228855 [+  156]: rcu_needs_cpu <-nohz_idle_notify
          <idle>-0     [00] 28994586831229011 [+   62]: next_timer_interrupt <-nohz_idle_notify
          <idle>-0     [00] 28994586831229074 [+   93]: hrtimer_get_next_event <-next_timer_interrupt
          <idle>-0     [00] 28994586831229167 [+  125]: _spin_lock_irqsave <-hrtimer_get_next_event
          <idle>-0     [00] 28994586831229292 [+   93]: _spin_unlock_irqrestore <-hrtimer_get_next_event
          <idle>-0     [00] 28994586831229386 [+   93]: _spin_lock_irqsave <-hrtimer_get_next_event
          <idle>-0     [00] 28994586831229480 [+   93]: _spin_unlock_irqrestore <-hrtimer_get_next_event
          <idle>-0     [00] 28994586831229574 [+  125]: ktime_get <-hrtimer_get_next_event
          <idle>-0     [00] 28994586831229699 [+   93]: getnstimeofday <-ktime_get
          <idle>-0     [00] 28994586831229792 [+  156]: do_gettimeofday <-getnstimeofday
          <idle>-0     [00] 28994586831229949 [+  156]: set_normalized_timespec <-ktime_get
          <idle>-0     [00] 28994586831230105 [+  125]: ns_to_timespec <-next_timer_interrupt
          <idle>-0     [00] 28994586831230230 [+  156]: _spin_lock <-next_timer_interrupt
          <idle>-0     [00] 28994586831230386 [+212406]: vtimer_idle_notify <-notifier_call_chain
          <idle>-0     [00] 28994586831442792 [+   93]: do_IRQ <-io_return
          <idle>-0     [00] 28994586831442886 [+   62]: account_system_vtime <-do_IRQ
          <idle>-0     [00] 28994586831442949 [+  125]: account_system_time <-account_system_vtime
          <idle>-0     [00] 28994586831443074 [+  250]: acct_update_integrals <-account_system_time
          <idle>-0     [00] 28994586831443324 [+   93]: do_monitor_call <-sysc_return
          <idle>-0     [00] 28994586831443417 [+   62]: notifier_call_chain <-do_monitor_call
          <idle>-0     [00] 28994586831443480 [+  156]: nohz_idle_notify <-notifier_call_chain
          <idle>-0     [00] 28994586831443636 [+  125]: vtimer_idle_notify <-notifier_call_chain
          <idle>-0     [00] 28994586831443761 [+  125]: do_adapter_IO <-do_IRQ
          <idle>-0     [00] 28994586831443886 [+  500]: tiqdio_thinint_handler <-do_adapter_IO
          <idle>-0     [00] 28994586831444386 [+  156]: qeth_qdio_output_handler <-tiqdio_thinint_handler
          <idle>-0     [00] 28994586831444542 [+   62]: skb_dequeue <-qeth_qdio_output_handler
          <idle>-0     [00] 28994586831444605 [+  125]: _spin_lock_irqsave <-skb_dequeue
          <idle>-0     [00] 28994586831444730 [+  125]: _spin_unlock_irqrestore <-skb_dequeue
          <idle>-0     [00] 28994586831444855 [+   93]: raise_softirq_irqoff <-qeth_qdio_output_handler
          <idle>-0     [00] 28994586831444949 [+   93]: skb_dequeue <-qeth_qdio_output_handler
          <idle>-0     [00] 28994586831445042 [+   93]: _spin_lock_irqsave <-skb_dequeue
          <idle>-0     [00] 28994586831445136 [+   93]: _spin_unlock_irqrestore <-skb_dequeue
          <idle>-0     [00] 28994586831445230 [+  250]: qeth_eddp_buf_release_contexts <-qeth_qdio_output_handler
          <idle>-0     [00] 28994586831445480 [+  125]: raise_softirq_irqoff <-qeth_qdio_output_handler
          <idle>-0     [00] 28994586831445605 [+   93]: del_timer <-tiqdio_thinint_handler
          <idle>-0     [00] 28994586831445699 [+  125]: _spin_lock_irqsave <-del_timer
          <idle>-0     [00] 28994586831445824 [+  218]: _spin_unlock_irqrestore <-del_timer
          <idle>-0     [00] 28994586831446042 [+  250]: qeth_qdio_input_handler <-tiqdio_thinint_handler
          <idle>-0     [00] 28994586831446292 [+   62]: __alloc_skb <-qeth_qdio_input_handler
          <idle>-0     [00] 28994586831446355 [+  125]: kmem_cache_alloc <-__alloc_skb
          <idle>-0     [00] 28994586831446480 [+  125]: __kmalloc <-__alloc_skb
          <idle>-0     [00] 28994586831446605 [+  156]: memset <-__alloc_skb
          <idle>-0     [00] 28994586831446761 [+  187]: memcpy <-qeth_qdio_input_handler
          <idle>-0     [00] 28994586831446949 [+  500]: netif_rx <-qeth_qdio_input_handler
          <idle>-0     [00] 28994586831447449 [+   93]: irq_exit <-do_IRQ
          <idle>-0     [00] 28994586831447542 [+   93]: account_system_vtime <-irq_exit
          <idle>-0     [00] 28994586831447636 [+   93]: account_system_time <-account_system_vtime
          <idle>-0     [00] 28994586831447730 [+   93]: acct_update_integrals <-account_system_time
          <idle>-0     [00] 28994586831447824 [+   93]: do_softirq <-irq_exit
          <idle>-0     [00] 28994586831447917 [+   62]: account_system_vtime <-do_softirq
          <idle>-0     [00] 28994586831447980 [+   93]: account_system_time <-account_system_vtime
          <idle>-0     [00] 28994586831448074 [+  125]: acct_update_integrals <-account_system_time
          <idle>-0     [00] 28994586831448199 [+   93]: __do_softirq <-do_softirq
          <idle>-0     [00] 28994586831448292 [+   93]: net_tx_action <-__do_softirq
          <idle>-0     [00] 28994586831448386 [+  125]: __kfree_skb <-net_tx_action
          <idle>-0     [00] 28994586831448511 [+  156]: sock_wfree <-__kfree_skb
          <idle>-0     [00] 28994586831448667 [+   93]: _spin_trylock <-net_tx_action
          <idle>-0     [00] 28994586831448761 [+   62]: __qdisc_run <-net_tx_action
          <idle>-0     [00] 28994586831448824 [+  156]: pfifo_fast_dequeue <-__qdisc_run
          <idle>-0     [00] 28994586831448980 [+   93]: net_rx_action <-__do_softirq
          <idle>-0     [00] 28994586831449074 [+  156]: process_backlog <-net_rx_action
          <idle>-0     [00] 28994586831449230 [+  156]: ip_rcv <-process_backlog
          <idle>-0     [00] 28994586831449386 [+  125]: ip_route_input <-ip_rcv
          <idle>-0     [00] 28994586831449511 [+  125]: ip_local_deliver <-ip_rcv
          <idle>-0     [00] 28994586831449636 [+  125]: tcp_v4_rcv <-ip_local_deliver
          <idle>-0     [00] 28994586831449761 [+  125]: _read_lock <-tcp_v4_rcv
          <idle>-0     [00] 28994586831449886 [+   93]: dummy_socket_sock_rcv_skb <-tcp_v4_rcv
          <idle>-0     [00] 28994586831449980 [+   93]: _spin_lock <-tcp_v4_rcv
          <idle>-0     [00] 28994586831450074 [+   93]: __wake_up <-tcp_v4_rcv
          <idle>-0     [00] 28994586831450167 [+   93]: _spin_lock_irqsave <-__wake_up
          <idle>-0     [00] 28994586831450261 [+   93]: autoremove_wake_function <-__wake_up
          <idle>-0     [00] 28994586831450355 [+   93]: default_wake_function <-autoremove_wake_function
          <idle>-0     [00] 28994586831450449 [+  125]: _spin_lock <-default_wake_function
          <idle>-0     [00] 28994586831450574 [+  187]: sched_clock <-default_wake_function
          <idle>-0     [00] 28994586831450761 [+  125]: resched_task <-default_wake_function
          <idle>-0     [00] 28994586831450886 [+   93]: _spin_unlock_irqrestore <-default_wake_function
          <idle>-0     [00] 28994586831450980 [+   93]: _spin_unlock_irqrestore <-__wake_up
          <idle>-0     [00] 28994586831451074 [+   93]: sk_reset_timer <-tcp_v4_rcv
          <idle>-0     [00] 28994586831451167 [+   93]: mod_timer <-sk_reset_timer
          <idle>-0     [00] 28994586831451261 [+  125]: _spin_lock_irqsave <-mod_timer
          <idle>-0     [00] 28994586831451386 [+  156]: _spin_unlock_irqrestore <-mod_timer
          <idle>-0     [00] 28994586831451542 [+   93]: account_system_vtime <-do_softirq
          <idle>-0     [00] 28994586831451636 [+   93]: account_system_time <-account_system_vtime
          <idle>-0     [00] 28994586831451730 [+  156]: acct_update_integrals <-account_system_time
          <idle>-0     [00] 28994586831451886 [+  125]: schedule <-cpu_idle
          <idle>-0     [00] 28994586831452011 [+   93]: profile_hit <-schedule
          <idle>-0     [00] 28994586831452105 [+  125]: sched_clock <-schedule
          <idle>-0     [00] 28994586831452230 [+  343]: _spin_lock_irq <-schedule
           <...>-2804  [00] 28994586831452574 [+   93]: account_vtime <-schedule
           <...>-2804  [00] 28994586831452667 [+   62]: account_user_time <-account_vtime
           <...>-2804  [00] 28994586831452730 [+  125]: account_system_time <-account_vtime
           <...>-2804  [00] 28994586831452855 [+  125]: acct_update_integrals <-account_system_time
           <...>-2804  [00] 28994586831452980 [+   93]: _spin_lock_bh <-sk_wait_data
           <...>-2804  [00] 28994586831453074 [+   93]: _spin_unlock_bh <-sk_wait_data
           <...>-2804  [00] 28994586831453167 [+   93]: local_bh_enable <-_spin_unlock_bh
           <...>-2804  [00] 28994586831453261 [+  125]: finish_wait <-sk_wait_data
           <...>-2804  [00] 28994586831453386 [+   93]: tcp_v4_do_rcv <-tcp_recvmsg
           <...>-2804  [00] 28994586831453480 [+   93]: tcp_rcv_established <-tcp_v4_do_rcv
           <...>-2804  [00] 28994586831453574 [+   93]: local_bh_enable <-tcp_rcv_established
           <...>-2804  [00] 28994586831453667 [+   93]: skb_copy_datagram_iovec <-tcp_rcv_established
           <...>-2804  [00] 28994586831453761 [+   93]: memcpy_toiovec <-skb_copy_datagram_iovec
           <...>-2804  [00] 28994586831453855 [+   62]: copy_to_user_mvcos_check <-memcpy_toiovec
           <...>-2804  [00] 28994586831453917 [+  187]: copy_to_user_std <-copy_to_user_mvcos_check
           <...>-2804  [00] 28994586831454105 [+  125]: tcp_ack <-tcp_rcv_established
           <...>-2804  [00] 28994586831454230 [+  125]: __kfree_skb <-tcp_ack
           <...>-2804  [00] 28994586831454355 [+  125]: kfree <-__kfree_skb
           <...>-2804  [00] 28994586831454480 [+  187]: kmem_cache_free <-__kfree_skb
           <...>-2804  [00] 28994586831454667 [+   93]: tcp_reno_cong_avoid <-tcp_ack
           <...>-2804  [00] 28994586831454761 [+   93]: tcp_current_mss <-tcp_rcv_established
           <...>-2804  [00] 28994586831454855 [+  156]: __tcp_push_pending_frames <-tcp_rcv_established
           <...>-2804  [00] 28994586831455011 [+   62]: tcp_send_delayed_ack <-tcp_rcv_established
           <...>-2804  [00] 28994586831455074 [+   93]: sk_reset_timer <-tcp_send_delayed_ack
           <...>-2804  [00] 28994586831455167 [+   93]: mod_timer <-sk_reset_timer
           <...>-2804  [00] 28994586831455261 [+   93]: _spin_lock_irqsave <-mod_timer
           <...>-2804  [00] 28994586831455355 [+   93]: _spin_unlock_irqrestore <-mod_timer
           <...>-2804  [00] 28994586831455449 [+  125]: __kfree_skb <-tcp_rcv_established
           <...>-2804  [00] 28994586831455574 [+   93]: kfree <-__kfree_skb
           <...>-2804  [00] 28994586831455667 [+  125]: kmem_cache_free <-__kfree_skb
           <...>-2804  [00] 28994586831455792 [+  156]: local_bh_enable <-tcp_recvmsg
           <...>-2804  [00] 28994586831455949 [+   93]: __tcp_select_window <-tcp_recvmsg
           <...>-2804  [00] 28994586831456042 [+   93]: release_sock <-tcp_recvmsg
           <...>-2804  [00] 28994586831456136 [+   93]: _spin_lock_bh <-release_sock
           <...>-2804  [00] 28994586831456230 [+   93]: _spin_unlock_bh <-release_sock
           <...>-2804  [00] 28994586831456324 [+  156]: local_bh_enable <-_spin_unlock_bh
           <...>-2804  [00] 28994586831456480 [+   93]: dnotify_parent <-sys_read
           <...>-2804  [00] 28994586831456574 [+  125]: _spin_lock <-dnotify_parent
           <...>-2804  [00] 28994586831456699 [+   62]: inotify_dentry_parent_queue_event <-sys_read
           <...>-2804  [00] 28994586831456761 [+ 1437]: inotify_inode_queue_event <-sys_read

Hmm. But the spinlock part of this seems to not really have changed.

Removing everything but the actual callchain info, and then doing a "diff" between your two roundtrips, and they look very different, and basically none of the difference seems to be due to spinlocks.

It seems to be due to a number of different things, but the bulk of the new costs seem to be in networking (and to some degree scheduling). There are smaller differences elsewhere, but the networking code _really_ blows up.

I don't know how much of some of these are "real" kernel changes, and how much of it is less inlining, but spinlocks don't seem to be the issue. Here's a quick walk-through (some of these get repeated a couple of times in your traces)

* Apparmor going through the generic security code and rw_verify_area:

apparmor_file_permission <-sys_write

becomes

security_file_permission <-rw_verify_area apparmor_file_permission <-security_file_permission aa_file_permission <-apparmor_file_permission

* the vfs write itself being deeper

sock_aio_write <-sys_write

becomes

vfs_write <-SyS_write
rw_verify_area <-vfs_write
do_sync_write <-vfs_write
sock_aio_write <-do_sync_write

* the socket code does totally new apparmor security things that were not in 2.6.16 at all:

security_socket_sendmsg <-sock_aio_write apparmor_socket_sendmsg <-security_socket_sendmsg aa_revalidate_sk <-apparmor_socket_sendmsg

* TCP doing more:

	__alloc_skb <-tcp_sendmsg
	..
	..
	ip_output <-ip_queue_xmit
	dev_queue_xmit <-ip_output

becomes

	tcp_established_options <-tcp_current_mss
	sk_stream_alloc_skb <-tcp_sendmsg
	__alloc_skb <-sk_stream_alloc_skb
	..
	tcp_init_tso_segs <-__tcp_push_pending_frames
	tcp_set_skb_tso_segs <-tcp_init_tso_segs
	..
	__skb_clone <-skb_clone
	__copy_skb_header <-__skb_clone
	tcp_established_options <-tcp_transmit_skb
	skb_push <-tcp_transmit_skb
	__tcp_select_window <-tcp_transmit_skb
	tcp_options_write <-tcp_transmit_skb
	..
	__sk_dst_check <-ip_queue_xmit
	skb_push <-ip_queue_xmit
	ip_local_out <-ip_queue_xmit
	__ip_local_out <-ip_local_out
	ip_output <-ip_local_out
	ip_finish_output <-ip_output
	skb_push <-ip_finish_output
	dev_queue_xmit <-ip_finish_output
	local_bh_disable <-dev_queue_xmit

* More TCP changes at tcp_ack time:

	kfree <-__kfree_skb
	kmem_cache_free <-__kfree_skb
	tcp_reno_cong_avoid <-tcp_ack
	tcp_current_mss <-tcp_rcv_established
	__tcp_push_pending_frames <-tcp_rcv_established
	tcp_send_delayed_ack <-tcp_rcv_established

becomes

skb_release_all <-__kfree_skb dst_release <-skb_release_all skb_release_data <-skb_release_all kfree <-skb_release_data kmem_cache_free <-__kfree_skb tcp_rtt_estimator <-tcp_ack bictcp_acked <-tcp_ack bictcp_cong_avoid <-tcp_ack tcp_is_cwnd_limited <-bictcp_cong_avoid tcp_current_mss <-tcp_rcv_established tcp_established_options <-tcp_current_mss __tcp_push_pending_frames <-tcp_rcv_established __tcp_ack_snd_check <-tcp_rcv_established tcp_send_delayed_ack <-__tcp_ack_snd_check

* The network driver doing more:

	qeth_hard_start_xmit <-dev_hard_start_xmit
	qeth_fill_header <-qeth_hard_start_xmit
	memset <-qeth_fill_header
	memset <-qeth_fill_header
	skb_queue_tail <-qeth_hard_start_xmit
	..
	mod_timer <-do_QDIO
	_spin_lock_irqsave <-mod_timer
	_spin_unlock_irqrestore <-mod_timer
	raise_softirq_irqoff <-qeth_hard_start_xmit
	..

becomes

	qeth_l3_hard_start_xmit <-dev_hard_start_xmit
	qeth_get_cast_type <-qeth_l3_hard_start_xmit
	qeth_get_priority_queue <-qeth_l3_hard_start_xmit
	skb_realloc_headroom <-qeth_l3_hard_start_xmit
	pskb_copy <-skb_realloc_headroom
	__alloc_skb <-pskb_copy
	kmem_cache_alloc <-__alloc_skb
	__kmalloc <-__alloc_skb
	skb_put <-pskb_copy
	copy_skb_header <-pskb_copy
	__copy_skb_header <-copy_skb_header
	skb_pull <-qeth_l3_hard_start_xmit
	skb_push <-qeth_l3_hard_start_xmit
	qeth_l3_fill_header <-qeth_l3_hard_start_xmit
	qeth_get_elements_no <-qeth_l3_hard_start_xmit
	qeth_do_send_packet <-qeth_l3_hard_start_xmit
	skb_queue_tail <-qeth_do_send_packet
	..
	qdio_perf_stat_inc <-do_QDIO
	qdio_kick_outbound_q <-do_QDIO
	qdio_perf_stat_inc <-qdio_kick_outbound_q
	__tasklet_schedule <-do_QDIO
	dev_kfree_skb_any <-qeth_l3_hard_start_xmit
	kfree_skb <-dev_kfree_skb_any
	__kfree_skb <-kfree_skb
	skb_release_all <-__kfree_skb
	dst_release <-skb_release_all
	sock_wfree <-skb_release_all
	skb_release_data <-skb_release_all
	__netif_schedule <-qeth_l3_hard_start_xmit
	raise_softirq_irqoff <-__netif_schedule
	..
	tasklet_action <-__do_softirq
	qdio_outbound_processing <-tasklet_action
	qdio_perf_stat_inc <-qdio_outbound_processing
	mod_timer <-qdio_outbound_processing

* the timer code doing more:

	__timer_stats_timer_set_start_info <-mod_timer
	__mod_timer <-mod_timer
	__timer_stats_timer_set_start_info <-__mod_timer
	lock_timer_base <-__mod_timer
	_spin_lock_irqsave <-lock_timer_base
	internal_add_timer <-__mod_timer
	_spin_unlock_irqrestore <-__mod_timer
	qdio_perf_stat_inc <-qdio_outbound_processing
	account_system_vtime <-__do_softirq

* the scheduler code doing way deeper chains:

profile_hit <-schedule
sched_clock <-schedule
_spin_lock_irq <-schedule
account_vtime <-schedule
account_user_time <-account_vtime

becomes

_spin_lock <-schedule sched_clock_cpu <-schedule sched_clock <-sched_clock_cpu deactivate_task <-schedule dequeue_task <-deactivate_task dequeue_task_fair <-dequeue_task dequeue_entity <-dequeue_task_fair update_curr <-dequeue_entity hrtick_start_fair <-dequeue_task_fair put_prev_task_fair <-schedule pick_next_task_fair <-schedule pick_next_task_rt <-schedule pick_next_task_fair <-schedule pick_next_task_idle <-schedule _spin_trylock <-tracing_record_cmdline finish_task_switch <-schedule account_vtime <-finish_task_switch account_user_time <-account_vtime acct_update_integrals <-account_user_time jiffies_to_timeval <-acct_update_integrals

Hmm. Not pretty.

Linus

That's true. I just wanted to give some background how all of this started. Spinlocks are equally good or bad for s390 on both kernel versions.

However quite a few of the additional function calls in networking code come from uninlining:

c2aa270a [NET]: uninline skb_push, de-bloats a lot 6be8ac2f [NET]: uninline skb_pull, de-bloats a lot 419ae74e [NET]: uninline skb_trim, de-bloats

Christian Ehrhardt identified these and more, but hasn't posted patches yet. Reverting these patches does increase performance.

That's when I started wondering what we would gain when we would inline spinlock code again.

This should be better now:

507e1231 timer stats: Optimize by adding quick check to avoid function calls

We did also address our device driver with several patches.

Hmm. Those functions are big only because of the stupid debugging, which is almost certainly not worth it any more. I doubt people have seen enough skb under/over-flows in the last years to merit the code.

I suspect we should remove the silly skb_under/over_panic functions, and do

- skb_put:
- if (unlikely(skb->tail > skb->end))
- skb_over_panic(skb, len, __builtin_return_address(0));
+ BUG_ON(skb->tail > skb->end);

- skb_push:
- if (unlikely(skb->data<skb->head))
- skb_under_panic(skb, len, __builtin_return_address(0));
+ BUG_ON(skb->data < skb->head);

at which point it might be worthwhile to inline them again, because the footprint of a BUG_ON() is really fairly small.

If this is a big deal on s390, it might be worth it.

Linus

From: Linus Torvalds <[email protected]>
Date: Fri, 14 Aug 2009 11:08:16 -0700 (PDT)

We have found a few bugs in the past year or two because of the check, but indeed not "a lot".

Maybe. Although most people turn on verbose BUG's and that expands to the same if not more code than what's there now in these SKB inlines.

But not inline in the code, though. So yeah, it has a memory footprint, but shouldn't have a cache footprint.

Linus

An example of this: stack usage. This is the code with BUG_ON():

	skb_push:
		push   %rbp
		mov    %esi,%eax
		add    %esi,0x68(%rdi)
		neg    %rax
		mov    %rsp,%rbp
		add    0xd8(%rdi),%rax
		mov    %rax,0xd8(%rdi)
		cmp    0xd0(%rdi),%rax
		jae    2f
		ud2a   
	1:	jmp    1b
	2:	leaveq 
		retq   

and note how in the code, we're just jumping over something like four bytes ("ud2" plus that silly endless loop-jump just to make gcc happy are both 2 bytes on x86[-64]).

Here's the same code with that horrid skb_under_panic():

	skb_push:
		push   %rbp
		mov    %esi,%eax
		mov    %rsp,%rbp
		neg    %rax
		push   %rbx
		mov    %rdi,%rbx
		sub    $0x8,%rsp
		add    0xd8(%rdi),%rax
		add    %esi,0x68(%rdi)
		mov    %rax,0xd8(%rdi)
		cmp    0xd0(%rdi),%rax
		jae    1f
		mov    0x8(%rbp),%rdx
		callq  skb_under_panic
	1:	mov    0xd8(%rbx),%rax
		pop    %r11
		pop    %rbx
		leaveq 
		retq   

and notice how it creates a stack frame due to the call (even when the call is never done!) and the dead space is now 11 bytes.

(Total size of functions: 41 bytes vs 64 bytes)

So things like that do make a difference. It's surprisingly expensive to add a function call t what otherwise could be a leaf function. And BUG_ON() avoids that.

Of course, even at just 41 bytes, it's not _entirely_ obvious that inlining is the right thing. Of those 41 bytes, four are just function overhead, and the "call" is five bytes in the caller and a few bytes of spills and argument setups, but inlining is still probably going to change each call-site from ~10 bytes to ~35 bytes.

Linus

---
 include/linux/skbuff.h |    4 ---
 net/core/skbuff.c      |   51 +----------------------------------------------
 2 files changed, 2 insertions(+), 53 deletions(-)

index f2c69a2..2af92b4 100644
@@ -483,10 +483,6 @@ extern int	       skb_cow_data(struct sk_buff *skb, int tailbits,
 extern int	       skb_pad(struct sk_buff *skb, int pad);
 #define dev_kfree_skb(a)	consume_skb(a)
 #define dev_consume_skb(a)	kfree_skb_clean(a)
-extern void	      skb_over_panic(struct sk_buff *skb, int len,
-				     void *here);
-extern void	      skb_under_panic(struct sk_buff *skb, int len,
-				      void *here);
 
 extern int skb_append_datato_frags(struct sock *sk, struct sk_buff *skb,
 			int getfrag(void *from, char *to, int offset,

From: Linus Torvalds <[email protected]>
Date: Fri, 14 Aug 2009 14:10:45 -0700 (PDT)

...

Yes on x86 it's better even with verbose debugging because of the inlining of the debug message pointer etc.

I'll have to do something more intelligent than I currently do on sparc64, and I had always been meaning to do that. :-)

An allyesconfig (CONFIG_FTRACE disabled) on x86_64 with gcc 4.3.2 results in the following vmlinux sizes:

574152755 2009-08-16 20:05 vmlinux-orig
574862000 2009-08-16 20:13 vmlinux-skb-inline

The skb-inline variant was created by using your patch and on top of it the patch below. Size increased by 692KB (0.12%).

Dunno.. is that acceptable?

---
 include/linux/skbuff.h |   35 +++++++++++++++++++++++++++++++++--
 net/core/skbuff.c      |   38 --------------------------------------
 2 files changed, 33 insertions(+), 40 deletions(-)

Index: linux-2.6/include/linux/skbuff.h
===================================================================
@@ -1116,7 +1116,6 @@ static inline void skb_set_tail_pointer(
 /*
  *	Add data to an sk_buff
  */
-extern unsigned char *skb_put(struct sk_buff *skb, unsigned int len);
 static inline unsigned char *__skb_put(struct sk_buff *skb, unsigned int len)
 {
 	unsigned char *tmp = skb_tail_pointer(skb);

@@ -1126,7 +1125,23 @@ static inline unsigned char *__skb_put(s
 	return tmp;
 }
 
-extern unsigned char *skb_push(struct sk_buff *skb, unsigned int len);
+/**
+ *	skb_put - add data to a buffer
+ *	@skb: buffer to use
+ *	@len: amount of data to add
+ *
+ *	This function extends the used data area of the buffer. If this would
+ *	exceed the total buffer size the kernel will panic. A pointer to the
+ *	first byte of the extra data is returned.
+ */
+static inline unsigned char *skb_put(struct sk_buff *skb, unsigned int len)
+{
+	unsigned char *tmp = __skb_put(skb, len);
+
+	BUG_ON(skb->tail > skb->end);
+	return tmp;
+}
+
 static inline unsigned char *__skb_push(struct sk_buff *skb, unsigned int len)
 {
 	skb->data -= len;

@@ -1134,6 +1149,22 @@ static inline unsigned char *__skb_push(
 	return skb->data;
 }
 
+/**
+ *	skb_push - add data to the start of a buffer
+ *	@skb: buffer to use
+ *	@len: amount of data to add
+ *
+ *	This function extends the used data area of the buffer at the buffer
+ *	start. If this would exceed the total buffer headroom the kernel will
+ *	panic. A pointer to the first byte of the extra data is returned.
+ */
+static inline unsigned char *skb_push(struct sk_buff *skb, unsigned int len)
+{
+	__skb_push(skb, len);
+	BUG_ON(skb->data < skb->head);
+	return skb->data;
+}
+
 extern unsigned char *skb_pull(struct sk_buff *skb, unsigned int len);
 static inline unsigned char *__skb_pull(struct sk_buff *skb, unsigned int len)
 {

Index: linux-2.6/net/core/skbuff.c
===================================================================
@@ -955,44 +955,6 @@ free_skb:
 EXPORT_SYMBOL(skb_pad);
 
 /**
- *	skb_put - add data to a buffer
- *	@skb: buffer to use
- *	@len: amount of data to add
- *
- *	This function extends the used data area of the buffer. If this would
- *	exceed the total buffer size the kernel will panic. A pointer to the
- *	first byte of the extra data is returned.
- */
-unsigned char *skb_put(struct sk_buff *skb, unsigned int len)
-{
-	unsigned char *tmp = skb_tail_pointer(skb);
-	SKB_LINEAR_ASSERT(skb);
-	skb->tail += len;
-	skb->len  += len;
-	BUG_ON(skb->tail > skb->end);
-	return tmp;
-}
-EXPORT_SYMBOL(skb_put);
-
-/**
- *	skb_push - add data to the start of a buffer
- *	@skb: buffer to use
- *	@len: amount of data to add
- *
- *	This function extends the used data area of the buffer at the buffer
- *	start. If this would exceed the total buffer headroom the kernel will
- *	panic. A pointer to the first byte of the extra data is returned.
- */
-unsigned char *skb_push(struct sk_buff *skb, unsigned int len)
-{
-	skb->data -= len;
-	skb->len  += len;
-	BUG_ON(skb->data < skb->head);
-	return skb->data;
-}
-EXPORT_SYMBOL(skb_push);
-
-/**
  *	skb_pull - remove data from the start of a buffer
  *	@skb: buffer to use
  *	@len: amount of data to remove

It's more relevant to look at just code size. BUG_ON() has more of an impact on data sizes, because it does something like 10-12 bytes of exception data for each bug-on. But that exception data is out-of-line and not interesting.

If the code size blows up a lot, that's worse than if the data size expands a bit.

Linus

Also, allyesconfig isnt really relevant to inlining cost in general as it enables everything. The defconfigs are better (at least on x86) because they tend to be some distro-alike config - i.e. they are closer to what most Linux users will run in the end.

Ingo

Ok, I'm still using allyesconfig but still these numbers should be good enough:

For the unpatched kernel we have

ffffffff81009000 T _stext
ffffffff83614130 T _etext
size: 39891248

ffffffff8460e250 R __start___bug_table
ffffffff8462e9ec R __stop___bug_table
size: 133020

And for the patched kernel (inlined functions) we get

ffffffff81009000 T _stext
ffffffff83627250 T _etext
size: 39969360

ffffffff84621080 R __start___bug_table
ffffffff84649c4c R __stop___bug_table
size: 166860

We have CONFIG_GENERIC_BUG, CONFIG_GENERIC_BUG_RELATIVE_POINTERS and CONFIG_DEBUG_BUGVERBOSE all enabled. So the size of each bug table entry is 10 bytes.
We end up with 3384 additional bug table entries caused by inlining. Text size increased by 78112 bytes which makes an average extra 23 bytes for each call site.

i ported your patch to latest mainline (see it attached below) i've done x86(-64) defconfig (with disabled CONFIG_OPTIMIZE_INLINING) measurements vmlinux:

text data bss dec hex filename
8455329 1192304 989908 10637541 a250e5 vmlinux.before
8471036 1192304 989908 10653248 a28e40 vmlinux.after

that's a +0.18% text size increase - quite significant.

I also did performance measurements, trying to figure out whether this increase in size can be measured via any runtime performance metrics such as cycles, instructions or cache-misses.

To do that i picked a micro-benchmarks lat_tcp.

( Note that microbenchmarks are biased in favor of inlining patches
like yours, because they disproportionately favor the speed benefit of it while not adequately showing the cache footprint disadvantage of increased kernel text size. )

Without your patch i got:

titan:~/l> perf stat --repeat 10 -e task-clock -e cycles -e instructions -e L1-icache-refs -e L1-icache-misses ./lat_tcp localhost TCP latency using localhost: 17.5198 microseconds
TCP latency using localhost: 17.5060 microseconds
TCP latency using localhost: 17.4684 microseconds
TCP latency using localhost: 17.5416 microseconds
TCP latency using localhost: 17.4881 microseconds
TCP latency using localhost: 17.4832 microseconds
TCP latency using localhost: 17.4830 microseconds
TCP latency using localhost: 17.4723 microseconds
TCP latency using localhost: 17.4733 microseconds
TCP latency using localhost: 17.5255 microseconds

Performance counter stats for './lat_tcp localhost' (10 runs):

    1494.625043  task-clock-msecs         #      0.564 CPUs    ( +-   0.077% )
     3665868023  cycles                   #   2452.701 M/sec   ( +-   0.070% )
     2163212606  instructions             #      0.590 IPC     ( +-   0.090% )
     2449056216  L1-icache-loads          #   1638.576 M/sec   ( +-   0.056% )
       61081182  L1-icache-load-misses    #     40.867 M/sec   ( +-   0.192% )

    2.649159316  seconds time elapsed   ( +-   0.090% )

With your patch i got:

titan:~/l> perf stat --repeat 10 -e task-clock -e cycles -e instructions -e L1-icache-refs -e L1-icache-misses ./lat_tcp localhost TCP latency using localhost: 17.6913 microseconds
TCP latency using localhost: 17.7218 microseconds
TCP latency using localhost: 17.6882 microseconds
TCP latency using localhost: 17.7196 microseconds
TCP latency using localhost: 17.6411 microseconds
TCP latency using localhost: 17.7136 microseconds
TCP latency using localhost: 17.6488 microseconds
TCP latency using localhost: 17.6663 microseconds
TCP latency using localhost: 17.7445 microseconds
TCP latency using localhost: 17.6851 microseconds

Performance counter stats for './lat_tcp localhost' (10 runs):

    1497.479984  task-clock-msecs         #      0.564 CPUs    ( +-   0.106% )
     3690097505  cycles                   #   2464.205 M/sec   ( +-   0.109% )
     2162432402  instructions             #      0.586 IPC     ( +-   0.127% )
     2437974192  L1-icache-loads          #   1628.051 M/sec   ( +-   0.105% )
       63064588  L1-icache-load-misses    #     42.114 M/sec   ( +-   0.278% )

    2.656952976  seconds time elapsed   ( +-   0.110% )

Summarized (for lat_tcp):

|  Before:
|
|    1494.625043  task-clock-msecs         #      0.564 CPUs    ( +-   0.077% )
|     3665868023  cycles                   #   2452.701 M/sec   ( +-   0.070% )
|     2163212606  instructions             #      0.590 IPC     ( +-   0.090% )
|
|  After:
|
|    1497.479984  task-clock-msecs         #      0.564 CPUs    ( +-   0.106% )
|     3690097505  cycles                   #   2464.205 M/sec   ( +-   0.109% )
|     2162432402  instructions             #      0.586 IPC     ( +-   0.127% )

So we've got a 0.2% slowdown, which is provably outside the noise level of 0.1%. The instruction count remained almost the same.

The reason for the slowdown can be seen in the L1 icache-fetch stats:

     2449056216  L1-icache-loads          #   1638.576 M/sec   ( +-   0.056% )
       61081182  L1-icache-load-misses    #     40.867 M/sec   ( +-   0.192% )

     2437974192  L1-icache-loads          #   1628.051 M/sec   ( +-   0.105% )
       63064588  L1-icache-load-misses    #     42.114 M/sec   ( +-   0.278% )

The icache-misses went up from 40.867 M/sec to 42.114 M/sec, a 3.05% worsening - well beyond the statistical significance of 0.28%.

So unless i botched the measurements or some accidental code layout differences punish the patch artificially, this patch is a small but measureable performance regression on x86.

The slowdown itself is barely provable with a test repeat count of 10 iterations (not a surprise really - such patches were not really provable before via /usr/bin/time kinds of measurements), on an otherwise totally idle system.

The icache-miss stats do support the notion that what is causing the slowdown is the critical path fallout out of the icache.

( By all means please repeat these measurements - they are very
easy to do via 'perf stat --repeat 10' - see the examples above. )

To build the kernel i used gcc 4.3.2. The CPU i used is friendly to inlining patches as well: it's an Extreme Edition Core2 Duo (booted to a single core, to stabilize the numbers):

Intel(R) Core(TM)2 CPU E6800 @ 2.93GHz

With 4MB of L2 cache. I suspect smaller CPUs would feel the negative effects of inlining in a more pronounced way.

Thanks,

Ingo

---
 include/linux/skbuff.h |   37 +++++++++++++++++++++++++++++++++++--
 net/core/skbuff.c      |   40 ----------------------------------------
 2 files changed, 35 insertions(+), 42 deletions(-)

Index: linux/include/linux/skbuff.h
===================================================================
@@ -1120,7 +1120,6 @@ static inline void skb_set_tail_pointer(
 /*
  *	Add data to an sk_buff
  */
-extern unsigned char *skb_put(struct sk_buff *skb, unsigned int len);
 static inline unsigned char *__skb_put(struct sk_buff *skb, unsigned int len)
 {
 	unsigned char *tmp = skb_tail_pointer(skb);

@@ -1130,7 +1129,24 @@ static inline unsigned char *__skb_put(s
 	return tmp;
 }
 
-extern unsigned char *skb_push(struct sk_buff *skb, unsigned int len);
+/**
+ *	skb_put - add data to a buffer
+ *	@skb: buffer to use
+ *	@len: amount of data to add
+ *
+ *	This function extends the used data area of the buffer. If this would
+ *	exceed the total buffer size the kernel will panic. A pointer to the
+ *	first byte of the extra data is returned.
+ */
+static inline unsigned char *skb_put(struct sk_buff *skb, unsigned int len)
+{
+	unsigned char *tmp = __skb_put(skb, len);
+
+	if (unlikely(skb->tail > skb->end))
+		skb_over_panic(skb, len, __builtin_return_address(0));
+	return tmp;
+}
+
 static inline unsigned char *__skb_push(struct sk_buff *skb, unsigned int len)
 {
 	skb->data -= len;

@@ -1138,6 +1154,23 @@ static inline unsigned char *__skb_push(
 	return skb->data;
 }
 
+/**
+ *	skb_push - add data to the start of a buffer
+ *	@skb: buffer to use
+ *	@len: amount of data to add
+ *
+ *	This function extends the used data area of the buffer at the buffer
+ *	start. If this would exceed the total buffer headroom the kernel will
+ *	panic. A pointer to the first byte of the extra data is returned.
+ */
+static inline unsigned char *skb_push(struct sk_buff *skb, unsigned int len)
+{
+	__skb_push(skb, len);
+	if (unlikely(skb->data<skb->head))
+		skb_under_panic(skb, len, __builtin_return_address(0));
+	return skb->data;
+}
+
 extern unsigned char *skb_pull(struct sk_buff *skb, unsigned int len);
 static inline unsigned char *__skb_pull(struct sk_buff *skb, unsigned int len)
 {

Index: linux/net/core/skbuff.c
===================================================================
@@ -1000,46 +1000,6 @@ free_skb:
 EXPORT_SYMBOL(skb_pad);
 
 /**
- *	skb_put - add data to a buffer
- *	@skb: buffer to use
- *	@len: amount of data to add
- *
- *	This function extends the used data area of the buffer. If this would
- *	exceed the total buffer size the kernel will panic. A pointer to the
- *	first byte of the extra data is returned.
- */
-unsigned char *skb_put(struct sk_buff *skb, unsigned int len)
-{
-	unsigned char *tmp = skb_tail_pointer(skb);
-	SKB_LINEAR_ASSERT(skb);
-	skb->tail += len;
-	skb->len  += len;
-	if (unlikely(skb->tail > skb->end))
-		skb_over_panic(skb, len, __builtin_return_address(0));
-	return tmp;
-}
-EXPORT_SYMBOL(skb_put);
-
-/**
- *	skb_push - add data to the start of a buffer
- *	@skb: buffer to use
- *	@len: amount of data to add
- *
- *	This function extends the used data area of the buffer at the buffer
- *	start. If this would exceed the total buffer headroom the kernel will
- *	panic. A pointer to the first byte of the extra data is returned.
- */
-unsigned char *skb_push(struct sk_buff *skb, unsigned int len)
-{
-	skb->data -= len;
-	skb->len  += len;
-	if (unlikely(skb->data<skb->head))
-		skb_under_panic(skb, len, __builtin_return_address(0));
-	return skb->data;
-}
-EXPORT_SYMBOL(skb_push);
-
-/**
  *	skb_pull - remove data from the start of a buffer
  *	@skb: buffer to use
  *	@len: amount of data to remove