2016-02-02 13 views
8

Ich habe daran gearbeitet, Code zu optimieren, die soziale Grafikdaten analysiert (mit viel Hilfe von https://blog.golang.org/profiling-go-programs) und ich habe erfolgreich viele überarbeitet langsamer Code.Wie zu optimieren golang Programm, das meiste Zeit in runtime.osyield und runtime.usleep

Alle Daten werden in den Speicher geladen von db erste und die Datenanalyse von dort erscheint CPU gebunden (max Speicherverbrauch < 10MB, CPU1 @ 100%)

Aber jetzt scheint die meiste Zeit meines Programms in zu sein runtime.osyield und runtime.usleep. Wie kann man das verhindern?

Ich habe GOMAXPROCS = 1 gesetzt und der Code spawnt keine goroutines (außer was die Golang-Bibliotheken anrufen).

Das ist mein top10 Ausgabe von pprof

(pprof) top10 
62550ms of 72360ms total (86.44%) 
Dropped 208 nodes (cum <= 361.80ms) 
Showing top 10 nodes out of 77 (cum >= 1040ms) 
     flat flat% sum%  cum cum% 
    20760ms 28.69% 28.69% 20850ms 28.81% runtime.osyield 
    14070ms 19.44% 48.13% 14080ms 19.46% runtime.usleep 
    11740ms 16.22% 64.36% 23100ms 31.92% _/C_/code/sc_proto/cloudgraph.(*Graph).LeafProb 
    6170ms 8.53% 72.89%  6170ms 8.53% runtime.memmove 
    4740ms 6.55% 79.44% 10660ms 14.73% runtime.typedslicecopy 
    2040ms 2.82% 82.26%  2040ms 2.82% _/C_/code/sc_proto.mAvg 
    890ms 1.23% 83.49%  1590ms 2.20% runtime.scanobject 
    770ms 1.06% 84.55%  1420ms 1.96% runtime.mallocgc 
    760ms 1.05% 85.60%  760ms 1.05% runtime.heapBitsForObject 
    610ms 0.84% 86.44%  1040ms 1.44% _/C_/code/sc_proto/cloudgraph.(*Node).DeepestChildren 
(pprof) 

Die _/C_/code/sc_proto/* Funktionen meinen Code sind.

Und die Ausgabe von web: output from web

(besser, SVG Version von Graph hier: https://goo.gl/Tyc6X4)

+1

Ihre Grafiken sind nicht lesbar. Sie sagen uns nicht, was Ihr Programm macht. [So erstellen Sie ein minimales, vollständiges und überprüfbares Beispiel.] (Http://stackoverflow.com/help/mcve). – peterSO

+0

Verwenden Sie cgo? – JimB

+0

@ JimB nicht mit cgo; alles rein Go – Aaron

Antwort

5

die Antwort selbst gefunden, so dass ich bin Entsendung hier dies für alle anderen, die eine ist mit ähnliches Problem. Und ein besonderer Dank an @JimB, dass er mich auf den richtigen Weg geschickt hat.

Wie aus der Grafik ersichtlich, sind die Pfade, die zu osyield und usleep führen, Garbage-Collection-Routinen. Dieses Programm benutzte eine verkettete Liste, die viele Zeiger erzeugte, was eine Menge Arbeit für die GC erzeugte, die gelegentlich die Ausführung meines Codes blockierte, während sie mein Chaos beseitigte.

Letztendlich kam die Lösung für dieses Problem von https://software.intel.com/en-us/blogs/2014/05/10/debugging-performance-issues-in-go-programs (was eine tolle Ressource war). Ich folgte den Anweisungen zum Speicherprofiler dort; und die Empfehlung, Sammlungen von Zeigern mit Scheiben zu ersetzen, klärte meine Müllsammlungsprobleme auf, und mein Code ist jetzt viel schneller!

+0

Welcher SQL-Treiber? (Übrigens, ich finde auch, dass die kumulative Ausgabe hilfreich ist, da das die Uhrzeit in Funktionsaufrufen eher wie beim Aufrufstack anzeigt) – JimB

+0

Der Treiber ist der Go-SQL-Treiber unter: https://github.com/go-sql -driver/mysql Ich kam zu der Schlussfolgerung, dass mein Datenbanktreiber der Thread war, der nachgab, weil unter der Ausgabe bei http: // localhost: 6060/debug/pprof/goroutine? debug = 1 ich sehe '1 @ 0x43079c 0x43086b 0x40487d 0x4043bb 0x5451ec 0x45f0e1 # \t 0x5451ec \t datenbank/sql. (* DB) .connectionOpener + 0x4c \t C:/Go/src/datenbank/sql/sql.gehen: 727' zusammen mit meinem goroutine (nächster Kommentar) – Aaron

+0

'1 @ 0x441d10 0x53447a 0x48ba79 0x48d7f7 0x48cfe5 0x49b7da 0x48dc02 0x49a8db 0x480e9f 0x45f0e1 # \t 0x53447a \t _/C_/code/sc_proto/cloudgraph (* Node) .AddChild + 0x8A. \t C: /code/sc_proto/cloudgraph/cloudgraph.go: 92 # \t 0x49b7da \t _/C_/code/sc_proto.main.func3 + 0x7a \t \t \t C: /code/sc_proto/main.go: 887 # \t 0x48dc02 \t _/C_/code/sc_proto.main + 0x1d2 \t \t \t \t C: /code/sc_proto/main.go: 908 # \t 0x49a8db \t _/C_/code/sc_proto.Test_main + 0x1b \t \t \t C: /code/sc_proto/main_test.go: 1002 # \t 0x480e9f \t testing.tRunner + 0x9f \t \t \t \t \t C:/Go/src /testing/testing.go: 473' – Aaron