Pulling out what hair I have left!

pgbpsu · 2011-04-01 11:56

I've been working on some string routines to parse GPS strings and I've hit a snag that has me confused, befuddled, and amazed. The first snippet below works. The second causes the whole program to hang.

 ' This works
  ' latitude N/S
  bytefill(@tempString,0,12)                                   ' set whole thing to "0" 
  bytemove(@tempString[0],@latString[1],4)                     ' copy ddmm from longitude string into temp_str
  bytemove(@tempString[4],@latString[6],4)                     ' copy mmmm from longitude string into temp_str

  ' This does not work
  ' longitude E/W
  bytefill(@tempString,0,12)                                   ' set whole thing to "0"
  bytemove(@tempString[0],@lonString[1],5)                     ' copy dddmm from longitude string into tempString
  bytemove(@tempString[5],@lonString[7],4)                     ' copy mmmm from longitude string into tempString

The first chunk is about 6 lines above the second. If I comment out the final bytemove in the second snippet or change the offending line to

  bytemove(@tempString[0],@lonString[7],4)                     ' copy mmmm from longitude string into tempString

, the program runs as it should, of course the value in tempString isn't correct.

I've declared things like this:

DAT
  tempString    byte "000000000000", 0
  latString     byte "SDDMM.MMMMMM", 0
  lonString     byte "SDDDMM.MMMMMM", 0

For the life of me I can't figure out why the second snippet causes a crash. I assume it's a memory leak, but how can that be? There are no other cogs accessing this memory. I've must be missing something obvious, but I've been working on it so long I think I've lost the forrest and the trees!

Any fresh eyes see the trouble?
Thanks,
Peter

Phil Pilgrim (PhiPi) · 2011-04-01 12:14

Please attach your entire program. I don't think the snippets you've posted tell the whole story.

-Phil

pgbpsu · 2011-04-01 12:34

You are no doubt correct. It's not pretty, but if you're willing to look, I'm willing to post. Please see attached.

Publison · 2011-04-01 12:45

Hi Peter,

It is customary to to use the "Archive" function of the Propeller Tool to post your code. That way all the objects in question are included. You might have changed them and no one would know.

attachment.php?attachmentid=79778&stc=1&thumb=1&d=1301687268

pgbpsu wrote: »

You are no doubt correct. It's not pretty, but if you're willing to look, I'm willing to post. Please see attached.

Phil Pilgrim (PhiPi) · 2011-04-01 12:50

What does your lonString look like when filled from the GPS routines?

-Phil

pgbpsu · 2011-04-01 13:02

Phil Pilgrim (PhiPi) wrote: »

What does your lonString look like when filled from the GPS routines?

-Phil

Hi Phil-

Here's the output as the program stands (lonString is W07751.9199928)
193206 19:32:06 010411 2011 04 01 N4047.647759 40476477 W07751.919928 268527447 001 10 1271177904

Phil-
Your's was an excellent question. I added a few lines to the PROCESS_GGA method and either their addition has jiggled something loose (unlikely) or it has revealed that my program wasn't hanging like I thought.

  ' longitude E/W
  bytefill(@tempString,0,12)                                   ' set whole thing to "0"
  uarts.str(DEBUG,string(13,"lonString: "))
  uarts.str(DEBUG,@lonString)
  uarts.str(DEBUG,string(" tempString: "))
  uarts.str(DEBUG,@tempString)
  
  bytemove(@tempString[0],@lonString[1],5)                     ' copy dddmm from longitude string into tempString
  bytemove(@tempString[0],@lonString[7],4)                     ' copy mmmm from longitude string into tempString

Before, my output terminal window would have been blank. However, with these lines I get:

lonString: W07751.917175 tempString:
lonString: W07751.917175 tempString:
lonString: W07751.917175 tempString:
lonString: W07751.917175 tempString:
lonString: W07751.917175 tempString:

I'm as confused as ever, but my program is not hanging. Something I've done is interfering with the return value from PROCESS_NMEA_LINE (which is called in the big IF statement in the top level object). I know this because I have a debug pin
which is set high before entering the PROCESS_NMEA_LINE. Immediately after processing my two NMEA sentences, that pin should go low and it does not.

