Le contexte change beaucoup plus lentement dans les nouveaux noyaux Linux


Answers

Peut-être que ce qui est devenu plus lent est le futex, le bloc de construction pour les variables de condition. Cela va faire la lumière:

strace -r ./test_latency 0 1 &> test_latency_strace & sleep 8 && killall test_latency

puis

for i in futex nanosleep rt_sig;do echo $i;grep $i test_latency_strace | sort -rn;done

qui montrera les microsecondes prises pour les appels système intéressants, triés par le temps.

Sur le noyau 2.6.32

$ for i in futex nanosleep rt_sig;do echo $i;grep $i test_latency_strace | sort -rn;done
futex
 1.000140 futex(0x601ac4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x601ac0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
 1.000129 futex(0x601ac4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x601ac0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
 1.000124 futex(0x601ac4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x601ac0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
 1.000119 futex(0x601ac4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x601ac0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
 1.000106 futex(0x601ac4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x601ac0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
 1.000103 futex(0x601ac4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x601ac0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
 1.000102 futex(0x601ac4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x601ac0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
 0.000125 futex(0x7f98ce4c0b88, FUTEX_WAKE_PRIVATE, 2147483647) = 0
 0.000042 futex(0x601b00, FUTEX_WAKE_PRIVATE, 1) = 1
 0.000038 futex(0x601b00, FUTEX_WAKE_PRIVATE, 1) = 1
 0.000037 futex(0x601b00, FUTEX_WAKE_PRIVATE, 1) = 1
 0.000030 futex(0x601b00, FUTEX_WAKE_PRIVATE, 1) = 1
 0.000029 futex(0x601b00, FUTEX_WAKE_PRIVATE, 1) = 0
 0.000028 futex(0x601b00, FUTEX_WAKE_PRIVATE, 1) = 1
 0.000027 futex(0x601b00, FUTEX_WAKE_PRIVATE, 1) = 1
 0.000018 futex(0x7fff82f0ec3c, FUTEX_WAKE_PRIVATE, 1) = 0
nanosleep
 0.000027 nanosleep({1, 0}, {1, 0}) = 0
 0.000019 nanosleep({1, 0}, {1, 0}) = 0
 0.000019 nanosleep({1, 0}, {1, 0}) = 0
 0.000018 nanosleep({1, 0}, {1, 0}) = 0
 0.000018 nanosleep({1, 0}, {1, 0}) = 0
 0.000018 nanosleep({1, 0}, {1, 0}) = 0
 0.000018 nanosleep({1, 0}, 0x7fff82f0eb40) = ? ERESTART_RESTARTBLOCK (To be restarted)
 0.000017 nanosleep({1, 0}, {1, 0}) = 0
rt_sig
 0.000045 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
 0.000040 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
 0.000038 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 0.000035 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
 0.000034 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
 0.000033 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 0.000032 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 0.000032 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 0.000031 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 0.000031 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 0.000028 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 0.000028 rt_sigaction(SIGRT_1, {0x37f8c052b0, [], SA_RESTORER|SA_RESTART|SA_SIGINFO, 0x37f8c0e4c0}, NULL, 8) = 0
 0.000027 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 0.000027 rt_sigaction(SIGRTMIN, {0x37f8c05370, [], SA_RESTORER|SA_SIGINFO, 0x37f8c0e4c0}, NULL, 8) = 0
 0.000027 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
 0.000025 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
 0.000025 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
 0.000023 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 0.000023 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 0.000022 rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
 0.000022 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 0.000021 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 0.000021 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 0.000021 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 0.000021 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 0.000021 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
 0.000019 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0

Sur le noyau 3.1.9

$ for i in futex nanosleep rt_sig;do echo $i;grep $i test_latency_strace | sort -rn;done
futex
 1.000129 futex(0x601764, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x601760, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
 1.000126 futex(0x601764, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x601760, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
 1.000122 futex(0x601764, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x601760, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
 1.000115 futex(0x601764, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x601760, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
 1.000114 futex(0x601764, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x601760, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
 1.000112 futex(0x601764, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x601760, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
 1.000109 futex(0x601764, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x601760, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
 0.000139 futex(0x3f8b8f2fb0, FUTEX_WAKE_PRIVATE, 2147483647) = 0
 0.000043 futex(0x601720, FUTEX_WAKE_PRIVATE, 1) = 1
 0.000041 futex(0x601720, FUTEX_WAKE_PRIVATE, 1) = 1
 0.000037 futex(0x601720, FUTEX_WAKE_PRIVATE, 1) = 1
 0.000036 futex(0x601720, FUTEX_WAKE_PRIVATE, 1) = 1
 0.000034 futex(0x601720, FUTEX_WAKE_PRIVATE, 1) = 1
 0.000034 futex(0x601720, FUTEX_WAKE_PRIVATE, 1) = 1
nanosleep
 0.000025 nanosleep({1, 0}, 0x7fff70091d00) = 0
 0.000022 nanosleep({1, 0}, {0, 3925413}) = ? ERESTART_RESTARTBLOCK (Interrupted by signal)
 0.000021 nanosleep({1, 0}, 0x7fff70091d00) = 0
 0.000017 nanosleep({1, 0}, 0x7fff70091d00) = 0
 0.000017 nanosleep({1, 0}, 0x7fff70091d00) = 0
 0.000017 nanosleep({1, 0}, 0x7fff70091d00) = 0
 0.000017 nanosleep({1, 0}, 0x7fff70091d00) = 0
 0.000017 nanosleep({1, 0}, 0x7fff70091d00) = 0
rt_sig
 0.000045 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 0.000044 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 0.000043 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 0.000040 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 0.000038 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
 0.000037 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 0.000036 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
 0.000036 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
 0.000035 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 0.000035 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
 0.000035 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
 0.000035 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
 0.000034 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 0.000031 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 0.000027 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 0.000027 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 0.000027 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 0.000027 rt_sigaction(SIGRT_1, {0x3f892067b0, [], SA_RESTORER|SA_RESTART|SA_SIGINFO, 0x3f8920f500}, NULL, 8) = 0
 0.000026 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 0.000026 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 0.000025 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
 0.000024 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 0.000023 rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
 0.000023 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 0.000022 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 0.000021 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
 0.000019 rt_sigaction(SIGRTMIN, {0x3f89206720, [], SA_RESTORER|SA_SIGINFO, 0x3f8920f500}, NULL, 8) = 0

J'ai trouvé ce rapport de bug de 5 ans qui contient un test de performance "ping pong" qui compare

  1. libpthread mutex à un seul thread
  2. Libpthread condition variable
  3. vieux signaux Uni Unix

Je devais ajouter

#include <stdint.h>

afin de compiler, ce que j'ai fait avec cette commande

g++ -O3 -o condvar-perf condvar-perf.cpp -lpthread -lrt

Sur le noyau 2.6.32

$ ./condvar-perf 1000000
NPTL
mutex                 elapsed:    29085 us; per iteration:   29 ns / 9.4e-05 context switches.
c.v. ping-pong test   elapsed:  4771993 us; per iteration: 4771 ns / 4.03 context switches.
signal ping-pong test elapsed:  8685423 us; per iteration: 8685 ns / 4.05 context switches.

Sur le noyau 3.1.9

$ ./condvar-perf 1000000
NPTL
mutex                 elapsed:    26811 us; per iteration:   26 ns / 8e-06 context switches.
c.v. ping-pong test   elapsed: 10930794 us; per iteration: 10930 ns / 4.01 context switches.
signal ping-pong test elapsed: 10949670 us; per iteration: 10949 ns / 4.01 context switches.

Je conclus que le changement de contexte du noyau 2.6.32 et 3.1.9 a effectivement ralenti, mais pas autant que vous pouvez le constater dans le noyau 3.2. Je réalise que cela ne répond pas encore à ta question, je vais continuer à creuser.

Edit: J'ai trouvé que changer la priorité en temps réel du processus (les deux threads) améliore les performances sur 3.1.9 pour correspondre à 2.6.32. Cependant, mettre la même priorité sur 2.6.32 la fait ralentir ... allez la figure - je vais y regarder de plus près.

Voici mes résultats maintenant:

Sur le noyau 2.6.32

$ ./condvar-perf 1000000
NPTL
mutex                 elapsed:    29629 us; per iteration:   29 ns / 0.000418 context switches.
c.v. ping-pong test   elapsed:  6225637 us; per iteration: 6225 ns / 4.1 context switches.
signal ping-pong test elapsed:  5602248 us; per iteration: 5602 ns / 4.09 context switches.
$ chrt -f 1 ./condvar-perf 1000000
NPTL
mutex                 elapsed:    29049 us; per iteration:   29 ns / 0.000407 context switches.
c.v. ping-pong test   elapsed: 16131360 us; per iteration: 16131 ns / 4.29 context switches.
signal ping-pong test elapsed: 11817819 us; per iteration: 11817 ns / 4.16 context switches.
$ 

Sur le noyau 3.1.9

$ ./condvar-perf 1000000
NPTL
mutex                 elapsed:    26830 us; per iteration:   26 ns / 5.7e-05 context switches.
c.v. ping-pong test   elapsed: 12812788 us; per iteration: 12812 ns / 4.01 context switches.
signal ping-pong test elapsed: 13126865 us; per iteration: 13126 ns / 4.01 context switches.
$ chrt -f 1 ./condvar-perf 1000000
NPTL
mutex                 elapsed:    27025 us; per iteration:   27 ns / 3.7e-05 context switches.
c.v. ping-pong test   elapsed:  5099885 us; per iteration: 5099 ns / 4 context switches.
signal ping-pong test elapsed:  5508227 us; per iteration: 5508 ns / 4 context switches.
$ 
Question

Nous cherchons à améliorer le système d'exploitation sur nos serveurs d'Ubuntu 10.04 LTS à Ubuntu 12.04 LTS. Malheureusement, il semble que la latence pour exécuter un thread qui est devenu exécutable a considérablement augmenté depuis le noyau 2.6 vers le noyau 3.2. En fait, les chiffres de latence que nous obtenons sont difficiles à croire.

Permettez-moi d'être plus précis sur le test. Nous avons un programme qui exécute deux threads. Le premier thread obtient l'heure actuelle (en ticks en utilisant RDTSC), puis signale une variable de condition une fois par seconde. Le deuxième thread attend sur la variable de condition et se réveille quand il est signalé. Il obtient alors l'heure actuelle (en ticks en utilisant RDTSC). La différence entre l'heure dans le deuxième thread et l'heure dans le premier thread est calculée et affichée sur la console. Après cela, le second thread attend une fois de plus la variable de condition. Il sera de nouveau signalé par le premier fil après environ une seconde passe.

Donc, en un mot, nous obtenons un fil pour la communication par thread via la mesure de la latence variable de la condition une fois par seconde en conséquence.

Dans le noyau 2.6.32, cette latence est de l'ordre de 2.8-3.5 us, ce qui est raisonnable. Dans le noyau 3.2.0, cette latence a augmenté à quelque part de l'ordre de 40-100 us. J'ai exclu toute différence de matériel entre les deux hôtes. Ils fonctionnent sur du matériel identique (processeurs double socket X5687 {Westmere-EP} fonctionnant à 3,6 GHz avec hyperthreading, speedstep et tous les états C éteints). L'application de test change l'affinité des threads pour les exécuter sur des cœurs physiques indépendants de la même socket (ie, le premier thread est exécuté sur Core 0 et le second thread sur Core 1), donc il n'y a pas de rebond des threads noyaux ou rebondissement / communication entre les douilles.

La seule différence entre les deux hôtes est que l'un exécute Ubuntu 10.04 LTS avec le noyau 2.6.32-28 (la boîte de changement de contexte rapide) et l'autre exécute le dernier Ubuntu 12.04 LTS avec le noyau 3.2.0-23 (le contexte lent boîte de commutation). Tous les paramètres du BIOS et le matériel sont identiques.

Y-a-t-il eu des changements dans le noyau qui pourraient expliquer ce ralentissement ridicule du temps nécessaire à l'exécution d'un thread?

Mise à jour: Si vous souhaitez exécuter le test sur votre build hôte et linux, j'ai posté le code à pastebin pour votre lecture. Compiler avec:

g++ -O3 -o test_latency test_latency.cpp -lpthread

Exécuter avec (en supposant que vous avez au moins une boîte à double cœur):

./test_latency 0 1 # Thread 1 on Core 0 and Thread 2 on Core 1

Mise à jour 2 : Après beaucoup de recherches dans les paramètres du noyau, les messages sur les changements du noyau et la recherche personnelle, j'ai trouvé le problème et j'ai posté la solution comme réponse à cette question.




Links