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