All,I have a a driver that must process an interrupt every 100 uS without missing any. I am having latency issues and I am looking for some help debugging my problem.
I am using a TME 5831 motherboard (VIA TwisterT chipset) with a custom BIOS. The SMBIOS is disabled.
I prepared a minimalistic kernel (configuration file attached) that uses a ramdisk for the apps (as to limit the scope of the latency problem). It has no disk(s) or network drivers. I use tty0 console and a serial console.
The IRQ is fired every 100 uS. The ISR for this takes typically 30 uS to execute and does some PCI transfers with the hardware. The typical latency between IRQ-assert and the execution of the ISR is about 12 uS. However sometimes IRQs for my hardware are lost or delayed.
While doing some instrumentation and using the kernel latency tracers I noticed that the scheduler sometimes take a long time to execute (50+ uS, with spikes to 99 uS).
I instrumented handle_irq() (see irq_32.diff) to take the time stamps before & after executing the ISR handlers. The time stamps are kept in some global arrays (which are exported as symbols). A utility module (irq_time.c) exports this to user-space via /proc/irq_time.
I did a run in which my custom driver is not loaded. The file report.txt (attached) shows the cpu info, the IRQ list (the timer interrupt is 0). The dump of /proc/irq_time has histograms which show that the timer interrupt has a sensible number of occurrences that gravitate around 55 uS. I managed to cause these high numbers by running this script:
while :; do cat /proc/nonexistent; done on the tty0 console.I need to understand whether this is caused by my setup or it's something to be expected from the scheduler/timer interrupt.
Regards, Vlad
cat /proc/cpuinfo
processor : 0
vendor_id : GenuineIntel
cpu family : 6
model : 11
model name : Intel(R) Celeron(TM) CPU 1200MHz
stepping : 4
cpu MHz : 1202.732
cache size : 256 KB
fdiv_bug : no
hlt_bug : no
f00f_bug : no
coma_bug : no
fpu : yes
fpu_exception : yes
cpuid level : 2
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 sep mtrr pge mca cmov pse36 mmx fxsr sse
bogomips : 2405.46
clflush size : 32
power management:
$ cat /proc/sched_debug
Sched Debug Version: v0.09, 2.6.31.5-pae #40
now at 569878.550195 msecs
.jiffies : 26987
.sysctl_sched_latency : 20.000000
.sysctl_sched_min_granularity : 4.000000
.sysctl_sched_wakeup_granularity : 5.000000
.sysctl_sched_child_runs_first : 0.000001
.sysctl_sched_features : 113917
cpu#0, 1202.732 MHz
.nr_running : 2
.load : 2048
.nr_switches : 166477
.nr_load_updates : 56987
.nr_uninterruptible : 0
.next_balance : 0.000000
.curr->pid : 10247
.clock : 569876.819824
.cpu_load[0] : 0
.cpu_load[1] : 0
.cpu_load[2] : 0
.cpu_load[3] : 0
.cpu_load[4] : 0
.rt.rt_nr_running : 0
.rt.rt_nr_uninterruptible : 4294967295
.rto_schedule : 0
.rto_schedule_tail : 0
.rto_wakeup : 0
.rto_pulled : 0
.rto_pushed : 0
.yld_count : 0
.sched_switch : 0
.sched_count : 166492
.sched_goidle : 53938
.ttwu_count : 0
.ttwu_local : 0
.bkl_count : 113
cfs_rq[0]:
.exec_clock : 33842.569082
.MIN_vruntime : 109488.040579
.min_vruntime : 109478.039924
.max_vruntime : 109488.040579
.spread : 0.000000
.spread0 : 0.000000
.nr_running : 2
.load : 2048
.nr_spread_over : 0
rt_rq[0]:
.rt_nr_running : 0
.rt_throttled : 0
.rt_time : 0.244658
.rt_runtime : 950.000000
runnable tasks:
task PID tree-key switches prio exec-runtime sum-exec sum-sleep
----------------------------------------------------------------------------------------------------------
sh 94 109488.040579 1368 120 109488.040579 76.460871 565643.825364
R cat 10247 109478.039924 0 120 109478.039924 0.000000 0.000000
$ cat /proc/schedstat
version 15
timestamp 27327
cpu0 0 0 167641 54449 0 0 34327664830 27532065207 113177
$ cat /proc/interrupts
CPU0
0: 57955 XT-PIC-XT timer
1: 46 XT-PIC-XT i8042
2: 0 XT-PIC-XT cascade
4: 4062 XT-PIC-XT serial
8: 0 XT-PIC-XT rtc
12: 3 XT-PIC-XT i8042
NMI: 0 Non-maskable interrupts
TRM: 0 Thermal event interrupts
MCE: 0 Machine check exceptions
MCP: 2 Machine check polls
ERR: 0
$ cat /proc/irq_time
IRQ count avg usS max uS
0 58634 11 89
1 46 6 25
4 4123 18 30
12 3 9 10
IRQ usS count
0 7 6
0 8 54032
0 9 907
0 10 201
0 11 34
0 12 25
0 13 13
0 14 11
0 15 4
0 16 3
0 17 1
0 18 7
0 20 2
0 21 3
0 22 3
0 23 1
0 29 4
0 30 2
0 31 4
0 32 7
0 33 5
0 34 19
0 35 22
0 36 23
0 37 23
0 38 33
0 39 32
0 40 44
0 41 47
0 42 56
0 43 76
0 44 93
0 45 148
0 46 184
0 47 133
0 48 148
0 49 114
0 50 92
0 51 83
0 52 77
0 53 86
0 54 66
0 55 63
0 56 61
0 57 70
0 58 101
0 59 99
0 60 123
0 61 211
0 62 294
0 63 312
0 64 212
0 65 100
0 66 51
0 67 11
0 68 7
0 69 2
0 70 2
0 71 5
0 72 5
0 73 6
0 74 3
0 75 5
0 76 2
0 77 6
0 79 3
0 82 1
0 85 1
0 87 1
0 88 2
0 89 1
IRQ usS count
1 5 39
1 6 2
1 7 2
1 18 1
1 20 1
1 25 1
IRQ usS count
4 5 557
4 6 156
4 7 74
4 8 122
4 9 73
4 10 45
4 11 39
4 12 79
4 13 97
4 14 174
4 15 180
4 16 132
4 17 162
4 18 154
4 19 121
4 20 171
4 21 104
4 22 90
4 23 119
4 24 187
4 25 179
4 26 195
4 27 298
4 28 425
4 29 178
4 30 12
IRQ usS count
12 8 1
12 9 1
12 10 1
Attachment:
config-rt-100Hz.gz
Description: GNU Zip compressed data
Attachment:
irq_32.diff
Description: Binary data
Attachment:
irq_time.c
Description: Binary data
