Unexpected delay in serial output.

[david]

Hi All,
While examining the serial data output on my project I noticed a lengthy delay between what I thought would be two consecutive numbers.
The device is a 12F1840 running at 16MHz and the serial output is at 115200 baud.  The snippet of code is as follows and the value of turns and dist were both 3 digit numbers-

      HRSOut "Batt OK",13,10   
   EndIf
   HRSOut SDec turns,"t ",13,10, SDec dist,"m ",13,10

Timing
HRSOut "BATT OK",13,10    takes 865uS
short delay               takes 87uS
HRSOut SDec turns,"t ",13,10   takes 603uS
delay                        takes 12.1mS    ****
SDec dist,"m ",13,10      takes 1.16mS

So where does that 12.1mS delay come from?   I should also add that the time for the second value sent is nearly twice as long as the first value yet both are 3 digit numbers followed by a letter and then CR/LF.  There is a delay of 410uS between the 1st and second digit of the second value sent (dist) and a smaller delay of 170uS between the 2nd and 3rd digit.

At first I thought it maybe the signed decimal but the 12.1mS delay is still there when the values are Dec and besides, why wouldn't they be the same?  I've also broken it in to two separate HRSOut lines but the delay is still there.
The full code is quite simple with no interrupts.    I'm looking for assistant guessers here but would also welcome anyone who may actually know what's going on.

Cheers,
David

[trastikata]

Hello David,

Did you measure the time delays on the PIC or the PC side?

[david]

Hello trastikata,
Greetings from down under.
Those time intervals were obtained from a basic logic analyser using PC timing.  I've had no reason to question it so far but I'll keep an open mind.

Cheers,
David

[TimB]

Hi

Remember that any pre processing like SDec takes time.

To verify this process the data to string then time sending the string.

[david]

Hello Tim,
Yes I can accept that but then why is the delay between the "Batt ok" and the first value sent only 87uS while the delay between the two values is 12100uS?
Actually there was a slight error in my first post.  I didn't have a battery line connected so the string was "BATT BAD" and not "BATT OK" as reported earlier.  i.e. 1 extra character was sent but the timing value was correct.
That short delay of 87uS is effectively the time for a single character.
So at 115200 baud and 8,N,1 (10 chars) we have 11520 chars/sec or 1char/86.8uS
I have screen captures if anyone is curious.

Cheers,
David

[david]

OK.  So writing the same variable value in both locations makes everything work correctly so it appears to be something to do with the processing or retrieval of the second variable.   

HRSOut SDec turns,"t ",13,10, SDec turns,"m ",13,10     This works correctly.
 
HRSOut SDec turns,"t ",13,10, SDec dist,"m ",13,10     This gives a large delay.


Normally dist=turns/2 so I now need to find out why such simple maths takes so long while clocking at 16MHz.

Cheers,
David

[TimB]

What var size is dist?

[david]

Funny you should ask Tim.

Previously I had turns as SWord and dist as SDWord because originally the relationship was a little more complex than dist=turns/2.
I've just found that by making turns and dist both SWord everything runs fine.

I had an earlier relationship which was more precise-   dist=turns/2-turns*turns/65536.   (2nd order polynomial)
That was why I needed the SDWord for dist but I can also re-arrange the formula to  dist=turns/2-turns/256*turns/256.  This allows me to get by with declaring turns and dist as SWord.  This gives the correct values and has only 87uS in two places between the 3 items.   I can sleep happy tonight.

Cheers,
David

[top204]

Converting an integer to its ASCII representation takes divisions of 10 for each digit until no more divisions are required, so a 32-bit conversion takes quite a few 32-bit divisions in the loop, which itself takes quite a few loops. Signed conversion also needs to take into account the 2's complement of the integer.

This all takes time, and for a device only running at 16MHz, its actual mnemonics are only running at 4MHz. i.e. Instruction clock ratio of 4:1.

The enhanced 14-bit core devices can happily run at 32MHz, so for more speed, increase the oscillator. For even more speed, write a procedure for the conversion from integer to ASCII. There are a few methods of doing so, and if time is the requirement, unroll the code within the procedure so it does not use loops. It will make the code size larger, but also a lot faster.

[david]

