Cause of marker slowdown identified : lockdep instrumentation

Mathieu Desnoyers <[email protected]>
Newsgroups gmane.linux.kernel.tracing
Message-ID <[email protected]>
Hi,

A bit of context : I have been concerned with I saw some unexpected 
slowdown while running lmbench on a marked kernel (with markers 
disabled, no probe connected). I was experiencing slowdown of about 9% 
on open/close lmbench test and 10.87% on select on 500 FDs test.

My sample tests :
500 selects
open/close

The biggest impact : markers located in lockdep code. Lockdep itself 
actually slows down those system calls by a factor 2 by itself without 
any markers, and since I mark the lockdep code, the marker impact became 
perceptible.

If I compare kernels with lockdep disabled, but respectively with 
markers compiled-out and compiled-in, the marker impact on open/close is 
about 2%. It fades down to 1% if I remove the syscall tracing. It 
becomes imperceptible (I recorded slightly better performance with 
markers compiled-in) for the 500 selects case.

I tried different scenarios in these tests, which led to interesting 
results. By its very intrusive nature, the lockdep instrumentation 
appears to be a good stress-test for the markers, since it exhibits its 
otherwise non perceptible impact. In the first place, when I did not 
know that the lockdep instrumentation was the faulty one for the 
performance impact, I tried to characterize the instruction cache 
pollution and register pressure caused by the marker code added to the 
kernel.

Changing the marker call for 750 bytes of NOPs in the lockdep enabled case
  - removes the register pressure from the compiler, since I remove the 
function call
  - Adds icache pollution
This test runs significantly faster than the normal function call. It 
tells me that i-cache pollution is not the faulty element there, but 
that register pressure seems to have the biggest impact. It also tells 
me that the branch is not the faulty one, since the branch is still 
there in the NOP test, which is significantly faster :

Test with lockdep enabled, markers compiled out (reference)
  Simple open/close: 5.6717 microseconds
  Select on 500 fd's: 11.6195 microseconds

Test with lockdep and markers enabled, with function call
  Simple open/close: 6.1823 microseconds (slowdown : 9%)
  Select on 500 fd's: 12.8831 microseconds (slowdown : 10.87%)

Test with lockdep and markers enabled, 750 bytes of NOPs replacing the 
function call
  Simple open/close: 6.0227 microseconds (slowdown : 6.1%)
  Select on 500 fd's: 11.8774 microseconds (slowdown : 2.2%)

Mathieu
lmpx.com only provides a reader for public news (NNTP) servers. It is not affiliated with the servers or forums shown here and is not responsible for the content of articles, which is written by their respective authors.