Re: [sched_delayed] sched: RT throttling activated

[Martin Mokrejs <mmokrejs@fold.natur.cuni.cz>]

Peter Zijlstra wrote:
> On Fri, Aug 23, 2013 at 01:35:24PM +0200, Martin Mokrejs wrote:
> 
>> # ps -deo pid,cls,cmd | grep -e 'RR \[' -e 'FF \['
> 
> This explicitly only lists kernel threads; from your other comment:
> 
>> The shell/python tasks have 'TS' in place of the FF value in the second column
>> so I guess they are not requiring realtime responsiveness.
> 
> I'll assume you actually inspected the other tasks and found none.

Yes, the other (false) matches were in the third or latter columns so I wanted to match
just those true matches and cut&paste it. I admit, this is not a general-purpose
REGEXP and is misleading.

> 
>>     7  FF [migration/0]
>>    10  FF [watchdog/0]
>>    11  FF [watchdog/1]
>>    12  FF [migration/1]
>>    17  FF [migration/2]
>>    22  FF [migration/3]
> 
> The 'migration' threads only look like FIFO threads but they're secretly
> not and don't count to the limit. The watchdog threads shouldn't run
> much either.
> 
>>  2161  FF [irq/50-iwlwifi]
> 
> Oh a threaded interrupt, I presume you're not using "threadiqrs" since

Is that what you talk about?

CONFIG_IRQ_FORCED_THREADING=y
CONFIG_GENERIC_SMP_IDLE_THREAD=y

> this is the only interrupt thread around and I see a
> 'request_threaded_irq()' call in
> drivers/net/wireless/iwlwifi/pcie/trans.c
> 
> And wow, why would that thing consume that much cpu. 
> 
> Johill, ever seen the iwlwifi interrupt go 'funny' and consume gobs of
> cpu-time?

I am not sure if I understand you but in case it helps somebody

Current values:

# cat /proc/interrupts 
           CPU0       CPU1       
  0:         23          0   IO-APIC-edge      timer
  1:         42          0   IO-APIC-edge      i8042
  8:         36          0   IO-APIC-edge      rtc0
  9:          3          0   IO-APIC-fasteoi   acpi
 12:     404650          0   IO-APIC-edge      i8042
 16:        109          0   IO-APIC-fasteoi   ehci_hcd:usb1
 23:     583646          0   IO-APIC-fasteoi   ehci_hcd:usb2
 40:          0          0   PCI-MSI-edge      pciehp
 41:      54319          0   PCI-MSI-edge      i915
 42:     553802          0   PCI-MSI-edge      ahci
 43:          0          0   PCI-MSI-edge      enp5s0
 44:     257268          0   PCI-MSI-edge      xhci_hcd
 45:          0          0   PCI-MSI-edge      xhci_hcd
 46:          0          0   PCI-MSI-edge      xhci_hcd
 47:          0          0   PCI-MSI-edge      xhci_hcd
 48:          0          0   PCI-MSI-edge      xhci_hcd
 49:     465462          0   PCI-MSI-edge      snd_hda_intel
 50:    3895788          0   PCI-MSI-edge      iwlwifi
NMI:       8687       9483   Non-maskable interrupts
LOC:   17531664   16978131   Local timer interrupts
SPU:          0          0   Spurious interrupts
PMI:       8687       9483   Performance monitoring interrupts
IWI:     213009     205171   IRQ work interrupts
RTR:          3          0   APIC ICR read retries
RES:    1922651    4491695   Rescheduling interrupts
CAL:      73741     348678   Function call interrupts
TLB:      98634     111173   TLB shootdowns
TRM:          0          0   Thermal event interrupts
THR:          0          0   Threshold APIC interrupts
MCE:          0          0   Machine check exceptions
MCP:        286        286   Machine check polls
ERR:          0
MIS:          0

# ifconfig wlp9s0
wlp9s0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        inet 192.168.0.24  netmask 255.255.255.0  broadcast 192.168.0.255
        inet6 fe80::4e80:93ff:fe15:e6c7  prefixlen 64  scopeid 0x20<link>
        ether 4c:80:93:15:e6:c7  txqueuelen 1000  (Ethernet)
        RX packets 811806  bytes 992611146 (946.6 MiB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 490006  bytes 71390887 (68.0 MiB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

# dmesg
...
[   11.789302] Intel(R) Wireless WiFi driver for Linux, in-tree:d
[   11.789310] Copyright(c) 2003-2013 Intel Corporation
[   11.791626] iwlwifi 0000:09:00.0: irq 50 for MSI/MSI-X
[   12.044905] iwlwifi 0000:09:00.0: loaded firmware version 18.168.6.1 op_mode iwldvm
[   13.896033] iwlwifi 0000:09:00.0: CONFIG_IWLWIFI_DEBUG enabled
[   13.896041] iwlwifi 0000:09:00.0: CONFIG_IWLWIFI_DEBUGFS disabled
[   13.896044] iwlwifi 0000:09:00.0: CONFIG_IWLWIFI_DEVICE_TRACING disabled
[   13.896047] iwlwifi 0000:09:00.0: CONFIG_IWLWIFI_DEVICE_TESTMODE disabled
[   13.896049] iwlwifi 0000:09:00.0: CONFIG_IWLWIFI_P2P disabled
[   13.896054] iwlwifi 0000:09:00.0: Detected Intel(R) Centrino(R) Wireless-N 1030 BGN, REV=0xB0
[   13.896173] iwlwifi 0000:09:00.0: L1 Disabled; Enabling L0S
[   13.917705] ieee80211 phy0: Selected rate control algorithm 'iwl-agn-rs'


> 
> 
>>> Nope, you get that message once to tell you that we throttle RT tasks.
>>
>> I think the message could improved to explain this is a warn ONCE message and
>> that there is no "[sched_delayed] sched: RT throttling deactivated" counterpart
>> message to be anticipated.
> 
> Would something like: 
> 
>   sched: [ONCE] RT throttle hit -- inspect system configuration.
> 
> Be a better message?

Not really. I would prefer something like:

[sched_delayed] sched: stopped running $cmd on CPU%d in favor of RR/FIFO task $psname

where the "$cmd" would be something like what "ps -deo pid,cls,cmd | grep -e RR -e FF" gives?

Still, I think when the interrupted task is ran again, a "counterpart" message should be logged.
Especially to see the timing between them could be helpful?

> 
> Also, could you clarify what exact kernel version you're running? I
> couldn't find it in your previous messages.


Vanilla 3.10.9, I thought it was in the very first message ...