Ich versuche, das folgende Jitter-Problem auf Linux zu lösen. Ich rufe sendto() genau auf die gleiche Weise mit den exakt gleichen Daten 2 Millionen mal auf. Meine Min/Max/Durchschnittswerte sind: Min, Max, Durchschnitt, 1175,14211,1322,858685. Das sind Nanosekunden. Min ist 1175, der Durchschnitt ist 1323, aber der Höchstwert ist 14211, was +10 Mal der Durchschnitt ist. Ich schließe nicht einmal den ersten Aufruf von sendto() ein, um Cache-Miss-Probleme zu beseitigen. Ich habe Task-Switches und Softirqs und Interrupts als potenzielle Jitterquellen beseitigt. Die einzigen verbleibenden Quellen für Jitter sind Cache-Misses, die unwahrscheinlich erscheinen, da dies der einzige Prozess ist, der auf dieser Box läuft, so dass es keinen anderen Prozess auf einem anderen Core gibt, der den L3-Cache verschmutzt. Die andere mögliche Quelle ist etwas im Linux-Kernel selbst, aber das scheint auch unwahrscheinlich, da dies UDP ist, so dass es keinen Grund gibt, den Zustand zu halten. Selbst wenn es einige Sperren und einige Cache-Fehler gibt, scheint es unwahrscheinlich, dass dies 12000 ns ergeben würde, wenn die durchschnittliche Zeit 1322 ns beträgt. Eine Art von Speicherzuweisung im Kernel könnte jedoch denkbar lange dauern. Wie kann ich dieses Problem weiter verfolgen?Wie kann ich die Quelle dieses Jitter auf Linux aufspüren?
Edit1: Ich entfernte die memcpy und die Ergebnisse ein wenig verändert, aber der Jitter ist in erster Linie immer noch da:
new max,time is 3029
new max,time is 3746
new max,time is 5287
new max,time is 6043
new max,time is 9882
min,max,average,1837,9882,2087.033864
Edit 2: Ich entfernte die sendto() mit einer Schleife rufen Sie die Memcpy 600 mal tun und die Ergebnisse sind:
new max,time is 1894
new max,time is 1922
new max,time is 1923
new max,time is 1925
new max,time is 1928
new max,time is 2002
new max,time is 4530
new max,time is 9269
new max,time is 9466
min,max,average,1880,9466,1881.731031
Da diese Ergebnisse ziemlich nah an den gleichen sind es nichts mit dem sendto() aufrufe, sich aber ein anderen systemischen Problem zu tun. Hier
ist das Setup:
uname -a
Linux ubuntu 3.13.0-24-generiC#47-Ubuntu SMP Fri May 2 23:30:00 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux
cat /proc/cmdline
BOOT_IMAGE=/boot/vmlinuz-3.13.0-24-generic root=UUID=9cd0a310-313a-4445-8594-39a7fc037b1e ro isolcpus=1-11 nohz_full=1-11 rcu_nocbs=1-11 intel_idle.max_cstate=0 intel_pstate=disable
cat /proc/cpuinfo | more
processor : 0
vendor_id : GenuineIntel
cpu family : 6
model : 62
model name : Intel(R) Xeon(R) CPU E5-2630 v2 @ 2.60GHz
stepping : 4
microcode : 0x415
cpu MHz : 2599.941
cache size : 15360 KB
physical id : 0
siblings : 6
core id : 0
cpu cores : 6
apicid : 0
initial apicid : 0
fpu : yes
fpu_exception : yes
cpuid level : 13
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bt
s rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx smx est tm2 ssse3 cx16 xtpr pdcm pcid dca sse4_1 sse4_2 x2apic popcnt tsc_deadline_timer aes xsave avx
f16c rdrand lahf_lm arat epb xsaveopt pln pts dtherm tpr_shadow vnmi flexpriority ept vpid fsgsbase smep erms
bogomips : 5199.88
clflush size : 64
cache_alignment : 64
address sizes : 46 bits physical, 48 bits virtual
power management:
... abgeschnitten 5 mehr Kerne. Ich habe Hyperthreading abgeschaltet, aber das hat nichts ausgemacht.
ich kompilieren den folgenden Code mit: g ++ -O2 jitter.cpp
#include <stdio.h>
#include <sys/time.h>
#include <inttypes.h>
#include <stdint.h>
#include <stdlib.h>
#include <string.h>
#include <sys/socket.h>
#include <netinet/in.h>
#include <strings.h>
#include <arpa/inet.h>
#include <time.h>
#include <unistd.h>
#include <sys/syscall.h>
void udp_send()
{
struct timespec tpe1, tpe2;
int sockfd,n;
struct sockaddr_in servaddr,cliaddr;
char sendline[1000];
sockfd=socket(AF_INET,SOCK_DGRAM,0);
bzero(&servaddr,sizeof(servaddr));
servaddr.sin_family = AF_INET;
// servaddr.sin_addr.s_addr=inet_addr("127.0.0.1");
servaddr.sin_addr.s_addr=inet_addr("192.168.5.51");
servaddr.sin_port=htons(3000);
int nIterations = 2000000;
int64_t *tTime = new int64_t[nIterations];
int k = 0;
for(k = 0; k < nIterations; k++)
{
clock_gettime(CLOCK_REALTIME, &tpe1);
memcpy(sendline, sendline+200, 64);
int n = sendto(sockfd,sendline,64,0,(struct sockaddr *)&servaddr,sizeof(servaddr));
if (n != 64)
printf("failed to send\n");
clock_gettime(CLOCK_REALTIME, &tpe2);
int64_t t2 = (tpe2.tv_sec - tpe1.tv_sec) *1000000000 + tpe2.tv_nsec - tpe1.tv_nsec;
if (k > 0)
tTime[k] = t2;
}
int64_t tMax = 0;
int64_t tMin = 99999999999;
int64_t tTotal = 0;
for (k = 1; k < nIterations; k++)
{
int64_t t2 = tTime[k];
if (t2 > tMax) { tMax = t2; printf("new max,time is %ld\n", tMax); }
if (t2 < tMin) tMin = t2;
if (t2 > 20000) { printf("that took too long,took,%ld\n", t2); }
tTotal += t2;
}
printf("min,max,average,%ld,%ld,%f\n", tMin, tMax, tTotal*1.0/nIterations);
}
int main()
{
udp_send();
return 0;
}
ich es mit diesem Skript ausgeführt (die ich aus dem Linux-dynticks Projekt nahm) (sudo ./run), die alle bewegt sich der Interrupts zu Core 0 und Einrichten der Ablaufverfolgung. Hier
#!/bin/bash
# Full dyntick CPU on which we'll run the user loop,
# it must be part of nohz_full kernel parameter
TARGET=5
NR_CPUS=$(getconf _NPROCESSORS_ONLN)
# Migrate nocb tasks to CPU 0
# Beware, this assume that there is no online CPU > NR_CPUS
for CPU in $(seq $(($NR_CPUS-1)))
do
PIDS=$(ps -o pid= -C rcuob/$CPU,rcuos/$CPU,rcuop/$CPU)
for PID in $PIDS
do
taskset -cp 0 $PID
done
done
# Migrate irqs to CPU 0
for D in $(ls /proc/irq)
do
if [[ -x "/proc/irq/$D" && $D != "0" ]]
then
echo $D
echo 1 > /proc/irq/$D/smp_affinity
fi
done
# Delay the annoying vmstat timer far away
sysctl vm.stat_interval=300
# Shutdown nmi watchdog as it uses perf events
sysctl -w kernel.watchdog=0
# Pin the writeback workqueue to CPU0
echo 1 > /sys/bus/workqueue/devices/writeback/cpumask
DIR=/sys/kernel/debug/tracing
echo > $DIR/trace
echo 0 > $DIR/tracing_on
# Uncomment the below for more details on what disturbs the CPU
echo 0 > $DIR/events/irq/enable
echo 1 > $DIR/events/sched/sched_switch/enable
echo 1 > $DIR/events/workqueue/workqueue_queue_work/enable
echo 1 > $DIR/events/workqueue/workqueue_execute_start/enable
echo 1 > $DIR/events/timer/hrtimer_expire_entry/enable
echo 1 > $DIR/events/timer/tick_stop/enable
echo 1 > $DIR/events/timer/enable
echo 0 > $DIR/events/net/enable
echo 0 > $DIR/events/sock/enable
echo 0 > $DIR/events/udp/enable
echo 0 > $DIR/events/skb/enable
echo nop > $DIR/current_tracer
echo 1 > $DIR/tracing_on
# Run a 10 secs user loop on target
taskset -c $TARGET /usr/lib/linux-tools/3.13.0-24-generic/perf stat ./a.out > dfa.tmp &
# chrt -f 99 taskset -c 1 ./a.out
sleep 30
killall a.out
# Checkout the trace in trace.* file
cat /sys/kernel/debug/tracing/per_cpu/cpu$TARGET/trace > trace.$TARGET
ist die resultierende Datei dfa.tmp:
new max,time is 2196
new max,time is 2729
new max,time is 5900
new max,time is 11621
new max,time is 14211
min,max,average,1175,14211,1322.858685
Hier ist das resultierende System Trace-Datei:
# tracer: nop
#
# entries-in-buffer/entries-written: 34361/34361 #P:6
#
# _-----=> irqs-off
# /_----=> need-resched
# |/_---=> hardirq/softirq
# ||/_--=> preempt-depth
# |||/ delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
<idle>-0 [005] dN.. 733.720555: hrtimer_cancel: hrtimer=ffff88087fd4eca0
<idle>-0 [005] dN.. 733.720555: hrtimer_start: hrtimer=ffff88087fd4eca0 function=tick_sched_timer expires=733280000000 softexpires=733280000000
<idle>-0 [005] d... 733.720556: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=taskset next_pid=1312 next_prio=120
perf-1312 [005] .... 733.721806: hrtimer_init: hrtimer=ffff880850b53378 clockid=CLOCK_MONOTONIC mode=HRTIMER_MODE_REL
perf-1312 [005] d... 733.721857: tick_stop: success=no msg=more than 1 task in runqueue
perf-1312 [005] d... 733.721883: sched_switch: prev_comm=perf prev_pid=1312 prev_prio=120 prev_state=S ==> next_comm=perf next_pid=1314 next_prio=120
a.out-1314 [005] dN.. 733.721934: tick_stop: success=no msg=more than 1 task in runqueue
a.out-1314 [005] d... 733.721936: sched_switch: prev_comm=perf prev_pid=1314 prev_prio=120 prev_state=R ==> next_comm=perf next_pid=1312 next_prio=120
perf-1312 [005] d... 733.722111: sched_switch: prev_comm=perf prev_pid=1312 prev_prio=120 prev_state=S ==> next_comm=perf next_pid=1314 next_prio=120
a.out-1314 [005] d.h. 733.722727: hrtimer_cancel: hrtimer=ffff88087fd4eca0
a.out-1314 [005] d.h. 733.722728: hrtimer_expire_entry: hrtimer=ffff88087fd4eca0 function=tick_sched_timer now=733280000768
a.out-1314 [005] d.h. 733.722731: hrtimer_expire_exit: hrtimer=ffff88087fd4eca0
a.out-1314 [005] d.h. 733.722731: hrtimer_start: hrtimer=ffff88087fd4eca0 function=tick_sched_timer expires=733284000000 softexpires=733284000000
a.out-1314 [005] d... 733.722736: tick_stop: success=yes msg=
a.out-1314 [005] d... 733.722737: hrtimer_cancel: hrtimer=ffff88087fd4eca0
a.out-1314 [005] d... 733.722737: hrtimer_start: hrtimer=ffff88087fd4eca0 function=tick_sched_timer expires=734280000000 softexpires=734280000000
a.out-1314 [005] .... 733.722960: timer_init: timer=ffff88084f8ec1d8
a.out-1314 [005] d.s. 733.723023: timer_start: timer=ffff8808518d0650 function=neigh_timer_handler expires=4295075867 [timeout=250]
a.out-1314 [005] d... 733.986838: hrtimer_cancel: hrtimer=ffff88087fd4eca0
a.out-1314 [005] d... 733.986839: hrtimer_start: hrtimer=ffff88087fd4eca0 function=tick_sched_timer expires=734044000000 softexpires=734044000000
a.out-1314 [005] d.h. 734.487025: hrtimer_cancel: hrtimer=ffff88087fd4eca0
a.out-1314 [005] d.h. 734.487025: hrtimer_expire_entry: hrtimer=ffff88087fd4eca0 function=tick_sched_timer now=734044000419
a.out-1314 [005] d.h. 734.487028: hrtimer_expire_exit: hrtimer=ffff88087fd4eca0
a.out-1314 [005] d.h. 734.487028: hrtimer_start: hrtimer=ffff88087fd4eca0 function=tick_sched_timer expires=734048000000 softexpires=734048000000
a.out-1314 [005] d.s. 734.487029: timer_cancel: timer=ffffffff81efd6a0
a.out-1314 [005] ..s. 734.487030: timer_expire_entry: timer=ffffffff81efd6a0 function=clocksource_watchdog now=4295075808
a.out-1314 [005] d.s. 734.487031: timer_start: timer=ffffffff81efd6a0 function=clocksource_watchdog expires=4295075933 [timeout=125]
a.out-1314 [005] ..s. 734.487032: timer_expire_exit: timer=ffffffff81efd6a0
a.out-1314 [005] d... 734.487033: hrtimer_cancel: hrtimer=ffff88087fd4eca0
a.out-1314 [005] d... 734.487033: hrtimer_start: hrtimer=ffff88087fd4eca0 function=tick_sched_timer expires=734280000000 softexpires=734280000000
a.out-1314 [005] d... 734.487033: hrtimer_cancel: hrtimer=ffff88087fd4eca0
a.out-1314 [005] d... 734.487033: hrtimer_start: hrtimer=ffff88087fd4eca0 function=tick_sched_timer expires=734280000000 softexpires=734280000000
a.out-1314 [005] d.h. 734.723117: hrtimer_cancel: hrtimer=ffff88087fd4eca0
a.out-1314 [005] d.h. 734.723117: hrtimer_expire_entry: hrtimer=ffff88087fd4eca0 function=tick_sched_timer now=734280000410
a.out-1314 [005] d.h. 734.723119: hrtimer_expire_exit: hrtimer=ffff88087fd4eca0
a.out-1314 [005] d.h. 734.723119: hrtimer_start: hrtimer=ffff88087fd4eca0 function=tick_sched_timer expires=734284000000 softexpires=734284000000
a.out-1314 [005] d.s. 734.723120: timer_cancel: timer=ffff8808518d0650
a.out-1314 [005] ..s. 734.723120: timer_expire_entry: timer=ffff8808518d0650 function=neigh_timer_handler now=4295075867
a.out-1314 [005] d.s. 734.723122: timer_start: timer=ffff8808518d0650 function=neigh_timer_handler expires=4295076117 [timeout=250]
a.out-1314 [005] ..s. 734.723126: timer_expire_exit: timer=ffff8808518d0650
a.out-1314 [005] d... 734.723127: hrtimer_cancel: hrtimer=ffff88087fd4eca0
a.out-1314 [005] d... 734.723127: hrtimer_start: hrtimer=ffff88087fd4eca0 function=tick_sched_timer expires=735280000000 softexpires=735280000000
a.out-1314 [005] d.h. 735.723507: hrtimer_cancel: hrtimer=ffff88087fd4eca0
a.out-1314 [005] d.h. 735.723508: hrtimer_expire_entry: hrtimer=ffff88087fd4eca0 function=tick_sched_timer now=735280000448
a.out-1314 [005] d.h. 735.723509: hrtimer_expire_exit: hrtimer=ffff88087fd4eca0
a.out-1314 [005] d.h. 735.723509: hrtimer_start: hrtimer=ffff88087fd4eca0 function=tick_sched_timer expires=735284000000 softexpires=735284000000
a.out-1314 [005] d.s. 735.723511: timer_cancel: timer=ffff8808518d0650
a.out-1314 [005] ..s. 735.723511: timer_expire_entry: timer=ffff8808518d0650 function=neigh_timer_handler now=4295076117
a.out-1314 [005] d.s. 735.723512: timer_start: timer=ffff8808518d0650 function=neigh_timer_handler expires=4295076367 [timeout=250]
a.out-1314 [005] ..s. 735.723515: timer_expire_exit: timer=ffff8808518d0650
a.out-1314 [005] d... 735.723516: hrtimer_cancel: hrtimer=ffff88087fd4eca0
a.out-1314 [005] d... 735.723516: hrtimer_start: hrtimer=ffff88087fd4eca0 function=tick_sched_timer expires=736280000000 softexpires=736280000000
a.out-1314 [005] d... 736.452298: timer_start: timer=ffff8800368823e0 function=commit_timeout expires=4295077736 [timeout=1437]
a.out-1314 [005] d.h. 736.452533: tick_stop: success=no msg=more than 1 task in runqueue
a.out-1314 [005] d.h. 736.452534: hrtimer_cancel: hrtimer=ffff88087fd4eca0
a.out-1314 [005] d.h. 736.452535: hrtimer_start: hrtimer=ffff88087fd4eca0 function=tick_sched_timer expires=736012000000 softexpires=736012000000
a.out-1314 [005] d... 736.452536: tick_stop: success=no msg=more than 1 task in runqueue
a.out-1314 [005] d... 736.452537: sched_switch: prev_comm=a.out prev_pid=1314 prev_prio=120 prev_state=x ==> next_comm=perf next_pid=1312 next_prio=120
perf-1312 [005] d... 736.452647: timer_start: timer=ffffffff81d14ae0 function=delayed_work_timer_fn expires=4295076549 [timeout=250]
perf-1312 [005] d.h. 736.455802: hrtimer_cancel: hrtimer=ffff88087fd4eca0
Die perf Ausgabe lautet:
4223.769000 task-clock (msec) # 1.000 CPUs utilized
0 context-switches # 0.000 K/sec
0 cpu-migrations # 0.000 K/sec
1,129 page-faults # 0.267 K/sec
10,977,496,067 cycles # 2.599 GHz
5,798,270,864 stalled-cycles-frontend # 52.82% frontend cycles idle
<not supported> stalled-cycles-backend
11,756,238,450 instructions # 1.07 insns per cycle
# 0.49 stalled cycles per insn
2,093,679,462 branches # 495.690 M/sec
14,232,955 branch-misses # 0.68% of all branches
4.222272487 seconds time elapsed
Was ist das Ergebnis der Ausführung von 'mlockall (MCL_CURRENT | MCL_FUTURE)' hinzugefügt, um größere Fehler zu beseitigen? –
Ich habe das nicht versucht, aber wenn ich aus dem Urlaub zurückkomme (im September, oder ?!) werde ich es tun. Ich werde sagen, dass, als ich das ftrace lief, es ein paar Fälle von Seitenfehlern gab, die als eine Quelle von vielleicht 10-20 Usec Unterbrechungen auftraten, aber sie passierten nur früh. Die größte Unterbrechung war der Aufruf von smp_apic_timer_interrupt in apic.c, den ich erwähnte, und es war in den 60-70 Usec-Bereich, also dachte ich, ich würde mich zuerst darauf konzentrieren. Mit dem Hack zum Kernel und dem Systemaufruf konnte ich bestätigen, dass in der Tat der smp_apic_timer_interrupt für 90 +% der Zeit verantwortlich war. – user3642186
Für was es hier wert ist, sind einige Kernel-Entwickler, die über dieses Problem sprechen: https://lkml.org/lkml/2012/3/28/92 – user3642186