Thanks for your insight and ideas Les.
Sticking to a SWord variable keeps the delay between the two variables to 87uS or one character space at 115200 baud.  I guess it was the disproportionate delay time of over 12mS for a SDWord variable that made me question what was happening.
After years of working at 4MHz and using 1k-2k chips I thought 16MHz was quite bold of me.  I know I can run at 32MHz and the UART can run happily at 230400 baud if I really get pushed but I shouldn't need to.
Maybe Ill buy some newer replacements for my old chips .....

What a great platform Positron is.  In the early days of programming I used the "canned" Basic commands a lot but as time goes on I find I'm writing more often directly to registers and Positron does both so well.  I've tried hard to understand the attraction of Arduino.  People talk about programming in Arduino but most examples I've seen attach a bunch of anonymous "include" modules with a bit of tacky code to string things together.  It seems few actually know what the include files are doing except that they perform a function such as an OLED display.  Is this the attraction?  That there is a large library of pre-programmed functions that you can click together like Lego?  I suspect I'm showing my age here. 

Best regards,
David

[trastikata]

Hello David,

With respect to Les' remark, I'd suggest, where it is possible to create a String variable with appropriate length.

Then first fill the string with the values and send that string variable, this way the timings should be correct ...

[top204]

Below is a code listing I have just adapted from the "Convert24.inc" library file (held in the C:\Users\User Name\PDS\Includes\ folder) to show how to convert a signed 32-bit integer into a String variable for enhanced 14-bit core devices or 18F devices. The original 'DwordToASCII' procedure was written for a PIC24 or dsPIC33 device.

According to the Proteus simulator, with the device operating at 32MHz, the conversion takes approx 2.38ms to complete, so at 16MHz it will take twice as long. However, the smaller the integer value to convert, the faster the conversion will be and vice-versa. The code listing also shows how easy it is to get the PIC12F1840 to run at 32MHz with its internal oscillator:

Code Select Expand

'
'   /\\\\\\\\\
'  /\\\///////\\\
'  \/\\\     \/\\\                                                 /\\\          /\\\
'   \/\\\\\\\\\\\/        /\\\\\     /\\\\\\\\\\     /\\\\\\\\   /\\\\\\\\\\\  /\\\\\\\\\\\  /\\\\\\\\\
'    \/\\\//////\\\      /\\\///\\\  \/\\\//////    /\\\/////\\\ \////\\\////  \////\\\////  \////////\\\
'     \/\\\    \//\\\    /\\\  \//\\\ \/\\\\\\\\\\  /\\\\\\\\\\\     \/\\\         \/\\\        /\\\\\\\\\\
'      \/\\\     \//\\\  \//\\\  /\\\  \////////\\\ \//\\///////      \/\\\ /\\     \/\\\ /\\   /\\\/////\\\
'       \/\\\      \//\\\  \///\\\\\/    /\\\\\\\\\\  \//\\\\\\\\\\    \//\\\\\      \//\\\\\   \//\\\\\\\\/\\
'        \///        \///     \/////     \//////////    \//////////      \/////        \/////     \////////\//
'                                  Let's find out together what makes a PIC Tick!
'
' A 32-bit integer to ASCII decimal conversion procedure demonstration.
' Written by Les Johnson for the Positron8 BASIC compiler.
'
    Device = 12F1840                                                ' Tell the compiler what device to compile for
    Declare Xtal = 32                                               ' Tell the compiler what frequency the device will be operating at (in MHz)
'
' Setup USART1
'
    Declare HRSOut1_Pin  = PORTA.0
    Declare HRSIn1_Pin   = PORTA.1
    Declare Hserial_Baud = 9600                                     ' Set the Baud rate for USART1

    Dim MyDword As SDword                                           ' Holds the value to convert to ASCII
    Dim MyString As String * 20                                     ' Holds the converted ASCII value

'------------------------------------------------------------------------------------------
' The main program starts here
'
Main:
    OSCCON = %11110010                                              ' Enable the 4xPLL so the device operates at 32MHz with its internal oscillator

    MyDword = -12345678                                             ' Load the variable to convert to ASCII
    MyString = SDwordToASCII(MyDword)                               ' Convert the signed 32-bit integer to its ASCII representation
    HRsoutLn "Result = ", MyString                                  ' Transmit the value to a serial terminal

