Go Down

Topic: Arduino 1.0 -> Serial.print NOT asynchronous? (Read 5102 times) previous topic - next topic

wipo

Jan 02, 2012, 09:52 am Last Edit: Jan 02, 2012, 08:12 pm by Coding Badly Reason: 1
Hi,

first of al, english is not my first nor my second language so I'll try to do my best.

In the past  few months I worked with the arduino 0022 software. Yesterday I finaly downloaded the new Arduino 1.0 software, where I found some interesting new feature in the serial.print function:

arduino reference page: "As of version 1.0, serial transmission is asynchronous; Serial.print() will return before any characters are transmitted."


So I made a little sketch to test this.


Code: [Select]
void loop() //Main Loop
{
 timebegin = millis();   //take the time before sending data
 Serial.print("lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj");   // some random text, not important
 timeend = millis(); //take the time afte sending data
 Serial.println();
 Serial.print(timeend);
 Serial.print(",");
 Serial.println(timeend);
 delay(100); //wait some time before doing this loop again.
}



If I do timeend - timebegin. I get a value of 5ms. So the serial.print function took 5ms before returning. I compiled this sketch with arduino 0022 and arduino 1.0. There is no difference in time so where is the asynchronous ???

So if in arduino 1.0 the Serial.print() really would return before any characters are transmitted, why does It take 5ms to return and why is there no difference in time with the arduino 0022 version?


Moderator edit: [code] [/code] tags added.

PaulS

Quote
If I do timeend - timebegin. I get a value of 5ms. So the serial.print function took 5ms before returning.

Since you didn't show setup, where Serial.begin() sets the speed, it's impossible for anyone else to replicate your test.

At reasonable baud rates, millis() is not particularly good as a timer. It's like using a calendar to time how long it takes your wife to get ready to go somewhere. Makes you feel like you are doing something, but that's about all.

Try using micros(), instead. Also, post ALL of your code.


wipo

#3
Jan 02, 2012, 11:17 am Last Edit: Jan 02, 2012, 08:14 pm by Coding Badly Reason: 1
Ok here it goes

its an atmega328 8mhz board.

changed code to

Code: [Select]
unsigned long timebegin;
unsigned long timeend;
void setup()
{
 Serial.begin(57600);
 
}
void loop()
{
 timebegin = micros();  
 Serial.print("lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj");  
 timeend = micros();
 Serial.println();
 Serial.println(timeend-timebegin);
 delay(100);
}


output in arduino serial monitor for 0022
Code: [Select]
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
5472
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
5464
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
5472
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
5472
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
5472
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
5472
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
5472
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
...



output in arduino serial monitor for 1.0
Code: [Select]
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
2208
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
2208
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
2208
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
2208
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
2208
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
2208
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
....


Ok, now I see some difference. But still 2ms is a long time for just filling a streambuffer  that will be send assync.

The fact is that I have another lager sketch with serial.print in it and a (fps) loopcounter. Logically I should, with the 1.0 version compared to the 0022 version now get more FPS/Counts in this sketch. But I don't :s


Moderator edit: [code] [/code] tags added.

wipo

#4
Jan 02, 2012, 12:53 pm Last Edit: Jan 02, 2012, 08:15 pm by Coding Badly Reason: 1
whow again I did find a strange behaviour with this new serial.print().

Take the sketch in prevouis post change baudrate to 19200 and you get this output in arduino 1.0
Code: [Select]
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
1832
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
1832
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
1824
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
1832
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
1832
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
1808
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
1824
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
1824
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
1832



So the time spend for serial.print() for sending the same string is less when decreasing baudrate. Increase the baudrate and the time spend by serial.print() will be larger. :s  Can some explain this? :)


Moderator edit: [code] [/code] tags added.

Graynomad

Baud rate should have no affect on this until the buffer fills up at which time you will see delays.

Is the data displayed starting at the absolute first printing, or after some time?

I would just do this once in setup and get the timing from that.

______
Rob
Rob Gray aka the GRAYnomad www.robgray.com

Coding Badly

#6
Jan 02, 2012, 08:48 pm Last Edit: Jan 02, 2012, 08:49 pm by Coding Badly Reason: 1

I cannot reproduce your test results.

The test...

Code: [Select]
unsigned long timebegin;
unsigned long timeend;

void setup()
{
 Serial.begin(57600);
 
}

static char S[] = "123456789.123456789.123456789.123456789.123456789.123456789.123456789.123456789.123456789.123456789.";
static unsigned short D[sizeof(S)];

