# Ausführzeit von Funktionen

**URL:** https://forum.clonkspot.org/t/ausfuhrzeit-von-funktionen/1222
**Category:** Hilfestellung
**Created:** [13. November 2018 um 20:01 UTC](https://forum.clonkspot.org/t/ausfuhrzeit-von-funktionen/1222 "2018-11-13T20:01:27Z")
**Posts on this page:** 11
**Page:** 1

<div class="post-metadata">

### Author: ![Bratkartoffl](https://forum.clonkspot.org/letter_avatar_proxy/v4/letter/b/cab0a1/32.png) [@Bratkartoffl](https://forum.clonkspot.org/u/Bratkartoffl)
#### Post date: [13. November 2018 um 20:01 UTC](https://forum.clonkspot.org/t/ausfuhrzeit-von-funktionen/1222/1 "2018-11-13T20:01:27Z")

</div>

Hallo allerseits,  
  
ich habe folgende Funktion:  
  
`private func CalcWake(int windDirection, int saveTo) {    var t = GetSystemTime(7) + GetSystemTime(6) * 1000 + GetSystemTime(5) * 60000;        /*Code, den ich hier mal weggelassen hab um ihn nicht erklären zu müssen*/    Log("t: %v", GetSystemTime(7) + GetSystemTime(6) * 1000 + GetSystemTime(5) * 60000 - t);        CycleWindMap("CalcWakeInnerLoop", windDirection < 180, Inside(windDirection, 90, 179), start, stop, startDir, windDirection, saveTo, turbCounts);}`  
  
CycleWindMap ruft die angegebene Funktion für jedes Element eines Arrays auf.  
  
Das Problem:  
  
Als Ergebnis bekomme ich immer `"t: 0"`, der Script Profiler gibt jedoch das hier aus:  
`00999ms MAW5::CalcWake00798ms MAW5::CalcWakeInnerLoop`  
  
Wo kommen diese 200 ms Unterschied her?  
  
Danke im Voraus

---

<div class="post-metadata">

### Author: ![Kanibal](https://forum.clonkspot.org/letter_avatar_proxy/v4/letter/k/b487fb/32.png) [@Kanibal](https://forum.clonkspot.org/u/Kanibal)
#### Post date: [13. November 2018 um 20:23 UTC](https://forum.clonkspot.org/t/ausfuhrzeit-von-funktionen/1222/2 "2018-11-13T20:23:46Z")

</div>

Ich hätte dazu mindestens zwei Theorien:  
1) Rufst Du das lokal oder im Netzwerkmodus auf? Siehe Doku von [GetSystemTime()](https://crdocs.clonkspot.org/de/sdk/script/fn/GetSystemTime.html).  
2) [Windows?](https://github.com/ckanibal/clonk-rage/blob/master/engine/src/C4Script.cpp#L4821-L4836)

---

<div class="post-metadata">

### Author: ![Bratkartoffl](https://forum.clonkspot.org/letter_avatar_proxy/v4/letter/b/cab0a1/32.png) [@Bratkartoffl](https://forum.clonkspot.org/u/Bratkartoffl)
#### Post date: [13. November 2018 um 21:28 UTC](https://forum.clonkspot.org/t/ausfuhrzeit-von-funktionen/1222/3 "2018-11-13T21:28:42Z")

</div>

1: Lokal  
2: Windows 7  
  
Ich habe die Ausgabe der Zeitdifferenz nochmal unter den Aufruf von CycleWindMap gesetzt  
Anscheined macht es einen Unterschied, mit welchen Parametern die Funktion aufgerufen wird  
windDirection == 90:  
  
`t: 0t: 48100481ms  MAW5::CalcWake00467ms  MAW5::CalcWakeInnerLoop`  
  
windDirection == 270:  
  
`t: 0t: 52500526ms  MAW5::CalcWake00312ms  MAW5::CalcWakeInnerLoop`

---

<div class="post-metadata">

### Author: ![Luchs](https://forum.clonkspot.org/user_avatar/forum.clonkspot.org/luchs/32/9_2.png) [@Luchs](https://forum.clonkspot.org/u/Luchs)
#### Post date: [14. November 2018 um 10:26 UTC](https://forum.clonkspot.org/t/ausfuhrzeit-von-funktionen/1222/4 "2018-11-14T10:26:48Z")

</div>

Jetzt sehen die Zahlen ja gut aus. CycleWindMap müsste auch irgendwo in der Ausgabe des Profilers auftauchen.

---

<div class="post-metadata">

### Author: ![Bratkartoffl](https://forum.clonkspot.org/letter_avatar_proxy/v4/letter/b/cab0a1/32.png) [@Bratkartoffl](https://forum.clonkspot.org/u/Bratkartoffl)
#### Post date: [14. November 2018 um 15:36 UTC](https://forum.clonkspot.org/t/ausfuhrzeit-von-funktionen/1222/5 "2018-11-14T15:36:28Z")

</div>

Ich habe alle sonstigen Aufrufe im Script zu CycleWindMap entfernt, jetzt bekomme ich diese Statistik:  
  
`t: 0t: 62100623ms  MAW5::CalcWake00616ms  MAW5::CycleWindMap00398ms  MAW5::CalcWakeInnerLoop`  
  
Ich verstehe immer noch nicht, wieso die Ausführzeit von CalcWakeInnerLoop so viel kürzer ist als die von CalcWake oder CycleWindMap, wenn alles, was nicht der Aufruf von CalcWakeInnerLoop ist, 0ms braucht.

---

<div class="post-metadata">

### Author: ![Luchs](https://forum.clonkspot.org/user_avatar/forum.clonkspot.org/luchs/32/9_2.png) [@Luchs](https://forum.clonkspot.org/u/Luchs)
#### Post date: [14. November 2018 um 18:14 UTC](https://forum.clonkspot.org/t/ausfuhrzeit-von-funktionen/1222/6 "2018-11-14T18:14:42Z")

</div>

Der Aufwand liegt offenbar in CycleWindMap. Wie sieht diese Funktion denn aus?

---

<div class="post-metadata">

### Author: ![Bratkartoffl](https://forum.clonkspot.org/letter_avatar_proxy/v4/letter/b/cab0a1/32.png) [@Bratkartoffl](https://forum.clonkspot.org/u/Bratkartoffl)
#### Post date: [14. November 2018 um 19:07 UTC](https://forum.clonkspot.org/t/ausfuhrzeit-von-funktionen/1222/7 "2018-11-14T19:07:10Z")

</div>

`private func CycleWindMap(string functionName, bool reverseI, bool reverseJ) {    for(var i = reverseI * xMap; Inside(i, 0, xMap); i += reverseI * -2 + 1) {        for(var j = reverseJ * yMap; Inside(j, 0, yMap); j += reverseJ * -2 + 1) {            Call(functionName, i, j, Par(3), Par(4), Par(5), Par(6), Par(7), Par(8), Par(9));        }    }}`

---

<div class="post-metadata">

### Author: ![Luchs](https://forum.clonkspot.org/user_avatar/forum.clonkspot.org/luchs/32/9_2.png) [@Luchs](https://forum.clonkspot.org/u/Luchs)
#### Post date: [14. November 2018 um 20:44 UTC](https://forum.clonkspot.org/t/ausfuhrzeit-von-funktionen/1222/8 "2018-11-14T20:44:22Z")

</div>

Das sieht grundsätzlich ok aus. Ich könnte mir schon vorstellen, dass von dieser Schleife deine 20% Overhead herkommen.  
  
Ich gehe mal davon aus, dass du die Frage hier stellst, weil der Code nicht schnell genug läuft. Daher würde ich dir empfehlen, ein paar manuelle Optimierungen mit dem Profiler auszuprobieren (es ist jeweils unklar, ob die Änderungen wirklich eine Verbesserung bringen):  
  
 - Die Berechnung von Invarianten aus der Schleife rausziehen.&nbsp; Also das aus dem 1. und 3. Teil der for-Schleifen.  
 - `Inside` inlinen, also direkt `0 &lt;= i &amp;&amp; i&#160; &lt; xMap`  
 - Direkter Funktionsaufruf statt Call. Ich meine, dass lokale Funktionsaufrufe statisch gebunden werden, sodass nicht mehr anhand des Namens gesucht werden muss.  
 - `...` statt `Par()`-Aufrufe

---

<div class="post-metadata">

### Author: ![Bratkartoffl](https://forum.clonkspot.org/letter_avatar_proxy/v4/letter/b/cab0a1/32.png) [@Bratkartoffl](https://forum.clonkspot.org/u/Bratkartoffl)
#### Post date: [15. November 2018 um 19:57 UTC](https://forum.clonkspot.org/t/ausfuhrzeit-von-funktionen/1222/9 "2018-11-15T19:57:39Z")

</div>

Du hast Recht, es liegt wirklich an CycleWindMap.  
  
Anscheinend entsteht der größte Zeitaufwand durch das Übergeben der Parameter an die aufgerufene Funktion, da lässt sich leider nichts machen.  
Meine ursprüngliche Frage ist damit beantwortet, danke für die Tipps.  
  
Jedoch habe ich noch eine weitere Frage:  
  
Mir ist beim Testen aufgefallen, dass ich die Laufzeit von CycleWindMap von ca. 200 ms auf 4 ms ( **!** ) reduzieren kann, wenn ich statt  
`CycleWindMap("Funktion", 0, 0)`  
`CycleWindMap("Funktion", 1, 1)`  
aufrufe (also rückwärts zähle anstatt vorwärts).  
Das löst natürlich alle Performance-Probleme, aber woran liegt das?

---

<div class="post-metadata">

### Author: ![Luchs](https://forum.clonkspot.org/user_avatar/forum.clonkspot.org/luchs/32/9_2.png) [@Luchs](https://forum.clonkspot.org/u/Luchs)
#### Post date: [15. November 2018 um 21:41 UTC](https://forum.clonkspot.org/t/ausfuhrzeit-von-funktionen/1222/10 "2018-11-15T21:41:47Z")

</div>

> \>Anscheinend entsteht der größte Zeitaufwand durch das Übergeben der Parameter an die aufgerufene Funktion, da lässt sich leider nichts machen.

  
Hast du da mal versucht, ob `...` statt der einzelnen Par-Aufrufe schneller ist?  
  

> \>Mir ist beim Testen aufgefallen, dass ich die Laufzeit von CycleWindMap von ca. 200 ms auf 4 ms (!) reduzieren kann

  
Seltsam, da habe ich keine Erklärung für.  
  
Edit: Hast du auch überprüft, dass du keinen off-by-one-Fehler in deiner Schleife hast? Mit Inside() läuft die Schleife tatsächlich von 0 bis xMap bzw. yMap (inklusive), anders als weiter oben von mir angenommen. Daher sollte xMap maximal LandscapeWidth()-1 sein und yMap entsprechend. Wenn du Inside() so ersetzt hast wie in meinem Post oben, dann ist klar, warum es rückwärts schneller läuft: in dem Fall macht die Schleife nämlich gar nichts.

---

<div class="post-metadata">

### Author: ![Bratkartoffl](https://forum.clonkspot.org/letter_avatar_proxy/v4/letter/b/cab0a1/32.png) [@Bratkartoffl](https://forum.clonkspot.org/u/Bratkartoffl)
#### Post date: [16. November 2018 um 17:04 UTC](https://forum.clonkspot.org/t/ausfuhrzeit-von-funktionen/1222/11 "2018-11-16T17:04:18Z")

</div>

> \>Hast du da mal versucht, ob ... statt der einzelnen Par-Aufrufe schneller ist?

  
Es liegt haupsächlich am Übergeben von i und j:  
Wenn ich mit Call eine leere Funktion aufrufe bekomme ich folgende Werte für xMap = 500 und yMap = 500  
`Call(functionName)    2300msCall(functionName, i, j)    6400msCall(functionName, i, i, j, j)    10500msCall(functionName, ...) (mit 9 übergebenen Parametern an CycleWindMap)    2380msCall(functionName, Par(2), Par(3), Par(4), Par(5), Par(6), Par(7), Par(8), Par(9))    2480ms`  
... ist also etwas schneller  
  
Bei rückwärts zählen bekomme ich ca. `200ms` ohne i und j, `250ms` mit und `300ms` mit weiteren Parametern (Unterschied zwischen ... und Par konnte ich nicht feststellen)  
  

> \>Wenn du Inside() so ersetzt hast wie in meinem Post oben, dann ist klar, warum es rückwärts schneller läuft: in dem Fall macht die Schleife nämlich gar nichts.

  
Ich habe die Funktion verwendet die ich weiter oben gepostet habe, die übergebene Funktion wurde auch für alle Werte von i und j aufgerufen.  
  

> \>Daher sollte xMap maximal LandscapeWidth()-1 sein und yMap entsprechend.

  
xMap ist (LandscapeWidth() - 1) / 15 und bezieht sich auf einen Array mit Länge xMap + 1
