sprintf braucht 16ms Zeit kann das sein?

[Chris (Gast)]

Hi!

Beim Debuggen serieller Ausgaben habe ich bemerkt, dass zwischen den 
gesendeten, sich wiederholenden Strings, eine seltsam lange Pause. Also 
habe ich Funktionen und dann einzelne Zeilen aus dem Programm genommen, 
um den Schuldigen zu finden.
Fündig geworden bin ich bei sprintf, das ich für die LCD-Ausgabe nutze.

Hier ein Beispiel, wie die betreffenden Zeilen aussehen:
//Test:
uint16_t auszugebenderwert = 12345;
//von hier
uint16_t test1= auszugebenderwert / 1000;
sprintf (buf, "%2u.%03u", (test1), auszugebenderwert-((test1)*1000));
//bis hier dauert es 16ms.


Abgesehen von der Tatsache, dass diese Funktion nur mal schnell 
programmiert ist, man es gut ohne sprintf lösen könnte und es sicherlich 
nicht nötig ist, für die Display-Ausgabe bei jedem Durchlauf der 
Hauptprogrammschleife zu berechnen, kann ich nicht glauben, dass das 
16ms dauern soll.....
Trotzdem: Nehme ich die sprintf-Zeile raus oder ersetze sie durch eine 
Funktion, die gleiche Ergebnisse liefert, verkürzt sich das Intervall 
bei der seriellen Übertragung von 21ms auf 5ms.
In diesen 5ms verarbeite ich eingehende Serielldaten, schreibe und lese 
über Hardware-SPI 7 Schieberegister, verarbeite alle Benutzereingaben 
und mehr. Die serielle Übertragung dauert dann nochmal rund 1ms.

Controller ist ein Atmega644P mit stolzen 20 Mhz.


Ist sprintf generell so langsam, oder ist an diesem Beispiel etwas 
spezielles? Könnte es an der Multiplikation liegen?

Gruß,
Chris

[Dr. Sommer (Gast)]

Chris schrieb:
> Ist sprintf generell so langsam, oder ist an diesem Beispiel etwas
> spezielles? Könnte es an der Multiplikation liegen?
Viel schlimmer - die Division! die wird in Software gemacht. Und 
ansonsten ist sprinft langsam, ja, da es ja den String parsen muss und 
sehr allgemein dabei ist.

[René B. (reneb)]

Kann dir passieren, wenn printf+Co komplett implementiert wurden. Besorg 
dir lieber eine abgespecktes printf, das nur den von dir benötigten 
Konvertierungsumfang hat.

[Roland H. (batchman)]

Dr. Sommer schrieb:
> Viel schlimmer - die Division! die wird in Software gemacht. Und
> ansonsten ist sprinft langsam, ja, da es ja den String parsen muss und
> sehr allgemein dabei ist.

René B. schrieb:
> Kann dir passieren, wenn printf+Co komplett implementiert wurden. Besorg
> dir lieber eine abgespecktes printf, das nur den von dir benötigten
> Konvertierungsumfang hat.

Schön und gut, aber die Rede ist von einem

Chris schrieb:
> Atmega644P mit stolzen 20 Mhz.

Passt das zusammen?

Chris schrieb:
> verkürzt sich das Intervall
> bei der seriellen Übertragung von 21ms auf 5ms.

Wie groß ist das Programm, und welche Baudrate wird verwendet? GCC? -Os?

Kannst Du mal ein minimales Programm testen und posten, nur mit dem 
obigen Fragment? Die These ist ja, dass der fragliche Block 16ms dauert.

Irgendwie habe ich da Zweifel :-)

[Johann L. (gjlayde)]

16ms bei 20MHz sind 320000 Ticks.  Im gezeigten Schnippel wird die Zeit 
i.W. für die 11 Divisionen verbraten.  Selbt wenn man jede Division mit 
1000 Ticks veranschlagt, bleiben immer noch rund 310000 herrenlose 
Ticks.

Ergo: Die Zeit geht woanders drauf, z.B. wegen hoher IRQ-Last, 
Warteschleifen bei der Ausgabe, etc.

[Grünkohl (Gast)]

Chris schrieb:
> Controller ist ein Atmega644P mit stolzen 20 Mhz.

.. und internem 8MHz RC-Oszillator mit ./.8 Teiler aktiv?

[Chris (Gast)]

Ich kann das auch nicht so recht glauben...

Die Baudrate ist 250000 Baud, das bestätigt auch der Logic Analyzer.

Das sprintf, um das es hier geht, hat auch nichts mit der seriellen 
Übertragung zu tun, sondern nur mit der Displayausgabe.
Die LCD-Anweisungen fallen auch nicht ins Gewicht da nur geänderte 
Zeichen ausgegeben werden (Grafik-LCD mit Fontgenerator... lahm...) und 
sich im Testszenario nichts an den Werten ändert. Testweise habe ich die 
eigentlichen LCD-Befehle auch schon raus genommen.

In der Hauptschleife wird alles (Eingabeverarbeitung, Displayausgabe, 
serielle Übertragung) nacheinander aufgerufen.

Die Division ist nicht schuld. Ich habe nun feste Werte in das sprintf 
eingefügt:
sprintf (buf, "%2u.%03u", 12, 345);
Das ergibt 19ms Abstand zwischen den versendeten Strings.

Ersetze ich sprintf durch
buf[0] = '1';
buf[1] = '2';
...
buf[5] = '5';
buf[6] = 0;
sind es nur noch 5,4ms.

Gruß,
Chris

[Grünkohl (Gast)]

Chris schrieb:
> Das ergibt 19ms Abstand zwischen den versendeten Strings.

