Re: [PATCH] tracing: Cleanup the convoluted softirq tracepoints

[Thomas Gleixner <tglx@linutronix.de>]

On Tue, 19 Oct 2010, Mathieu Desnoyers wrote:
> * Thomas Gleixner (tglx@linutronix.de) wrote:
> > On Tue, 19 Oct 2010, Steven Rostedt wrote:
> as an excuse for adding extra performance impact to kernel code, because when it
> will be replaced by asm gotos, all that will be left is the performance impact
> inappropriately justified as insignificant compared to the impact of the old
> tracepoint scheme.

Can you at one point just stop your tracing lectures and look at the
facts ?

The impact of a sensible tracepoint design on the code in question
before kstat_incr_softirqs_this_cpu() was added would have been a mere
_FIVE_ bytes of text. But the original tracepoint code itself is
_TWENTY_ bytes of text larger.

So we trade horrible code plus 20 bytes text against 5 bytes of text
in the hotpath. And you tell me that these _FIVE_ bytes are impacting
performance so much that it's significant.

Now with kstat_incr_softirqs_this_cpu() the impact is zero, it even
removes code.

And talking about non impact of disabled trace points. The tracepoint
in question which made me look at the code results in deinlining
__raise_softirq_irqsoff() in net/dev/core.c. There goes your theory.

So no, you _cannot_ tell what impact a tracepoint has in reality
except by looking at the assembly output.

And what scares me way more is the size of a single tracepoint in a
code file.

Just adding "trace_softirq_entry(nr);" adds 88 bytes of text. So
that's optimized tracing code ?

All it's supposed to do is:

    if (enabled)
	trace_foo(nr);

Replace "if (enabled)" with your favourite code patching jump label
whatever magic. The above stupid version takes about 28, but the
"optimized" tracing code makes that 88. Brilliant. That's inlining
utter shite for no good reason. WTF is it necessary to inline all that
gunk ?

Please spare me the "jump label will make this less intrusive"
lecture. I'm not interested at all.

Let's instead look at some more facts:

#include <linux/interrupt.h>
#include <linux/module.h>

#include <trace/events/irq.h>

static struct softirq_action softirq_vec[NR_SOFTIRQS];

void test(struct softirq_action *h)
{
	trace_softirq_entry(h - softirq_vec);

	h->action(h);
}

Compile this code with GCC 4.5 with and without jump labels (zap the
select HAVE_ARCH_JUMP_LABEL line in arch/x86/Kconfig)

So now the !jumplabel case gives us:

../build/kernel/soft.o:     file format elf64-x86-64

Disassembly of section .text:

0000000000000000 <test>:
   0:	55                   	push   %rbp
   1:	48 89 e5             	mov    %rsp,%rbp
   4:	41 55                	push   %r13
   6:	49 89 fd             	mov    %rdi,%r13
   9:	49 81 ed 00 00 00 00 	sub    $0x0,%r13
  10:	41 54                	push   %r12
  12:	49 c1 ed 03          	shr    $0x3,%r13
  16:	49 89 fc             	mov    %rdi,%r12
  19:	53                   	push   %rbx
  1a:	48 83 ec 08          	sub    $0x8,%rsp
  1e:	83 3d 00 00 00 00 00 	cmpl   $0x0,0x0(%rip)        # 25 <test+0x25>
  25:	74 4d                	je     74 <test+0x74>
  27:	65 48 8b 04 25 00 00 	mov    %gs:0x0,%rax
  2e:	00 00 
  30:	ff 80 44 e0 ff ff    	incl   -0x1fbc(%rax)
  36:	48 8b 1d 00 00 00 00 	mov    0x0(%rip),%rbx        # 3d <test+0x3d>
  3d:	48 85 db             	test   %rbx,%rbx
  40:	74 13                	je     55 <test+0x55>
  42:	48 8b 7b 08          	mov    0x8(%rbx),%rdi
  46:	44 89 ee             	mov    %r13d,%esi
  49:	ff 13                	callq  *(%rbx)
  4b:	48 83 c3 10          	add    $0x10,%rbx
  4f:	48 83 3b 00          	cmpq   $0x0,(%rbx)
  53:	eb eb                	jmp    40 <test+0x40>
  55:	65 48 8b 04 25 00 00 	mov    %gs:0x0,%rax
  5c:	00 00 
  5e:	ff 88 44 e0 ff ff    	decl   -0x1fbc(%rax)
  64:	48 8b 80 38 e0 ff ff 	mov    -0x1fc8(%rax),%rax
  6b:	a8 08                	test   $0x8,%al
  6d:	74 05                	je     74 <test+0x74>
  6f:	e8 00 00 00 00       	callq  74 <test+0x74>
  74:	4c 89 e7             	mov    %r12,%rdi
  77:	41 ff 14 24          	callq  *(%r12)
  7b:	58                   	pop    %rax
  7c:	5b                   	pop    %rbx
  7d:	41 5c                	pop    %r12
  7f:	41 5d                	pop    %r13
  81:	c9                   	leaveq 
  82:	c3                   	retq   

