lkml.org 
[lkml]   [2007]   [Jul]   [24]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    Date
    From
    SubjectRe: Pin-pointing the root of unusual application latencies
    Ingo Molnar wrote:

    > add 'notrace' to the definition of read_tsc in arch/i386/kernel/tsc.c

    ( check_dektec_in-1095 |#0): new 271 us user-latency.
    ( check_dektec_in-1095 |#0): new 275 us user-latency.
    ( check_dektec_in-1095 |#0): new 290 us user-latency.
    ( check_dektec_in-1095 |#0): new 297 us user-latency.
    ( check_dektec_in-1095 |#0): new 345 us user-latency.
    ( check_dektec_in-1095 |#0): new 358 us user-latency.
    ( check_dektec_in-1095 |#0): new 384 us user-latency.
    ( check_dektec_in-1095 |#0): new 392 us user-latency.
    ( check_dektec_in-1095 |#0): new 395 us user-latency.
    ( check_dektec_in-1095 |#0): new 396 us user-latency.
    ( check_dektec_in-1095 |#0): new 1031 us user-latency.
    ( check_dektec_in-1095 |#0): new 1100 us user-latency.
    ( check_dektec_in-1095 |#0): new 1105 us user-latency.
    ( check_dektec_in-1095 |#0): new 1106 us user-latency.

    Here's the function trace for the 1106-µs latency:

    http://linux.kernel.free.fr/latency/1106-us-trace.txt

    These two lines repeat ~2000 times for ~800 µs:

    softirq--4 0.... 272us : __lock_text_start (rt_run_flush)
    softirq--4 0.... 272us : rt_spin_unlock (rt_run_flush)

    With a pair of the following in the middle:

    softirq--4 0.... 670us : call_rcu (rt_run_flush)
    softirq--4 0D..1 670us : __rcu_advance_callbacks (call_rcu)

    PID 4 is [softirq-timer/0] and has priority 50 in SCHED_FIFO.
    My process has priority 80 in SCHED_RR. It is waiting for IRQ10.

    # cat /proc/interrupts
    CPU0
    0: 37 XT-PIC-XT timer
    1: 2 XT-PIC-XT i8042
    2: 0 XT-PIC-XT cascade
    7: 0 XT-PIC-XT acpi
    10: 151250933 XT-PIC-XT eth2, Dta1xx
    11: 12435 XT-PIC-XT eth0
    12: 4 XT-PIC-XT eth1
    14: 17154 XT-PIC-XT ide0
    NMI: 0
    LOC: 5786548
    ERR: 0
    MIS: 0

    > or do echo 1 > /proc/sys/kernel/trace_use_raw_cycles
    > if you are using recent enough -rt

    http://people.redhat.com/mingo/realtime-preempt/older/patch-2.6.20-rt8

    +int trace_use_raw_cycles = 0;
    +
    +#ifdef CONFIG_EVENT_TRACE
    +/*
    + * Convert raw cycles to usecs.
    + * Note: this is not the 'clocksource cycles' value, it's the raw
    + * cycle counter cycles. We use GTOD to timestamp latency start/end
    + * points, but the trace entries inbetween are timestamped with
    + * get_cycles().
    + */
    +static unsigned long notrace cycles_to_us(cycle_t delta)
    +{
    + if (!trace_use_raw_cycles)
    + return cycles_to_usecs(delta);
    +#ifdef CONFIG_X86
    + do_div(delta, cpu_khz/1000+1);
    +#elif defined(CONFIG_PPC)
    + delta = mulhwu(tb_to_us, delta);
    +#elif defined(CONFIG_ARM)
    + delta = mach_cycles_to_usecs(delta);
    +#else
    + #error Implement cycles_to_usecs.
    +#endif
    +
    + return (unsigned long) delta;
    +}
    +#endif

    # cat /proc/sys/kernel/trace_use_raw_cycles
    0

    Should I set trace_use_raw_cycles=1 even if I notrace read_tsc?

    Regards.
    -
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

    \
     
     \ /
      Last update: 2007-07-24 10:33    [W:0.025 / U:2.520 seconds]
    ©2003-2016 Jasper Spaans. hosted at Digital OceanAdvertise on this site