void loop()
{
 char* R;
 unsigned short* P;

 R = &S[0];
 P = &D[0];

 while ( *R != 0 )
 {
   timebegin = micros();  
   Serial.write( *R );  
   timeend = micros();
   *P = timeend - timebegin;
   ++R;
   ++P;
 }

 Serial.println();
 Serial.println();

 R = &S[0];
 P = &D[0];

 while ( *R != 0 )
 {
   Serial.println( *P );
   ++R;
   ++P;
 }
 Serial.println();
 Serial.flush();

 delay( 5000 );
}


The results...

Code: [Select]
123456789.123456789.123456789.123456789.123456789.123456789.123456789.123456789.123456789.123456789.

52  <-- ISR fires sending the first byte
44  <-- ISR fires sending the second byte
28  <-- third byte buffered
24
24
48  <-- ISR fires sending the third byte
24
24
24
28
44
28
24
28
24
48
24
24
24
24
48
24
28
24
28
44
28
32
24
24
48
24
24
24
28
44
28
24
28
24
48
24
24
24
24
48
24
28
24
28
44
28
24
24
24
44
24
32
24
28
44
28
24
28
24
48
24
24
24
24
48
24
28
24
28
44
28
24
24
24
48
164  <-- buffer full; write blocks
164
168
164
168
164
168
164
168
164
168
164
168
164
168
164
168
164
168

123456789.123456789.123456789.123456789.123456789.123456789.123456789.123456789.123456789.123456789.

52
48
24
24
24
52
24
24
24
28
44
28
24
28
24
48
24
24
24
24
48
24
28
24
28
44
28
24
24
24
48
24
24
28
24
52
28
24
28
24
48
24
24
24
24
48
24
28
24
28
44
28
24
24
24
48
24
24
24
24
48
24
28
24
24
52
24
28
24
24
48
24
24
24
28
44
28
24
28
24
48
156
168
172
160
164
168
164
168
164
160
164
168
164
168
164
168
164
168
164



Looks to me like Serial is working.

fat16lib

#7
Jan 02, 2012, 10:01 pm Last Edit: Jan 03, 2012, 12:22 am by fat16lib Reason: 1
Are you using the latest release of Arduino 1.0?

Are you using a 8 MHz board?

When I run your sketch I get this
Quote

lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
956
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
952
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
956
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
956
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
956
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
952
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
956
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
952
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
952

This is still very slow.  I have been working with sixeyes to optimize writing strings to a serial port.  See http://arduino.cc/forum/index.php/topic,85207.0.html.

The problem is that print(const char*)  ends up writing to the buffer a character at a time.  My new serial library is faster but still a bit slow since Print::print(const char*) calls Print::write(const char*) which does character at a time writes.

With my new library I get
Quote
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
276
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
276
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
272
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
272
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
272
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj


I have optimized write(const char*) in my new serial library. I will soon post the version with optimized write(const char*).

If I change the print to write with my new library like this:
Code: [Select]
#include <SerialPort.h>
// port zero, 63 byte RX buffer 63 byte TX buffer
SerialPort<0, 63, 63> NewSerial;
#define Serial NewSerial

unsigned long timebegin;
unsigned long timeend;
void setup()
{
 Serial.begin(57600);
 
}
void loop()
{
 timebegin = micros();  
 Serial.write("lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj");  
 timeend = micros();
 Serial.println();
 Serial.println(timeend-timebegin);
 delay(100);
}

I get very fast buffering:
Quote

lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
52
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
56
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
60
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
52
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
64
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
64
lkjljlkjlkjljlkjlkjlkjlkjlkjlkjlkj
52



wipo

@Coding Badly:
thx for taking the time to do some tests. But you have a complete other sketch. Please try to use my sketch on a 8mhz board like I did. For most beginners, my sketch is more easy to understend. Your sketch does in fact the same but your code is more difficult for most beginners. So if you conclude that your timings are good with your code, then why are my timings bad with my code?

@fat16lib:
Also thx for taking your time to check out my problem. I'll check out your topic and test your code asap.



INFO: I use a atmega328 board running on 8mhz and downloaded the last arduino 1.0 version.
EXTRA: I took the time to compile some other sketches with arduino 1.0 and they are all slower compared to the same sketch compiled with arduino 0022. I do use micros() to compare timings en also use a simple loopcounter. I think I'll stay with arduino 0022 for a while.

Graynomad

Rob Gray aka the GRAYnomad www.robgray.com

Coding Badly


Apply this...

http://arduino.cc/forum/index.php/topic,85908.msg643676.html#msg643676

...and please let us know if it makes a difference.

kawoonoon

hi guys..
I just want to clarify,

what communication does Serial.print() do?
is it asynchronous or synchronous?

thank you...

Graynomad

Rob Gray aka the GRAYnomad www.robgray.com

Go Up