Why that is I'm still working on....
p

pgbpsu · 2011-04-01 13:18

Publison-

You're right. Here's the zip. SleepAndWakeGpsTest - Archive [Date 2011.04.01 Time 16.00].zip

max72 · 2011-04-01 13:30

I had troubles using GPS IO mini because modifying a non essential bit of code it stopped working. I spent a lot of time before finding the problem was related to stack size.
I don't know if it is your case, but this is the first test I would do.

Massimo

pgbpsu · 2011-04-01 13:58

Massimo-

That's a possibility I hadn't considered. The stack size for this cog is 90 longs which should be more than enough, but I'll tinker with it to see if upping that helps.

p

Phil Pilgrim (PhiPi) · 2011-04-01 15:10

I think you forgot to change your code back to the non-working version:

bytemove(@tempStringb][color=red]0[/color][/b,@lonString[7],4)

Ditto the stack size suggestion.

-Phil

pgbpsu · 2011-04-01 15:46

Hi Phil-

I've increased the stack size for this cog from 90 to 100 to 200 and that doesn't solve it. I've been (maybe incorrectly) focused on this line:

  bytemove(@tempString[5],@lonString[7],4)                     ' copy mmmm from longitude string into tempString

Changing the last parameter of the bytemove command (number of bytes to move) has a very strange effect on things. Setting it to 0 and my debug messages start coming out right away at a rate of 1Hz. They are wrong but they arrive right away. Setting this parameter to 1 and it also starts up quickly and I get a new message every 1 second. Setting it to 2 and things don't come right away, but eventually they start arriving. Set it to three and I have to wait even longer for the first message. Setting it to 4 and I stop getting them even after waiting for several minutes. The only changes between these 4 runs is the final parameter of this one line. In each case below stack size is 200 longs.

' above line commented out
Welcome aboard.
Handling clock duties in cog:      2
Made it here. cnt: 0019050709
cnt since last: 0006236256 223628 22:36:28 010411 2011 04 01 N4047.647947 40476479 W07751.917175 268443207 000 00 0018842184
cnt since last: 0082428224 223629 22:36:29 010411 2011 04 01 N4047.647947 40476479 W07751.917175 268443207 000 00 0100760568
cnt since last: 0081131008 223630 22:36:30 010411 2011 04 01 N4047.647947 40476479 W07751.917175 268443207 000 00 0182678968
cnt since last: 0082424416 223631 22:36:31 010411 2011 04 01 N4047.647947 40476479 W07751.917175 268443207 000 00 0264597352
cnt since last: 0081114656 223632 22:36:32 010411 2011 04 01 N4047.647947 40476479 W07751.917175 268443207 000 00 0346515736
cnt since last: 0163683712 223634 22:36:34 010411 2011 04 01 N4047.647947 40476479 W07751.917175 268443207 000 00 0509287576
cnt since last: 0081119040 223635 22:36:35 010411 2011 04 01 N4047.647947 40476479 W07751.917175 268443207 000 00 0591205960
cnt since last: 0082424448 223636 22:36:36 010411 2011 04 01 N4047.647947 40476479 W07751.917175 268443207 000 00 0673124344

' parameter set to 0
Welcome aboard.
Handling clock duties in cog:      2
Made it here. cnt: -1904504725
cnt since last: 0005100272 223751 22:37:51 010411 2011 04 01 N4047.647947 40476479 W07751.917175 268443207 000 00 -1904867298
cnt since last: 0083734432 223752 22:37:52 010411 2011 04 01 N4047.647947 40476479 W07751.917175 268443207 000 00 -1822948914
cnt since last: 0079823200 223753 22:37:53 010411 2011 04 01 N4047.647947 40476479 W07751.917175 268443207 000 00 -1741030514
cnt since last: 0083743728 223754 22:37:54 010411 2011 04 01 N4047.647947 40476479 W07751.917175 268443207 000 00 -1659112130
cnt since last: 0079795376 223755 22:37:55 010411 2011 04 01 N4047.647947 40476479 W07751.917175 268443207 000 00 -1577193746
cnt since last: 0083741760 223756 22:37:56 010411 2011 04 01 N4047.647947 40476479 W07751.917175 268443207 000 00 -1495275346
cnt since last: 0162380304 223758 22:37:58 010411 2011 04 01 N4047.647947 40476479 W07751.917175 268443207 000 00 -1332913106
cnt since last: 0079801680 223759 22:37:59 010411 2011 04 01 N4047.647947 40476479 W07751.917175 268443207 000 00 -1250994722
cnt since last: 0083732208 223800 22:38:00 010411 2011 04 01 N4047.647947 40476479 W07751.917175 268443207 000 00 -1169076322