'-----------------------------------------------------------------------------
' Convert a signed 32-bit integer value to an ASCII decimal representation in a String variable
' Input     : pValue holds the signed 32-bit value to convert
' Output    : Returns the ASCII decimal conversion as a string
' Notes     : None
'
Proc SDwordToASCII(pValue As SDword), String * 10
    Dim bDigits[10] As Byte Heap
    Dim bIndex      As Byte
    Dim bNumber     As Byte
    Dim wResAddress As Word
    Dim wDigAddress As Word

    bIndex = 0
    Clear Result
    wResAddress = AddressOf(Result)
    wDigAddress = AddressOf(bDigits)

    If pValue < 0 Then
        Ptr8(wResAddress++) = "-"
        pValue = Abs(pValue)
    EndIf
    Repeat
        bNumber = pValue // 10
        Ptr8(wDigAddress++) = bNumber + 48
        pValue = pValue / 10
        Inc bIndex
    Until pValue = 0
'
' Reverse the digits held in bDigits into the Result string
'
    While bIndex > 0
        Ptr8(wResAddress++) = Ptr8(--wDigAddress)
        Dec bIndex
    Wend
EndProc

'------------------------------------------------------------------------------------------
' Set the config fuses for internal oscillator on a PIC12F1840 device
'
    Config1 FOSC_INTOSC, WDTE_OFF, PWRTE_OFF, MCLRE_ON, CP_OFF, CPD_OFF, BOREN_OFF
    Config2 WRT_OFF, PLLEN_ON, LVP_OFF


[top204]

Below is a modified version of the above signed 32-bit integer to ASCII conversion procedure that uses indirect operations that make it faster and smaller, but still clear enough to see what is happening:

Code Select Expand

'
'   /\\\\\\\\\
'  /\\\///////\\\
'  \/\\\     \/\\\                                                 /\\\          /\\\
'   \/\\\\\\\\\\\/        /\\\\\     /\\\\\\\\\\     /\\\\\\\\   /\\\\\\\\\\\  /\\\\\\\\\\\  /\\\\\\\\\
'    \/\\\//////\\\      /\\\///\\\  \/\\\//////    /\\\/////\\\ \////\\\////  \////\\\////  \////////\\\
'     \/\\\    \//\\\    /\\\  \//\\\ \/\\\\\\\\\\  /\\\\\\\\\\\     \/\\\         \/\\\        /\\\\\\\\\\
'      \/\\\     \//\\\  \//\\\  /\\\  \////////\\\ \//\\///////      \/\\\ /\\     \/\\\ /\\   /\\\/////\\\
'       \/\\\      \//\\\  \///\\\\\/    /\\\\\\\\\\  \//\\\\\\\\\\    \//\\\\\      \//\\\\\   \//\\\\\\\\/\\
'        \///        \///     \/////     \//////////    \//////////      \/////        \/////     \////////\//
'                                  Let's find out together what makes a PIC Tick!
'
' Another, faster and smaller, 32-bit integer to ASCII decimal conversion procedure demonstration.
' Written by Les Johnson for the Positron8 BASIC compiler.
'
    Device = 12F1840                                                ' Tell the compiler what device to compile for
    Declare Xtal = 32                                               ' Tell the compiler what frequency the device will be operating at (in MHz)
'
' Setup USART1
'
    Declare HRSOut1_Pin  = PORTA.0
    Declare HRSIn1_Pin   = PORTA.1
    Declare Hserial_Baud = 9600                                     ' Set the Baud rate for USART1

    Dim MyDword As SDword                                           ' Holds the value to convert to ASCII
    Dim MyString As String * 20                                     ' Holds the converted ASCII value

'------------------------------------------------------------------------------------------
' The main program starts here
'
Main:
    OSCCON = %11110010                                              ' Enable the 4xPLL so the device operates at 32MHz with its internal oscillator

    MyDword = -12345678                                             ' Load the variable to convert to ASCII
    SDwordToASCII(MyDword, MyString)                                ' Convert the signed 32-bit integer to its ASCII representation in MyString
    HRsoutLn "Result = ", MyString                                  ' Transmit the value to a serial terminal

