strange ping response times...

[Luigi Rizzo]

On Wed, Apr 11, 2012 at 02:16:49PM +0200, Andre Oppermann wrote:
> On 11.04.2012 13:00, Luigi Rizzo wrote:
> >On Wed, Apr 11, 2012 at 12:35:10PM +0200, Andre Oppermann wrote:
> >>On 11.04.2012 01:32, Luigi Rizzo wrote:
> >>>On Tue, Apr 10, 2012 at 07:05:00PM -0400, Barney Wolff wrote:
> >>>>CPU cache?
> >>>>Cx states?
> >>>>powerd?
> >>>
> >>>powerd is disabled, and i am going down to C1 at most
> >>>	>   sysctl -a | grep cx
> >>>	hw.acpi.cpu.cx_lowest: C1
> >>>	dev.cpu.0.cx_supported: C1/1 C2/80 C3/104
> >>>
> >>>which shouldn't take so much. Sure, cache matters, but the
> >>>fact is, icmp processing on loopback should occur inline.
> >>>
> >>>unless there is a forced descheduling on a select with timeout>   0
> >>>which would explain the extra few microseconds (and makes me worry
> >>>on how expensive is a scheduling decision...)
> >>
> >>Things going through loopback go through a NETISR and may
> >>end up queued to avoid LOR situations.  In addition per-cpu
> >>queues with hash-distribution for affinity may cause your
> >>packet to be processed by a different core.  Hence the additional
> >>delay.
> >
> >so you suggest that the (de)scheduling is costing several microseconds ?
> 
> Not directly.  I'm just trying to explain what's going on to
> get a better idea where it may go wrong.
> 
> There may be a poor ISR/scheduler interaction that prevents that
> causes the packet to be processed only on the next tick or something
> like that.  I don't have a better explanation for this.

ok, some final remarks just for archival purposes
(still related to the loopback ping)

ping takes a timestamp in userspace before trying to transmit
the packet, and then the timestamp for the received packet
is recorded in the kernel (in the interrupt or netisr thread
i believe -- anyways, not in userspace). A thing that seems to make
the difference is the choice of idle states:
	machdep.idle = {acpi, hlt, mwait, spin}
	hw.acpi.cpu.cx_lowest={C1, C2, C3}
results in 10-15% of samples with significantly different values
(see table below, all values in microseconds)

	config		normal		top 10-15%
	-----------------------------------------
	acpi+c3		13		85
	acpi+c2		10		40
	acpi+c1		7		10

	spin		7		8
	hlt,mwait		6..10 (no clear distinction)
	ping -f			5-6

This suggests that sometimes the responding thread
may be started on a sleeping core and so takes
longer to wake up.

The high values are not periodic but the ratio is close to
the 128/1000 which relates profhz and tick, so that might be
something to look at.

cheers
luigi