The jumplabel=y case gives:

../build/kernel/soft.o:     file format elf64-x86-64

Disassembly of section .text:

0000000000000000 <test>:
   0:	55                   	push   %rbp
   1:	48 89 e5             	mov    %rsp,%rbp
   4:	41 55                	push   %r13
   6:	49 89 fd             	mov    %rdi,%r13
   9:	49 81 ed 00 00 00 00 	sub    $0x0,%r13
  10:	41 54                	push   %r12
  12:	49 c1 ed 03          	shr    $0x3,%r13
  16:	49 89 fc             	mov    %rdi,%r12
  19:	53                   	push   %rbx
  1a:	48 83 ec 08          	sub    $0x8,%rsp
  1e:	e9 00 00 00 00       	jmpq   23 <test+0x23>
  23:	eb 4d                	jmp    72 <test+0x72>
  25:	65 48 8b 04 25 00 00 	mov    %gs:0x0,%rax
  2c:	00 00 
  2e:	ff 80 44 e0 ff ff    	incl   -0x1fbc(%rax)
  34:	48 8b 1d 00 00 00 00 	mov    0x0(%rip),%rbx        # 3b <test+0x3b>
  3b:	48 85 db             	test   %rbx,%rbx
  3e:	74 13                	je     53 <test+0x53>
  40:	48 8b 7b 08          	mov    0x8(%rbx),%rdi
  44:	44 89 ee             	mov    %r13d,%esi
  47:	ff 13                	callq  *(%rbx)
  49:	48 83 c3 10          	add    $0x10,%rbx
  4d:	48 83 3b 00          	cmpq   $0x0,(%rbx)
  51:	eb eb                	jmp    3e <test+0x3e>
  53:	65 48 8b 04 25 00 00 	mov    %gs:0x0,%rax
  5a:	00 00 
  5c:	ff 88 44 e0 ff ff    	decl   -0x1fbc(%rax)
  62:	48 8b 80 38 e0 ff ff 	mov    -0x1fc8(%rax),%rax
  69:	a8 08                	test   $0x8,%al
  6b:	74 05                	je     72 <test+0x72>
  6d:	e8 00 00 00 00       	callq  72 <test+0x72>
  72:	4c 89 e7             	mov    %r12,%rdi
  75:	41 ff 14 24          	callq  *(%r12)
  79:	58                   	pop    %rax
  7a:	5b                   	pop    %rbx
  7b:	41 5c                	pop    %r12
  7d:	41 5d                	pop    %r13
  7f:	c9                   	leaveq 
  80:	c3                   	retq   

So that saves _TWO_ bytes of text and replaces:

-  1e:	83 3d 00 00 00 00 00 	cmpl   $0x0,0x0(%rip)        # 25 <test+0x25>
-  25:	74 4d                	je     74 <test+0x74>
+  1e:	e9 00 00 00 00       	jmpq   23 <test+0x23>
+  23:	eb 4d                	jmp    72 <test+0x72>

So it trades a conditional vs. two jumps ? WTF ??

I thought that jumplabel magic was supposed to get rid of the jump
over the tracing code ? In fact it adds another jump. Whatfor ?

Now even worse, when you NOP out the jmpq then your tracepoint is
still not enabled. Brilliant !

Did you guys ever look at the assembly output of that insane shite you
are advertising with lengthy explanations ? 

Obviously _NOT_

Come back when you can show me a clean imlementation of all this crap
which reproduces with my jumplabel enabled stock compiler. And please
just send me a patch w/o the blurb.

And sane looks like:

    jmpq   2f  <---- This gets noped out 
1:
    mov    %r12,%rdi
    callq  *(%r12)
    [whatever cleanup it takes ]
    leaveq 
    retq   

2f:
    [tracing gunk]
    jmp    1b

And further I want to see the tracing gunk in a minimal size so the
net/core/dev.c deinlining does not happen.

Thanks,

	tglx

P.S.: It might be helpful and polite if you'd take off your tracing
      blinkers from time to time.