'-----------------------------------------------------------------------------
' Convert a signed 32-bit integer value to an ASCII decimal representation in a String variable
' Input     : pValue holds the signed 32-bit value to convert
'           : pStrAddr holds the address of the String that will hold the ASCII conversion
' Output    : Converts the ASCII decimal conversion in the String loaded as pStrAddr
' Notes     : None
'
Proc SDwordToASCII(pValue As SDword, ByRef pStrAddr As Word)
    Dim bDigits[10] As Byte Heap
    Dim bIndex      As Byte = 0
    Dim wDigAddress As FSR1L.Word

    wDigAddress = AddressOf(bDigits)
    If pValue < 0 Then
        Ptr8(pStrAddr++) = "-"
        pValue = Abs(pValue)
    EndIf
    Repeat
        Ptr8(wDigAddress++) = (pValue // 10) + 48
        pValue = pValue / 10
        Inc bIndex
    Until pValue = 0
'
' Reverse the digits held in bDigits into the return string
'
    While bIndex > 0
        Ptr8(pStrAddr++) = Ptr8(--wDigAddress)
        Dec bIndex
    Wend
    Ptr8(pStrAddr) = 0                                              ' Add a null to terminate the returned string
EndProc

'------------------------------------------------------------------------------------------
' Set the config fuses for internal oscillator on a PIC12F1840 device
'
    Config1 FOSC_INTOSC, WDTE_OFF, PWRTE_OFF, MCLRE_ON, CP_OFF, CPD_OFF, BOREN_OFF
    Config2 WRT_OFF, PLLEN_ON, LVP_OFF


[david]

Les - many thanks for the excellent code examples there but I didn't mean to put you to extra trouble.  That gives me a better insight to what is going on including some gaps when only small numbers were sent (as per trastikata's post). If I get time today I will revisit the original problem using more concise code.  It's possible I was creating the problem further back and passing it to the serial output process.  Let me sort out some easier to follow example and if it's not obvious where I've goofed up, I will post the full code.
Many thanks for your support and knowledge base, so freely shared.

Best regards,
David

[david]

I've managed to capture the effect I noticed using very simple code.
This is the full code that the following plots were captured from.

Code Select Expand

Device  12F1840
        Declare Xtal 16
        Config1 FCMEN_OFF, IESO_OFF, CLKOUTEN_OFF, BOREN_OFF, CPD_OFF, CP_OFF, MCLRE_OFF, PWRTE_ON, WDTE_OFF, FOSC_INTOSC
        Config2 LVP_OFF, BORV_19, STVREN_OFF, PLLEN_OFF, WRT_OFF
               
        TRISA = %00011010        '
        OSCCON=%01111010      'PLL disabled, 16MHz=01111010
        APFCON=0
        T1CON=%00000000        'Tmr1 off
        CM1CON0=0
        OSCTUNE=0
        OPTION_REG=%0000000  'WPUs ON
        WPUA=%00001000        'RA3 WPU enabled
        ANSELA=%00010000      'RA4 as analog
    ADCON0=%00001101      'ADC on, AN3 selected  10 bit
    ADCON1=%10101000      'Rt justified, Fosc/16,Vdd as +ref
    PORTA=0
    Declare Hserial_Clear=On
    SPBRGL=34              '115200=34     230400=16
    SPBRGH=0               '115200=0      9600=1
        RCSTA=%10010000        'bit 4=1  rx on
        TXSTA=%00100100        'BRGH=1
        BAUDCON=%01001000      'output inverted -use FTDI dongle
             
        Dim turn As SWord      '16 bit   max 65535   5 chars
        Dim dist As SWord      '16 bit   max 65535   5 chars 
       'Dim dist As SDWord     '32 bit   max 4294967296  10 chars
        DelayMS 100          'start up delay
       
start:  For turn=0 To 5000          'approx 0.5 second updates
        dist=turn/2
                                   
        HRSOut SDec turn,"t ",13,10, SDec dist,"m ",13,10     'signed
        DelayMS 50
        Next turn
End


The only code changes made were to the variable "dist" - from SWord to SDWord as indicated in the plot names.  I've tried to capture with increasing numeric values - 2, 3, 4 digits to show some effects.   Note that some plots have just a bidirectional arrow displaying timing as Width while others have two green cursors showing timing as |T1-T2|.
With "dist" as SWord, the spacing between the two fields starts as 2 chars wide for smaller numbers and decreases as the numbers get larger until there is no spacing with 4 digits.
With "dist" as SDWord, the massive spacing between the two fields does decrease slightly but also the spacing between characters in the 2nd field gets larger as the numbers increase.
I can get around the issue ok but I'm curious if this is expected behaviour.  I'm in a good position now to try any changes needed.

