Warum ist meine Python-App mit 'System'/Kernel CPU-Zeit angehalten

Question

Zunächst war ich nicht sicher, ob ich dies als eine Ubuntu-Frage oder hier posten sollte. Aber ich vermute, dass es eher eine Python-Frage als eine OS-Frage ist.

Meine Python-Anwendung läuft auf Ubuntu auf einem 64-Core-AMD-Server. Es zieht Bilder von 5 GigE-Kameras über das Netzwerk, indem es zu einem .so durch ctypes aufruft und verarbeitet sie dann. Ich sehe häufige Pausen in meiner Anwendung, die dazu führen, dass Bilder von den Kameras von der externen Kamerabibliothek gelöscht werden.

Um dies zu debuggen, habe ich das beliebte psutil Python-Paket verwendet, mit dem ich CPU-Status alle 0,2 Sekunden in einem separaten Thread abmelde. Ich schlafe für 0,2 Sekunden in diesem Thread und wenn dieser Schlaf wesentlich länger dauert, sehe ich auch Kamerarahmen fallengelassen. Ich habe Pausen von bis zu 17 Sekunden gesehen! Die meisten meiner Verarbeitung ist entweder in OpenCV oder Numpy (von denen beide die GIL veröffentlichen) oder in einem Teil der App eine multiprocessing.Pool mit 59 Prozessen (das es um die Python GIL zu bekommen).

Meine Debug-Protokollierung zeigt eine sehr hohe "System" (d. H. Kernel) CPU-Zeit auf vielen meiner Prozess Threads, wenn die Pausen passieren.

Zum Beispiel. Ich sehe CPU-Zeiten wie folgt (in der Regel alle 0,2 Sekunden) und dann plötzlich einen großen Sprung ('Process' Zahlen sind in der CPU-Auslastung, dh 1 CPU voll verwendet würde 1 sein, Linux top zeigt 123% wäre 1,2):

Process user | Process system | OS system % | OS idle % 
19.9   | 10.5   | 6   | 74 
5.6   | 2.3   | 4   | 87 
6.8   | 1.7   | 11   | 75 
4.6   | 5.5   | 43   | 52 
0.5   | 26.4   | 4   | 90 

Ich weiß nicht, warum die hohe Systembenutzung des Betriebssystems eine Zeile gemeldet wird, bevor die hohe Prozesssystemnutzung angepasst wird. Die beiden entsprechen seit 26.4 von 64 Kernen = 41%. An diesem Punkt erlebte meine Anwendung eine ca. 3,5 Sekunden lange Pause (wie von meinem CPU-Info-Logging-Thread mit OpenCV cv2.getTickCount() und auch der Sprung in Zeitstempel in der Python-Logging-Ausgabe bestimmt) verursacht mehrere Kamera-Frames gelöscht werden.

Wenn dies passiert, habe ich auch die CPU-Informationen für jeden Thread meines Prozesses protokolliert. Für das obige Beispiel wurden 25 Threads bei einer System-CPU-Auslastung von 0,9 und einigen weiteren bei 0,6 ausgeführt, was der Summe für den obigen Prozess von 26,4 entspricht. An diesem Punkt liefen etwa 183 Threads.

Diese Pause scheint normalerweise kurz nach der Verwendung des Multiprocessing-Pools zu erfolgen (sie wird für kurze Bursts verwendet), geschieht aber bei jedem Pool-Einsatz nicht. Wenn ich die Verarbeitungsmenge halbiere, die außerhalb des Pools stattfinden muss, passiert auch kein Überspringen der Kamera.

Frage: Wie kann ich feststellen, warum OS 'System'/Kernel-Zeit plötzlich durch das Dach geht? Warum würde das in einer Python-App passieren?

Und noch wichtiger: irgendwelche Ideen, warum das passiert und wie man es vermeidet?

Hinweise:

• Dies als root läuft (es hat für die Kamera Bibliothek leider) von upstart
• Wenn die Kameras die App neu gestartet (mit respawn in Emporkömmling) und dies geschieht mehrere ausgeschaltet Mal am Tag, so dass es nicht lange läuft, habe ich auch gesehen, dass dies sehr bald passiert, nachdem der Prozess startet
• Es ist der gleiche Code läuft über und über, es ist nicht wegen der Ausführung einer anderen Zweig meines Codes
• Derzeit verfügt über eine nice von -2, ich habe versucht, die nice ohne
• Ubuntu 12.04.5 LTS
• Python 2.7
• Maschine 128GB hat den Speichers beeinflussen zu entfernen, die ich bin nicht annähernd mit

Answer 1

OK. Ich habe die Antwort auf meine eigene Frage. Ja, ich habe über drei Monate gebraucht, um so weit zu kommen.

Es scheint GIL Thrashing in Python, das ist der Grund für die massiven 'System' CPU-Spikes und die damit verbundenen Pausen. Hier ist ein good explanation of where the thrashing comes from. Diese Präsentation hat mich auch in die richtige Richtung gelenkt.

Python 3.2 introduced a new GIL implementation um dieses Thrashing zu vermeiden. Das Ergebnis kann mit einem einfachen Gewinde Beispiel gezeigt werden (von der Darstellung oben genommen):

from threading import Thread 
import psutil 

def countdown(): 
    n = 100000000 
    while n > 0: 
     n -= 1 

t1 = Thread(target=countdown) 
t2 = Thread(target=countdown) 
t1.start(); t2.start() 
t1.join(); t2.join() 

print(psutil.Process().cpu_times())  

auf meinem MacBook Pro mit Python 2.7.9 diese verwenden 14.7s von ‚user‘ CPU und 13.2s von ‚System‘ ZENTRALPROZESSOR.

Python 3.4 verwendet 15.0s 'Benutzer' (etwas mehr) aber nur 0.2s 'System'.

So, die GIL ist immer noch an Ort und Stelle, es läuft nur noch so schnell wie wenn der Code single-threaded ist, aber es vermeidet alle GIL-Konflikte von Python 2, die als Kernel ('System') CPU-Zeit manifestiert. Diese Behauptung ist meines Erachtens der Grund für die Probleme der ursprünglichen Frage.

aktualisieren

Ein weiterer Grund für die CPU Problem mit OpenCV/TBB befunden wurde. Vollständig dokumentiert in dieser SO question.