Re: [GIT PULL] First batch of KVM changes for 4.1

From: Linus Torvalds <torvalds@linux-foundation.org>
To: Andy Lutomirski <luto@amacapital.net>
Cc: Marcelo Tosatti <mtosatti@redhat.com>,
	Paolo Bonzini <pbonzini@redhat.com>,
	Peter Zijlstra <peterz@infradead.org>,
	"linux-kernel@vger.kernel.org" <linux-kernel@vger.kernel.org>,
	Gleb Natapov <gleb@kernel.org>, kvm list <kvm@vger.kernel.org>,
	Ralf Baechle <ralf@linux-mips.org>,
	Andrew Lutomirski <luto@kernel.org>
Subject: Re: [GIT PULL] First batch of KVM changes for 4.1
Date: Fri, 17 Apr 2015 17:28:06 -0400	[thread overview]
Message-ID: <CA+55aFz=fqbNF6wRZJoFXEv=FBCE14eXgooCosmtarOjYcSDOw@mail.gmail.com> (raw)
In-Reply-To: <CALCETrVJvHjwCWDgS+is3owZKbj7d8L-zxAkv6cOp7f4aTFzsg@mail.gmail.com>

On Fri, Apr 17, 2015 at 4:39 PM, Andy Lutomirski <luto@amacapital.net> wrote:
>
> On my box, vclock_gettime using kvm-clock is about 40 ns.  An empty
> syscall is about 33 ns.  clock_gettime *should* be around 17 ns.
>
> The clock_gettime syscall is about 73 ns.
>
> Could we figure out why clock_gettime (the syscall) is so slow

If we only could profile some random program (let's call it "a.out"
that did the syscall(__NR_gettime_syscall) a couple million times.

Oh, lookie here, Santa came around:

  21.83%   [k] system_call
  12.85%   [.] syscall
   9.76%   [k] __audit_syscall_exit
   9.55%   [k] copy_user_enhanced_fast_string
   4.68%   [k] __getnstimeofday64
   4.08%   [k] syscall_trace_enter_phase1
   3.85%   [k] __audit_syscall_entry
   3.77%   [k] unroll_tree_refs
   3.15%   [k] sys_clock_gettime
   2.92%   [k] int_very_careful
   2.73%   [.] main
   2.35%   [k] syscall_trace_leave
   2.28%   [k] read_tsc
   1.73%   [k] int_restore_rest
   1.73%   [k] int_with_check
   1.48%   [k] syscall_return
   1.32%   [k] dput
   1.24%   [k] system_call_fastpath
   1.21%   [k] syscall_return_via_sysret
   1.21%   [k] tracesys
   0.81%   [k] do_audit_syscall_entry
   0.80%   [k] current_kernel_time
   0.73%   [k] getnstimeofday64
   0.68%   [k] path_put
   0.66%   [k] posix_clock_realtime_get
   0.61%   [k] int_careful
   0.60%   [k] mntput
   0.49%   [k] kfree
   0.36%   [k] _copy_to_user
   0.31%   [k] int_ret_from_sys_call_irqs_off

looks to me like it's spending a lot of time in system call auditing.
Which makes no sense to me, since none of this should be triggering
any auditing. And there's a lot of time in low-level kernel system
call assembly code.

If I only remembered the name of the crazy person who said "Ok" when I
suggest he just be the maintainer of the code since he has spent a lot
of time sending patches for it. Something like Amdy Letorsky. No, that
wasn't it. Hmm. It's on the tip of my tongue.

Oh well. Maybe somebody can remember the guys name. It's familiar for
some reason. Andy?

             Linus