Best regards,
David

[trastikata]

Hello David,

try this code instead:

Code Select Expand

        Dim sSerialString As String * 20
             
        Dim turn As SWord      '16 bit   max 65535   5 chars
        Dim dist As SWord      '16 bit   max 65535   5 chars
       'Dim dist As SDWord     '32 bit   max 4294967296  10 chars
        DelayMS 100          'start up delay
       
start:  For turn=0 To 5000          'approx 0.5 second updates
        dist=turn/2
                   
        'HRSOut SDec turn,"t ",13,10, SDec dist,"m ",13,10     'signed
        sSerialString = Str$(SDec turn) + "t " + 13 + 10 + Str$(SDec dist) + "m " + 13 + 10   
        HRSOut sSerialString                       
        DelayMS 50
        Next turn
End


[david]

Hello trastikata,
Many thanks for your reply - yes that looks very good.  Two plots attached.  No problems that I can see.
I should add that timing wise it's the same as my posted code with "dist" declared as a SWord.  Plot2 is a total of 16 chars x87.5uS ~1400uS but the code is a little bigger.

Cheers,
David

[tumbleweed]

I would image that since the data types did not change (both 'turn' and 'dist' defined as SWord), all that did was move the timing from the HRSOut statement to the new sSerialString statement... if you were to measure the total execution time instead of just the serial transfer speed it would be approx the same.

Once you change 'dist' to a SDWord then it has to use 32-bit conversions, hence the large delay in between the transfer of the two parts.

[david]

I can accept that the larger variable will take longer but 12mS?  This is at 87.5uS/char.  Besides - what's with the strange spacing between adjacent numerals as seen in the SDWord_2nd_field plot?

Here's 3 variants I've tried.  The 1st and 3rd work fine.  The 3rd also allows me to use a more complex relationship for dist=turns/2 such as dist=turns/2-turns*turns/65536 - which does require the SDWord variable.  The code example was simplified to the bare minimum that showed the effect.  Note also the size of the prog bytes in Example 2

Example 1
Dim turn As SWord     
Dim dist As SWord    '**** 
DelayMS 100         
       
start:  For turn=0 To 5000         
          dist=turn/2    'simple maths
          HRSOut SDec turn,"t ",13,10, SDec dist,"m ",13,10   
          DelayMS 50
        Next turn
Works well.  270 prog bytes, 17 variable bytes

**************************************************************

Example 2
Dim turn As SWord     
Dim dist As SDWord     '****
DelayMS 100         
       
start:  For turn=0 To 5000         
          dist=turn/2     'simple maths
          HRSOut SDec turn,"t ",13,10, SDec dist,"m ",13,10   
          DelayMS 50
        Next turn
Very long delay between "turn" and "dist".  Numerals in "dist" also delayed.
522 prog bytes, 34 variable bytes.

*************************************************************

Example 3
Dim turn As SWord     
Dim dist As SWord     '****
Dim temp As SDword    '****   
DelayMS 100         
       
start:  For turn=0 To 5000         
          temp=turn/2
          dist=temp                           
          HRSOut SDec turn,"t ",13,10, SDec dist,"m ",13,10     'signed
          DelayMS 50
        Next turn
Works well.  274 prog bytes, 21 variable bytes

Example 3 works well and has modest code size.

Cheers,
David

[tumbleweed]

Example 2 has a number of 32x32 division operations. These will be slow, as division is about the worst case operation. I didn't bother timing it, but at 16MHz 12ms doesn't surprise me.

Timing in between the chars changes as it does these division operations "one char at a time", and time for a division can vary greatly depending on the values.

Example 3 is really pretty much the same as Example 1 since you truncate the value by assigning 'dist=temp'. If 'turn' is a SWord then there's no reason for 'dist' to be a SDWord, or to have 'temp' at all. Matter of fact, if 'turn' is always > 0 then it's probably better to just use unsigned numbers, although maybe you have a reason for that somewhere else.