| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Date: Thu, 13 Oct 2016 06:15:37 +0000
From: "Koehrer Mathias (ETAS/ESW5)" <mathias.koehrer@...s.com>
To: Julia Cartwright <julia@...com>
CC: "Williams, Mitch A" <mitch.a.williams@...el.com>,
"Kirsher, Jeffrey T" <jeffrey.t.kirsher@...el.com>,
Greg <gvrose8192@...il.com>,
"netdev@...r.kernel.org" <netdev@...r.kernel.org>,
"intel-wired-lan@...ts.osuosl.org" <intel-wired-lan@...ts.osuosl.org>,
"linux-rt-users@...r.kernel.org" <linux-rt-users@...r.kernel.org>,
"Sebastian Andrzej Siewior" <sebastian.siewior@...utronix.de>
Subject: Re: Kernel 4.6.7-rt13: Intel Ethernet driver igb causes huge
latencies in cyclictest
Hi Julia,
thanks for the detailed analysis!
>
> [...]
> Okay, we finally received our wakeup event. We were expecting to be woken up at
> 10024735653388ns, but were actually woken up at 10024735682387ns.
>
> 10024735682387 - 10024735653388 = 28999ns
>
> Our timer fired ~29us late! But why...?
>
> Sorry I don't have answers, just more questions. I do wonder what
> kworker/0:3 was up to at the time the timer interrupt should have fired.
>
> Julia
I have now instrumented the igb driver to generate trace points that allows me to identify in
more details what's going on.
This delivered interesting results!
Here are some places where I added traces:
In file igb_ptp.c:
void igb_ptp_rx_hang(struct igb_adapter *adapter)
{
struct e1000_hw *hw = &adapter->hw;
unsigned long rx_event;
u32 tsyncrxctl;
trace_igb(700);
tsyncrxctl = rd32(E1000_TSYNCRXCTL);
trace_igb(701);
/* Other hardware uses per-packet timestamps */
if (hw->mac.type != e1000_82576)
return;
...
In file igb_main.c:
static void igb_check_lvmmc(struct igb_adapter *adapter)
{
struct e1000_hw *hw = &adapter->hw;
u32 lvmmc;
trace_igb(600);
lvmmc = rd32(E1000_LVMMC);
trace_igb(601);
if (lvmmc) {
...
When I run now my test, I get the following trace:
[...]
kworker/-607 0....... 107315621us+: igb: val: 700
kworker/-607 0d..h... 107315640us : irq_handler_entry: irq=47 name=eth2-rx-0
kworker/-607 0d..h... 107315640us : irq_handler_exit: irq=47 ret=handled
kworker/-607 0d..h1.. 107315640us : sched_waking: comm=irq/47-eth2-rx- pid=18009 prio=49 target_cpu=000
kworker/-607 0dN.h2.. 107315641us : sched_wakeup: comm=irq/47-eth2-rx- pid=18009 prio=49 target_cpu=000
kworker/-607 0dN.h1.. 107315643us : irq_handler_entry: irq=48 name=eth2-tx-0
kworker/-607 0dN.h1.. 107315643us : irq_handler_exit: irq=48 ret=handled
kworker/-607 0dN.h2.. 107315643us : sched_waking: comm=irq/48-eth2-tx- pid=18010 prio=49 target_cpu=000
kworker/-607 0dN.h3.. 107315644us : sched_wakeup: comm=irq/48-eth2-tx- pid=18010 prio=49 target_cpu=000
kworker/-607 0dN..1.. 107315644us : rcu_utilization: Start context switch
kworker/-607 0dN..1.. 107315644us : rcu_utilization: End context switch
kworker/-607 0dN..2.. 107315644us : sched_stat_runtime: comm=kworker/0:1 pid=607 runtime=88996 [ns] vruntime=49754678074 [ns]
kworker/-607 0d...2.. 107315645us : sched_switch: prev_comm=kworker/0:1 prev_pid=607 prev_prio=120 prev_state=R+ ==> next_comm=irq/47-eth2-rx- next_pid=18009 next_prio=49
irq/47-e-18009 0d....11 107315646us : softirq_raise: vec=3 [action=NET_RX]
irq/47-e-18009 0.....12 107315646us : softirq_entry: vec=3 [action=NET_RX]
irq/47-e-18009 0.....12 107315647us : napi_poll: napi poll on napi struct ffff88040ae58c50 for device eth2 work 0 budget 64
irq/47-e-18009 0.....12 107315647us : softirq_exit: vec=3 [action=NET_RX]
irq/47-e-18009 0d...1.. 107315648us : rcu_utilization: Start context switch
irq/47-e-18009 0d...1.. 107315648us : rcu_utilization: End context switch
irq/47-e-18009 0d...2.. 107315648us : sched_switch: prev_comm=irq/47-eth2-rx- prev_pid=18009 prev_prio=49 prev_state=S ==> next_comm=irq/48-eth2-tx- next_pid=18010 next_prio=49
irq/48-e-18010 0d....11 107315649us : softirq_raise: vec=3 [action=NET_RX]
irq/48-e-18010 0.....12 107315649us : softirq_entry: vec=3 [action=NET_RX]
irq/48-e-18010 0.....12 107315650us : napi_poll: napi poll on napi struct ffff88040ae5f450 for device eth2 work 0 budget 64
irq/48-e-18010 0.....12 107315650us : softirq_exit: vec=3 [action=NET_RX]
irq/48-e-18010 0d...1.. 107315651us : rcu_utilization: Start context switch
irq/48-e-18010 0d...1.. 107315651us : rcu_utilization: End context switch
irq/48-e-18010 0d...2.. 107315651us : sched_switch: prev_comm=irq/48-eth2-tx- prev_pid=18010 prev_prio=49 prev_state=S ==> next_comm=kworker/0:1 next_pid=607 next_prio=120
kworker/-607 0....... 107315652us : igb: val: 701
kworker/-607 0....... 107315652us : igb: val: 106
kworker/-607 0....... 107315652us : igb: val: 107
kworker/-607 0....... 107315652us+: igb: val: 600
kworker/-607 0d..h... 107315689us : local_timer_entry: vector=239
kworker/-607 0d..h1.. 107315689us : hrtimer_interrupt: cpu=0 offset=-34521 curr=kworker/0:1[120] thread=cyclictest[19]
kworker/-607 0d..h1.. 107315689us : hrtimer_cancel: hrtimer=ffff8803d42efe18
kworker/-607 0d..h... 107315689us : hrtimer_expire_entry: hrtimer=ffff8803d42efe18 function=hrtimer_wakeup now=752735681960
kworker/-607 0d..h1.. 107315689us : sched_waking: comm=cyclictest pid=18015 prio=19 target_cpu=000
kworker/-607 0dN.h2.. 107315690us : sched_wakeup: comm=cyclictest pid=18015 prio=19 target_cpu=000
kworker/-607 0dN.h... 107315690us : hrtimer_expire_exit: hrtimer=ffff8803d42efe18
kworker/-607 0dN.h1.. 107315690us : hrtimer_interrupt: cpu=0 offset=318040 curr=kworker/0:1[120] thread=<none>[-1]
kworker/-607 0dN.h... 107315690us : write_msr: 6e0, value 28096cdb9ce
kworker/-607 0dN.h... 107315690us : local_timer_exit: vector=239
kworker/-607 0dN..1.. 107315690us : rcu_utilization: Start context switch
kworker/-607 0dN..1.. 107315691us : rcu_utilization: End context switch
kworker/-607 0dN..2.. 107315691us : sched_stat_runtime: comm=kworker/0:1 pid=607 runtime=38439 [ns] vruntime=49754716513 [ns]
kworker/-607 0d...2.. 107315691us : sched_switch: prev_comm=kworker/0:1 prev_pid=607 prev_prio=120 prev_state=R+ ==> next_comm=cyclictest next_pid=18015 next_prio=19
kworker/-607 0d...2.. 107315691us : x86_fpu_regs_activated: x86/fpu: ffff8803f7f55940 fpregs_active: 1 fpstate_active: 1 counter: 99 xfeatures: 2 xcomp_bv: 0
kworker/-607 0d...2.. 107315691us : write_msr: c0000100, value 7ffff7400700
cyclicte-18015 0....... 107315692us : sys_exit: NR 230 = 0
cyclicte-18015 0....... 107315697us : sys_enter: NR 1 (5, 7ffff7400300, 1f, 7ffff77a5460, 2, 7ffff744c99a)
cyclicte-18015 0.....11 107315698us : tracing_mark_write: hit latency threshold (37 > 33)
cyclicte-18015 0....... 107315699us : sys_exit: NR 1 = 31
cyclicte-18015 0....... 107315699us : sys_enter: NR 1 (4, 4076b0, 2, 7ffff77a5460, 2, 7ffff744c99a)
Very interesting is also the trace that I get in an idle system - without cyclictest running.
When I just enable my igb tracepoint I got the following result:
[...]
kworker/-607 0....... 585779012us+: igb: val: 700
kworker/-607 0....... 585779042us : igb: val: 701
kworker/-607 0....... 585779042us : igb: val: 106
kworker/-607 0....... 585779043us : igb: val: 107
kworker/-607 0....... 585779043us+: igb: val: 600
kworker/-607 0....... 585779080us : igb: val: 601
The time between my trace points 700 and 701 is about 30us,
the time between my trace points 600 and 601 is even 37us!!
The code in between is
tsyncrxctl = rd32(E1000_TSYNCRXCTL);
resp.
lvmmc = rd32(E1000_LVMMC);
In both cases this is a single read from a register.
I have no idea why this single read could take that much time!
Is it possible that the igb hardware is in a state that delays the read access
and this is why the whole I/O system might be delayed?
I hope this delivers more details on understanding this issue.
Thanks for any feedback!
Regards
Mathias
Powered by blists - more mailing lists