Forums » Software Development »
High latency for DMTimer interrupt
Added by Mary Frantz over 8 years ago
I have implemented a timer interrupt in a kernel module. At the start of the isr, it reads the timer value which should be close to the load register value. I am measuring the latency as the difference between the auto-reload value and the value of the counter when the isr starts, then finding the maximum over time.
The timer (DMTIMER4) is clocked at 24 MHz, and interrupts at a 2 kHz rate.
The maximum latency was 495 usec (almost the whole interrupt interval).
Module code:
/* The interrupt handler.
We get an interrupt when the timer overflows,
*/
static irqreturn_t timer_irq_handler(int irq, void *dev_id)
{
// keep track of how many calls we had
static int32_t irq_counter = 0;
int in, i;
unsigned int start, end, run;
static unsigned int starts[16];
static int idx = 0;
// reset the timer interrupt status
iowrite32(DMTIMER_IRQSTATUS_OVF_IT_FLAG ,DmTimerSS + DMTIMER_IRQSTATUS);
ioread32(DmTimerSS + DMTIMER_IRQSTATUS);
// start
start = ioread32(DmTimerSS + DMTIMER_TCRR);
irq_counter++;
// do irq stuff ....
// run time
end = ioread32(DmTimerSS + DMTIMER_TCRR);
run = end - start;
if (run > runTimeClks)
runTimeClks = run;
starts[idx++] = start;
idx &= 0x0F;
if (start > maxStart)
maxStart = start;
if (start > 0xfffffff0)
{
//printk("start = 0x%08x end = 0x%08x\n", start, end);
printk("starts: \n");
for (i=0; i<16; i++)
printk("0x%08x\n", starts[i]);
}
// tell the kernel it's handled
return (IRQ_HANDLED);
}
// Initialize the kernel module
static int __init dmtimer_init(void)
{
int ret = 0;
printk("sys7100_dmtimer: starting module init\n");
// initialize timers, etc
....
// install our IRQ handler timer
ret = request_irq(timer_irq, timer_irq_handler, IRQF_DISABLED | IRQF_TIMER , "dmtimer4", timer_irq_handler);
if(ret)
{
printk("sys7100_dmtimer: request_irq failed (on irq %d), bailing out\n", timer_irq);
return ret;
}
// done!
printk("dmtimer: DM Timer initialized and started (%lu Hz, IRQ %d)\n", (long unsigned)fsFreq, timer_irq);
// return success
return 0;
}
The kernel is compiled with Preemptable Kernel (Low-Latency Desktop) enabled.
Linux version: 3.2.0-00351-gb80917e-dirty #20 PREEMPT
Any way to tighten this up? I'd really like to run at 8kHz, but I can make 2kHz work.
Mary
Replies (12)
RE: High latency for DMTimer interrupt - Added by Gregory Gluszek over 8 years ago
Hi Mary,
You mentioned that your maximum latency is ~500 usec. Is this maximum a rare or common occurrence? What is your average latency?
One utility that might be helpful in figuring out what is going on is ftrace (https://www.kernel.org/doc/Documentation/trace/ftrace.txt). This will make your system run slightly slower when enabled, but can let you know what else is going on in the kernel that might explain the maximum latency you are experiencing.
Thanks,
\Greg
RE: High latency for DMTimer interrupt - Added by Mary Frantz over 8 years ago
No, this high latency is rare. Typical is more like 3 usec. I see this when the printk() call displays the last 16 'start' counter values.
Note, I have also removed the lcdc and touchscreen support from the kernel to eliminate those interrupts.
I have also written 0x00000004 to the ILR registers of the other interrupts present (found using cat /proc/interrupts) to make the timer interrupt the highest priority.
I will look at ftrace.
Mary
RE: High latency for DMTimer interrupt - Added by Jonathan Cormier over 8 years ago
Mary Frantz wrote:
I see this when the printk() call displays the last 16 'start' counter values.
What do you mean by this? You see the low latency or the high latency when it prints?
RE: High latency for DMTimer interrupt - Added by Mary Frantz over 8 years ago
This code:
if (start > 0xfffffff0)
{
//printk("start = 0x%08x end = 0x%08x\n", start, end);
printk("starts: \n");
for (i=0; i<16; i++)
printk("0x%08x\n", starts[i]);
}
prints the value of 'start' (the counter value at the start of the isr) for the most recent 16 interrupts occurrences, when the current value is nearing rollover.
Some example values:
root@mityarm335x:/sys/kernel/debug# [10367.447845] starts: [10367.453575] 0xffffd16f [10367.455047] 0xffffd163 [10367.457489] 0xffffd172 [10367.447845] 0xffffd16c [10367.462402] 0xffffd165 [10367.464874] 0xffffd168 [10367.467315] 0xffffd165 [10367.469757] 0xffffd166 [10367.472229] 0xffffd165 [10367.474670] 0xffffd165 [10367.477142] 0xffffd166 [10367.479583] 0xffffd166 [10367.482055] 0xffffd164 [10367.484497] 0xfffffffc [10367.486938] 0xffffd1e6 [10367.450134] 0xffffd18d [10367.452575] 0xffffd16f [10367.455047] 0xffffd163 [10367.457489] 0xffffd172 [10367.459960] 0xffffd16c [10367.462402] 0xffffd165 [10367.464874] 0xffffd168 [10367.467315] 0xffffd165 [10367.469757] 0xffffd166 [10367.472229] 0xffffd165 [10367.474670] 0xffffd165 [10367.477142] 0xffffd166 [10367.479583] 0xffffd166
The timer reload value is 0xFFFFD120
About ftrace:
The document you referred me to expect a directory called /sys/kernel/debug/tracing but no such directory exists. Is there something I need to enable in the kernel configuration?
root@mityarm335x:/sys/kernel/debug# ls asoc hid mmc1 regmap ubi bdi ieee80211 musb-hdrc.0 regulator ubifs clock memblock musb-hdrc.1 sched_features usb dynamic_debug mitysom335x omap_mux suspend_stats wakeup_sources gpio mmc0 pm_debug sys7100_digio
RE: High latency for DMTimer interrupt - Added by Jonathan Cormier over 8 years ago
Mary Frantz wrote:
This code:
[...]
prints the value of 'start' (the counter value at the start of the isr) for the most recent 16 interrupts occurrences, when the current value is nearing rollover.
Some example values:
[...]
The timer reload value is 0xFFFFD120
What is the relation between the reload value and the start values?
I know that print statements inside interrupts are very frowned on, could they be causing the high latency values.
About ftrace:
The document you referred me to expect a directory called /sys/kernel/debug/tracing but no such directory exists. Is there something I need to enable in the kernel configuration?
This link spells out which kernel configs should be enabled.
https://lwn.net/Articles/365835/
RE: High latency for DMTimer interrupt - Added by Mary Frantz over 8 years ago
For more information about how the DM Timer works, refer the the AM335x Technical Reference Manual.
To summarize, the DMTimer is configured to auto-reload the value in the reload register (in this case, 0xFFFFD120.) when it reaches it max value. It counts up to 0xFFFFFFFF, then reloads 0xFFFFD120 into the counter register. The interrupt occurs on the transition from 0xFFFFFFFF to 0xFFFFD120.
The variable 'start' is the value of the counter register when the isr executes, which should happen just after the counter is reloaded with 0xFFFFD120.
interrupt latency = (start - reload) / clkrate
Typical: latency = (0xFFFFD16F - 0xFFFFD120) / 24 MHz = 3.28 usec
Outlier: latency = (0xFFFFFFFc - 0xFFFFD120) / 24 MHz = 499.83 usec
The printk() statement is only there temporarily as a debugging tool. It is only called after the long latency has already occurred.
Regarding ftrace:
From the article:
For the purpose of debugging, the kernel configuration parameters that should be enabled are:
CONFIG_FUNCTION_TRACER
CONFIG_FUNCTION_GRAPH_TRACER
CONFIG_STACK_TRACER
CONFIG_DYNAMIC_FTRACE
I looked for these in my .config file
[linux-devkit]:~/projects/linux-mityarm-335x> cat .config | grep TRACE CONFIG_STACKTRACE_SUPPORT=y CONFIG_TRACE_IRQFLAGS_SUPPORT=y # CONFIG_RCU_TRACE is not set # CONFIG_TREE_RCU_TRACE is not set CONFIG_CAN_PM_TRACE=y # CONFIG_TRACE_SINK is not set # CONFIG_BACKTRACE_SELF_TEST is not set CONFIG_HAVE_FUNCTION_TRACER=y CONFIG_HAVE_FUNCTION_GRAPH_TRACER=y CONFIG_HAVE_DYNAMIC_FTRACE=y CONFIG_HAVE_FTRACE_MCOUNT_RECORD=y # CONFIG_FTRACE is not set [linux-devkit]:~/projects/linux-mityarm-335x>
I ran
make ARCH=arm CROSS_COMPILE=arm-arago-linux-gnueabi- menuconfig
but didn't see any entries mentioning "Trace"
Mary
RE: High latency for DMTimer interrupt - Added by Jonathan Cormier over 8 years ago
Mary Frantz wrote:
For more information about how the DM Timer works, refer the the AM335x Technical Reference Manual.
To summarize, the DMTimer is configured to auto-reload the value in the reload register (in this case, 0xFFFFD120.) when it reaches it max value. It counts up to 0xFFFFFFFF, then reloads 0xFFFFD120 into the counter register. The interrupt occurs on the transition from 0xFFFFFFFF to 0xFFFFD120.
The variable 'start' is the value of the counter register when the isr executes, which should happen just after the counter is reloaded with 0xFFFFD120.
interrupt latency = (start - reload) / clkrate
Typical: latency = (0xFFFFD16F - 0xFFFFD120) / 24 MHz = 3.28 usec
Outlier: latency = (0xFFFFFFFc - 0xFFFFD120) / 24 MHz = 499.83 usec
Okay thanks. I haven't used the hardware timers before.
The printk() statement is only there temporarily as a debugging tool. It is only called after the long latency has already occurred.
Regarding ftrace:
From the article:
[...]
I looked for these in my .config file
[...]
I ran
make ARCH=arm CROSS_COMPILE=arm-arago-linux-gnueabi- menuconfig
but didn't see any entries mentioning "Trace"
Mary
Heres what I get when I boot the devkit filesystem and kernel.
root@mitysom-335x ~ $ mount -t debugfs debugfs /sys/kernel/debug/ root@mitysom-335x ~ $ cd /sys/kernel/debug/ root@mitysom-335x /sys/kernel/debug $ ls asoc gpio mmc0 sched_features bdi hid mmc1 suspend_stats binder jbd2 omap_mux tracing bluetooth kprobes pm_debug usb clock memblock regmap wakeup_sources dri mitysom335x regulator root@mitysom-335x /sys/kernel/debug $ ls tracing/ README saved_cmdlines available_events set_event available_filter_functions set_ftrace_filter available_tracers set_ftrace_notrace buffer_size_kb set_ftrace_pid buffer_total_size_kb set_graph_function current_tracer trace dyn_ftrace_total_info trace_clock enabled_functions trace_marker events trace_options free_buffer trace_pipe kprobe_events tracing_cpumask kprobe_profile tracing_enabled options tracing_on per_cpu tracing_thresh printk_formats root@mitysom-335x /sys/kernel/debug $ uname -a Linux mitysom-335x 3.2.0-00353-g0e79938c3ba3-dirty #250 Mon Sep 28 15:18:12 EDT 2015 armv7l unknown root@mitysom-335x /sys/kernel/debug $ zcat /proc/config.gz | grep TRACE CONFIG_STACKTRACE_SUPPORT=y CONFIG_TRACE_IRQFLAGS_SUPPORT=y # CONFIG_RCU_TRACE is not set # CONFIG_TREE_RCU_TRACE is not set CONFIG_TRACEPOINTS=y CONFIG_CAN_PM_TRACE=y CONFIG_NETFILTER_XT_TARGET_TRACE=y # CONFIG_TRACE_SINK is not set CONFIG_STACKTRACE=y # CONFIG_BACKTRACE_SELF_TEST is not set CONFIG_NOP_TRACER=y CONFIG_HAVE_FUNCTION_TRACER=y CONFIG_HAVE_FUNCTION_GRAPH_TRACER=y CONFIG_HAVE_DYNAMIC_FTRACE=y CONFIG_HAVE_FTRACE_MCOUNT_RECORD=y CONFIG_CONTEXT_SWITCH_TRACER=y CONFIG_GENERIC_TRACER=y CONFIG_FTRACE=y CONFIG_FUNCTION_TRACER=y CONFIG_FUNCTION_GRAPH_TRACER=y # CONFIG_IRQSOFF_TRACER is not set # CONFIG_SCHED_TRACER is not set # CONFIG_STACK_TRACER is not set # CONFIG_BLK_DEV_IO_TRACE is not set CONFIG_DYNAMIC_FTRACE=y CONFIG_FTRACE_MCOUNT_RECORD=y # CONFIG_FTRACE_STARTUP_TEST is not set
RE: High latency for DMTimer interrupt - Added by Bob Duke over 8 years ago
Mary,
Here is a link to the RT Linux Wiki:
https://rt.wiki.kernel.org/index.php/Main_Page
There's a direct link to the 3.2-rt patch readme: https://www.kernel.org/pub/linux/kernel/projects/rt/3.2/README
-Bob
RE: High latency for DMTimer interrupt - Added by Gregory Gluszek over 8 years ago
Hi Mary,
Regarding RT Linux I would specifically recommend https://rt.wiki.kernel.org/index.php/RT_PREEMPT_HOWTO as a primer for understanding what the RT kernel changes from mainline as well as how to apply the patch. Note that this How To is for the 2.6 kernel, so there are some differences with 3.2, however, the core of the guide is still pertinent.
Please keep in mind that once you've patched the kernel you will need a bit of manual configuration in order to get the benefits that the RT kernel offers (i.e. raising the priority of the thread now associated with your IRQ, possibly assigning processes to properly real-time configured cgroups). I want to stress again the usefulness of becoming familiar with ftrace. I've found this utility to be invaluable in terms of finding out why tasks lose priority on the processor or are delayed from executing.
Let us know if you have any questions.
Thanks,
\Greg
RE: High latency for DMTimer interrupt - Added by Jonathan Cormier over 8 years ago
Note that the RT linux page also has an Ftrace guide: https://rt.wiki.kernel.org/index.php/Ftrace
RE: High latency for DMTimer interrupt - Added by Mary Frantz over 8 years ago
Here's what I did to apply the RT PREEMPT patch:
Helpful websites:
https://rt.wiki.kernel.org/index.php/RT_PREEMPT_HOWTO
https://www.osadl.org/Single-View.111+M5d103f5bd04.0.html
Get the patch (get the latest patch that matches your kernel version or you will get a lot of errors). I am using kernel 3.2.0.
# cd ~/projects # mkdir rt-patch # cd rt-patch # wget https://www.kernel.org/pub/linux/kernel/projects/rt/3.2/older/patches-3.2-rt10.tar.gz
Unpack the patch with the command line or GUI ("Extract Here"):
# tar -xvzf ../rt-patch/patches-3.2.0-rt10.tar.gz
Copy the 'patches' directory into the source tree directory using the GUI (copy/paste)
Change into the kernel source directory
# cd ~/projects/linux-mityarm-335x
I backed up my source tree at this point ... just in case.
Use quilt to apply the patches.
If necessary, and it was for me, install quilt. See http://man.cx/quilt
# sudo apt-get install quilt
Quilt expects the patch files to be located under the source tree in the directory "patches". You can set a different directory, but I didn't. A file in that directory ("series") tells quilt the order in which to apply the patches. Each patch is a summary of the 'diff' command executed after changes were made.
Query the contents of the 'series' file
# quilt series
See the contents of the stack
# quilt applied # quilt previous
Apply the patches (-v is for verbose mode, -a is for all)
# quilt push -av
Note: this failed at "kgb-serial-hackaround.patch". The changes in this patch were not extensive, but for some reason quilt didn't want to add a #include line. The error message make it clear where the error was. So...
I forced the other changes in the patch
# quilt push -fv
I added the failed line "#include <linux/kdb.h>" myself to /drivers/tty/serial/8250.c
Then I had to refresh.
# quilt refresh
Then continued with the remaining patches
# quilt push -av
You can undo a patch (I didn't try this)
# quilt revert [-P patch] {file} ...
Configure the kernel from current .config# source /usr/local/ti-sdk-am335x-evm-05.03.02.00/linux-devkit/environment-setup # make ARCH=arm CROSS_COMPILE=arm-arago-linux-gnueabi- menuconfig
Set the preemption model. Enable high resolution timer support
Kernel Features -> Preemption Model -> Fully preemptable kernel
High Resolution Timer Support
Kernel Hacking -> (enable any kernel debugging stuff you want for ftrace)
Compiled the kernel and modules. Recompiled my timer module.
Using ftrace to check it out:
root@mityarm335x:~# cd /sys/kernel/debug/tracing/ root@mityarm335x:/sys/kernel/debug/tracing# echo irqsoff > current_tracer root@mityarm335x:/sys/kernel/debug/tracing# cat tracing_max_latency 427 root@mityarm335x:/sys/kernel/debug/tracing# cat trace # tracer: irqsoff # # irqsoff latency trace v1.1.5 on 3.2.0-rt10-00351-gb80917e-dirty # -------------------------------------------------------------------- # latency: 457 us, #26/26, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0) # ----------------- # | task: swapper-0 (uid:0 nice:0 policy:0 rt_prio:0) # ----------------- # => started at: trace_hardirqs_off # => ended at: trace_hardirqs_on # # # _------=> CPU# # / _-----=> irqs-off # | / _----=> need-resched # || / _---=> hardirq/softirq # ||| / _--=> preempt-depth # |||| / _--=> migrate-disable # ||||| / delay # cmd pid |||||| time | caller # \ / ||||| \ | / <idle>-0 0d.h1. 0us : sub_preempt_count <-irq_exit <idle>-0 0d..2. 0us : rcu_enter_nohz <-irq_exit <idle>-0 0d..2. 0us : idle_cpu <-irq_exit <idle>-0 0d..2. 0us : tick_nohz_stop_sched_tick <-irq_exit <idle>-0 0d..2. 0us : ktime_get <-tick_nohz_stop_sched_tick <idle>-0 0d..2. 0us : clocksource_read_cycles <-ktime_get <idle>-0 0d..2. 0us : update_ts_time_stats.clone.10 <-tick_nohz_stop_sched_tick <idle>-0 0d..2. 0us : timekeeping_max_deferment <-tick_nohz_stop_sched_tick <idle>-0 0d..2. 0us : rcu_preempt_needs_cpu <-tick_nohz_stop_sched_tick <idle>-0 0d..2. 0us : rcu_preempt_cpu_qs <-rcu_preempt_needs_cpu <idle>-0 0d..2. 0us : sub_preempt_count <-irq_exit <idle>-0 0d..1. 0us : __irq_svc <-trace_hardirqs_on <idle>-0 0d..1. 0us : trace_hardirqs_on <-trace_hardirqs_on <idle>-0 0d..1. 0us : cpu_idle <-trace_hardirqs_off <idle>-0 0d..1. 0us : cpu_idle <-stop_critical_timings <idle>-0 0d..1. 0us : stop_critical_timings <-stop_critical_timings <idle>-0 0d..1. 0us+: am33xx_enter_idle <-trace_hardirqs_off <idle>-0 0d..1. 31us : do_gettimeofday <-am33xx_enter_idle <idle>-0 0d..1. 31us : getnstimeofday <-do_gettimeofday <idle>-0 0d..1. 31us!: clocksource_read_cycles <-getnstimeofday <idle>-0 0d..1. 427us : do_gettimeofday <-am33xx_enter_idle <idle>-0 0d..1. 427us : getnstimeofday <-do_gettimeofday <idle>-0 0d..1. 427us : clocksource_read_cycles <-getnstimeofday <idle>-0 0d..1. 427us+: am33xx_enter_idle <-trace_hardirqs_on <idle>-0 0d..1. 458us : trace_hardirqs_on <-trace_hardirqs_on <idle>-0 0d..1. 458us : <stack trace>
This seems a little high to me for just reading the time of day, which amounts to a register read.
The latency in the timer module isr around 360 usec.
Then I turned tracing off.
# echo nop > current_tracer
Now the latency of the timer module isr is 150 usec. Down from 1.5 msec, so much improved.
I will need to do more testing as my application grows. But this works for me right now.
Mary
RE: High latency for DMTimer interrupt - Added by Jonathan Cormier over 8 years ago
Mary, Thank you for this detailed post. Please let us know how this works out.