' parameter set to 1
Welcome aboard.
Handling clock duties in cog:      2
Made it here. cnt: -1041897791
cnt since last: 0170913632 223523 22:35:23 010411 2011 04 01 N4047.647947 40476479 W07751.917175 268512975 000 00 -0878269532
cnt since last: 0081114688 223524 22:35:24 010411 2011 04 01 N4047.647947 40476479 W07751.917175 268512975 000 00 -0796351148
cnt since last: 0082422480 223525 22:35:25 010411 2011 04 01 N4047.647947 40476479 W07751.917175 268512975 000 00 -0714432748
cnt since last: 0081115664 223526 22:35:26 010411 2011 04 01 N4047.647947 40476479 W07751.917175 268512975 000 00 -0632514364
cnt since last: 0163681936 223528 22:35:28 010411 2011 04 01 N4047.647947 40476479 W07751.917175 268512975 000 00 -0469251004
cnt since last: 0081119040 223529 22:35:29 010411 2011 04 01 N4047.647947 40476479 W07751.917175 268512975 000 00 -0387332620
cnt since last: 0082424464 223530 22:35:30 010411 2011 04 01 N4047.647947 40476479 W07751.917175 268512975 000 00 -0305414220
cnt since last: 0081114656 223531 22:35:31 010411 2011 04 01 N4047.647947 40476479 W07751.917175 268512975 000 00 -0223495836

' parameter set to 2
Welcome aboard.
Handling clock duties in cog:      2
Made it here. cnt: -0143041159
cnt since last: 1562736800 224018 22:40:18 010411 2011 04 01 N4047.647947 40476479 W07751.917175 269210647 000 00 1412298588
cnt since last: 0079823584 224019 22:40:19 010411 2011 04 01 N4047.646487 40476464 W07751.913088 269210647 000 03 1494216988
cnt since last: 0083760416 224020 22:40:20 010411 2011 04 01 N4047.648260 40476482 W07751.914925 269210647 000 02 1576516284
cnt since last: 0079779984 224021 22:40:21 010411 2011 04 01 N4047.647878 40476478 W07751.914616 269210647 000 02 1658434668
cnt since last: 0083730288 224022 22:40:22 010411 2011 04 01 N4047.647572 40476475 W07751.914337 269210647 000 02 1740353068
cnt since last: 0079807792 224023 22:40:23 010411 2011 04 01 N4047.647978 40476479 W07751.914616 269210647 000 02 1822271452
cnt since last: 0083731184 224024 22:40:24 010411 2011 04 01 N4047.648066 40476480 W07751.914643 269210647 000 02 1904189836
cnt since last: 0079806864 224025 22:40:25 010411 2011 04 01 N4047.648216 40476482 W07751.914760 269210647 000 02 1986108236

