Project

General

Profile

High latency for DMTimer interrupt

Added by Mary Frantz almost 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 almost 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 almost 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 almost 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 almost 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 almost 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 almost 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 almost 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 almost 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 almost 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 almost 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 almost 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 &lt;linux/kdb.h&gt;" 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 almost 8 years ago

Mary, Thank you for this detailed post. Please let us know how this works out.

    (1-12/12)
    Go to top
    Add picture from clipboard (Maximum size: 1 GB)