linux-kernel - Re: Pin-pointing the root of unusual application latencies

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <46A5B8E3.4060004@free.fr>
Date:	Tue, 24 Jul 2007 10:31:31 +0200
From:	John Sigler <linux.kernel@...e.fr>
To:	Ingo Molnar <mingo@...e.hu>
CC:	linux-rt-users@...r.kernel.org,
	oprofile-list@...ts.sourceforge.net, linux-kernel@...r.kernel.org
Subject: Re: 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@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/