' parameter set to 3
Welcome aboard.
Handling clock duties in cog:      2
Made it here. cnt: 1818227633
cnt since last: -1669254544 224148 22:41:48 010411 2011 04 01 N4047.656459 40476564 W07751.921765 276187377 001 04 0143293396
cnt since last: 0085049488 224150 22:41:50 010411 2011 04 01 N4047.649363 40476493 W07751.920108 276187376 001 08 0225895300
cnt since last: 0081099200 224151 22:41:51 010411 2011 04 01 N4047.649584 40476495 W07751.920163 276187376 001 08 0307813684
cnt since last: 0082425344 224152 22:41:52 010411 2011 04 01 N4047.649694 40476496 W07751.920373 276187376 001 08 0389732084
cnt since last: 0081114656 224153 22:41:53 010411 2011 04 01 N4047.649790 40476497 W07751.920522 276187376 001 08 0471650468
cnt since last: 0082422464 224154 22:41:54 010411 2011 04 01 N4047.649911 40476499 W07751.920693 276187376 001 08 0553568852
cnt since last: 0081114672 224155 22:41:55 010411 2011 04 01 N4047.649941 40476499 W07751.920860 276187376 001 08 0635487252
cnt since last: 0082422464 224156 22:41:56 010411 2011 04 01 N4047.649883 40476498 W07751.920952 276187376 001 08 0717405636
cnt since last: 0081114656 224157 22:41:57 010411 2011 04 01 N4047.649709 40476497 W07751.920960 276187376 001 08 0799324020

' parameter set to 4
NO RESPONSE AFTER SEVERAL MINUTES.

Clearly this is a coding error. I thought it was a simple one. Maybe it's more fundamental.

Rayman · 2011-04-02 05:20

I just took a quick look and while I don't see the problem, my guess would be that a zero at the end of one of the strings is being erased...

Try putting in a bunch of zero's in between your strings like this:
...
ggaString byte "$GPGGA", 0
byte 0[20]
polytString byte "$POLYT", 0
...

Another possibility is that there are zeros in the strings your moving around that shouldn't be there...

I guess you've looked into stack space already... How many longs are free in your program?
Does the main SPIN cog have enough stack space?

max72 · 2011-04-02 13:17

pgbpsu wrote: »

Massimo-

That's a possibility I hadn't considered. The stack size for this cog is 90 longs which should be more than enough, but I'll tinker with it to see if upping that helps.

p

Sorry I wasn't clear, the stack looking critical is
gps_stack[10] in NavsyncCW25.spin

Massimo

pgbpsu · 2011-04-04 11:27

Massimo-

Again, thanks for looking at the code. I had forgotten about the stack space set aside in the NavsyncCW25 file you indicated. However, this code is not running in a cog launched from within the object so this stack space is not used. All the code called in this object resides cog that was launched by the top-level object. I was able to comment out the stack space variable you refer to and on INIT method and still able to get the object to compile and run as before.

Thanks for the suggestion.

pgbpsu · 2011-04-04 13:47

After a terrific amount of fiddling today (both with print statements and pin toggles) I've concluded that the problem is speed. The way my program is structured, I've got 2 NMEA messages. The two NMEA messages come one right after the other (GGA followed by POLYT) with about 3.5mS between the end of the GGA and the beginning of the POLYT. I'm trying to process (make pointers and convert some strings to decimals) each one right after it arrives. My original post was trying to parse the GGA messages which happens to be the first. Seems I'm not done parsing the GGA message before the POLYT message arrives.

I've rearranged things and now it seems to work as expected....

Thanks all for your input. I don't think anyone (including me when I first posted this) had enough info to debug this. But it was because of all the suggestions here that I kept searching for the needle.

Thanks,
p

Phil Pilgrim (PhiPi) · 2011-04-04 13:52

'Excellent debugging! I dropped out of the discussion because, frankly, I was out of ideas. I'm really glad you found the problem.

-Phil

pgbpsu · 2011-04-04 19:02

Hi Phil-

Knowing the structure of the program and the NMEA port baud rate, I should have looked at this earlier. It was one of your questions that made helped me discover that my program wasn't hanging. It was simply not returning a value I was expecting before printing out all the info collected from the NMEA messages. The slightly altered version is working fine. I think this explains the problems I was seeing. There are no other cogs acting on this memory so race condition or corrupt memory seemed unlikely, the cog stack had been increased to 200 longs which seems unreasonable (and still didn't help). I'm running this for a couple of days to see what the logged data look like but I'm optimistic.

Thanks again for looking over the code and making suggestions.
Kind regards,
Peter

Pulling out what hair I have left!

Comments