Wird da vielleicht mit 'long long' oder 'float' gewandelt?

[Chris (Gast)]

Ach so ja: Ich programmiere über AtmelStudio6.

Wenn ich direkt nach dem sprintf ein return platziere, ist die 
Verzögerung weg. Vermutlich wird das sprintf dann weg optimiert. Lasse 
ich das return weg und packe den nachfolgenden Code in eine If-Abfrage, 
die nicht wahr wird, so ist die Verzögerung vorhanden, obwohl nach dem 
sprintf nichts mehr ausgeführt wird (mit Breakpoint verifiziert).

Morgen ersetze ich sprintf mal durch strtoul.

[Chris (Gast)]

Float: Nein
Ansonsten nur uint8 und uint16 in der ganzen Funktion. Ich habe dem 
Compiler für sprintf auch keine speziellen Dinge bezüglich der 
sprintf-Variante gesagt.

[Jörg W. (dl8dtl) (Moderator)]

Chris schrieb:
> Ach so ja: Ich programmiere über AtmelStudio6.

Hast du denn nun auch die Optimierung eingeschaltet?

[Johann L. (gjlayde)]

Chris schrieb:

> In der Hauptschleife wird alles (Eingabeverarbeitung, Displayausgabe,
> serielle Übertragung) nacheinander aufgerufen.

Also blockierend? D.h. lahme Displayausgabe blockiert die serielle 
Überttragung?

> Die Division ist nicht schuld. Ich habe nun feste Werte in das sprintf
> eingefügt:
> sprintf (buf, "%2u.%03u", 12, 345);

Gut, dann sind es nicht 11 Divisionen sondern nur noch 10.

[Chris (Gast)]

> Also blockierend? D.h. lahme Displayausgabe blockiert die serielle
> Überttragung?
Im Prinzip ja, aber nur, wenn sich der Displayinhalt ändert. Und das 
passiert im Testszenario nicht, die Display-Funktionen sind zusätzlich 
auskommentiert. Später wird die Ausgabe Timer-gesteuert gelöst 
(natürlich nicht innerhalb einer ISR).

[Peter D. (peda)]

Chris schrieb:
> Die Division ist nicht schuld. Ich habe nun feste Werte in das sprintf
> eingefügt:
> sprintf (buf, "%2u.%03u", 12, 345);
> Das ergibt 19ms Abstand zwischen den versendeten Strings.

Dieser Code simuliert im AVRStudio 4.18 mit WINAVR braucht bei 20MHz 
95,4µs (1908 Zyklen).

Deine 19ms werden also wo ganz anders verbraten. Das sprintf ist völlig 
unschuldig.

Oder hast Du etwa die Optimierung ausgeschaltet?
Die muß natürlich -Os sein.

Peter

[Chris (Gast)]

Ich konnte etwas Zeit einsparen, indem ich das sprintf durch utoa 
ersetzt habe. Aber viel ist das wirklich nicht. Ich suche weiter... Wenn 
ich feste Werte einsetze, wird wohl im weiteren Verlauf der Funktion 
einiges weg optimiert, so dass ich dachte, es liege an dem sprintf.

[Peter D. (peda)]

Vielleicht rufst Du einen Interrupt viel zu oft auf und der klaut dann 
der Mainloop die ganze CPU-Zeit.

19ms zu 95,4µs ist ja etwa 200:1. Also ein Mainzyklus auf 200 
Interrupt-Handler Zyklen.

Beim ARM merkt man sowas sofort, der läßt das Main dann garnicht mehr 
ran und alles steht.
Aber der AVR muß zwischen den Interrupts immer mindestens einen 
Main-Befehl machen.


Peter

[Jörg W. (dl8dtl) (Moderator)]

Chris schrieb:
> Ich konnte etwas Zeit einsparen, indem ich das sprintf durch utoa
> ersetzt habe.

Weiß nicht, irgendwas ist da grundlegend daneben.  Bist du dir sicher,
dass du den korrekten Takt eingestellt hast?

Ich habe mal folgendes Mini-Testprogramm geschrieben:

#include <avr/io.h>
#include <stdio.h>
#include <stdlib.h>

char buf[100];

void doit(uint16_t val)
{
  uint16_t test1= val / 1000;
  PORTD |= 1;
  sprintf (buf, "%2u.%03u", (test1), val-((test1)*1000));
  PORTD &= ~1;
}

int
main(void)
{
  DDRD = 1;

  for (;;) {
    doit(rand());
  }
}

Das rand() darin dient einerseits der Simulation möglichst vieler
verschiedener Werte, andererseits verhindet es natürlich sicher,
dass der Compiler irgendwelche Festwerte einsetzen kann.

Compiliert mit einem nicht ganz taufrischen GCC 4.5.1, mit dem dürfte
auch die avr-libc (und damit das sprintf()) compiliert worden sein,
-Os, für einen ATmega2560, der mit dem internen 8-MHz-RC-Oszillator
läuft.

Anbei die Messung mit dem Oszilloskop an Pin D0.  Der Oszi steht auf
"env", d. h. es werden die maximale und minimale Ausführungszeit
geloggt.  Die linke high-Periode ist das sprintf(), die nachfolgende
low-Periode das nächste rand().  Das sprintf() braucht zwischen 188
und 250 µs (das rand() dann um die 140 µs).  Das entspricht etwa
zwischen 1500 und 2000 Takten und entspricht damit dem, was Peter
simuliert hat.

Wenn man das auf deine 16 ms zurückrechnet, könnte man den Verdacht
haben, du würdest versehentlich mit dem 128-kHz-Oszillator arbeiten.