Posted 24 September 2023,
This post addresses the problem I have started to see regarding print buffer overflow due to the decreased time (now 50mSec) between environment updates. When running longer field tests, I have started to see many lines where telemetry printout has become garbled, with the next line of printout starting before the previous line has finished, as shown in the accompanying printout
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 |
26.0 79.1 29.4 -49.5 30.4 29.1 0.13 557 340 99671 14345 105 44 NONE RIGHT 26.1 76.0 28.9 -48.3 30.4 29.5 0.09 592 341 95520 14372 93 56 NONE RIGHT 26.1 75.4 29.4 -46.9 30.8 29.9 0.09 619 306 91167 14184 99 50 NONE RIGHT 26.2 75.5 30.1 -45.9 30.6 30.2 0.04 617 289 86287 13881 89 60 NONE RIGHT 26.2 75.5 29.7 -45.0 30.1 29.9 0.02 624 186 8026.3 76.0 29.4 -44.5 29.9 30.1 0.00 26.4 76.7 29.4 -44.7 29.4 30.0 -0.06 631 146 68856 12126.5 77.4 29.1 -45.5 29.5 29.6 0.00 615 149 61634 113526.5 77.9 29.2 -45.9 29.5 29.2 0.03 26.6 79.5 28.9 -46.2 29.7 29.2 0.05 NONE RIGHT 26.6 80.0 28.5 -45.8 28.9 29.6 -0.07 599 173 62531 9948 38 111 NONE RIGHT 26.7 83.8 29.0 -45.5 226.8 88.5 28.6 -45.6 29.1 29.0 0.01 583 159 61878 9404 65 84 NONE RIGHT 26.8 93.3 28.8 -45.8 28.8 29.4 -0.06 588 156 61146 9122 41 108 NONE RIGH26.9 100.3 28.7 -46.1 28.7 29.2 -0.03 601 163 60295 8826.9 118.5 28.6 -46.8 28.7 28.9 -0.02 584 145 59063 8527.0 128.0 28.1 -47.9 29.2 28.8 0.04 568 159 57476 828ONE RIGHT 27.0 132.9 28.2 -48.7 28.7 28.6 0.01 554 13527.1 137.6 28.1 -427.2 150.0 28.3 -48.7 29.3 28.3 0.10 533 136 50884 7676 94 55 NONE RIGHT27.2 212.1 28.9 -48.3 28.8 29.0 -0.027.3 262.0 28.7 -47.9 29.6 28.7 0.09 539 131 45341 73127.3 281.6 28.9 -47.9 29.6 29.0 0.0127.4 272.2 28.1 -47.5 29.7 29.0 0.07 539 136 38918 69927.5 290.9 28.3 -47.3 29.6 28.8 0.0827.5 279.6 28.5 -46.8 29.6 29.2 0.0427.5 290.3 28.4 -46.4 29.5 29.2 0.03 541 137 27442 66327.6 283.6 28.3 -427.7 272.1 28.7 -46.2 29.2 29.2 0.04 544 148 18598 64027.7 274.8 28.4 -46.5 29.0 29.0 0.00 526 150 13790 63027.8 270.0 28.4 -46.8 29.0 28.3 0.07 531 155 8745 618127.9 268.7 28.1 -47.1 29.2 28.8 0.0427.9 268.5 28.0 -46.9 29.2 28.8 0.04 527 161 3192 551628.0 262.1 28.5 -428.1 256.2 28.4 -484 4043 55 94 NONE28.1 96.2 28.1 -4628.1 83.0 28.2 -4528.2 79.2 30.0 -45.5 28.6 28.5 0.01 28.3 78.2 27.7 -44.1 32.2 28.2 0.40 28.3 76.6 28.0 -42.7 30.0 28.1 0.19 28.4 77.2 27.8 -40.5 28.3 28.3 0.00 2 2226 3622 57 92 28.5 78.8 27.5 -3828.6 78.9 27.2 -39.0 27.2 28.3 -0.11 558 166 1754 3531 8 127 NONE RIGHT 28.6 79.2 26.8 -40.1 26.5 27.7 -0.12 559 161 1591 3482 0 127 NONE RIGHT 28.7 79.5 25.3 -42.6 25.7 26.7 -0.10 548 161 1395 3424 4 127 NONE RIGHT 28.7 80.2 25.2 -45.8 25.5 25.5 0.00 507 158 1344 3329 38 112 NONE RIGHT 28.8 79.7 24.8 -4828.8 81.1 26.6 -51.0 25.0 24.9 0.01 28.8 80.7 26.2 -52.1 27.0 26.0 0.10 416 164 2120 1615 80 69 NONE RIGHT 28.9 80.7 26.5 -52.8 25.5 26.1 -0.06 402 167 2526 958 29 120 NONE RIGHT 28.9 80.2 26.7 -53.1 28.6 26.1 -0.06 394 168 2884 513 26 124 NONE RIGHT 29.0 80.7 26.7 -53.8 28.6 26.5 0.21 377 166 3313 151 101 48 NONE RIGHT 29.0 80.1 27.3 -54.7 26.0 24.7 0.13 3529.1 80.8 27.5 -55.3 27.1 25.6 0.15 340 162 4303 123 929.1 80.0 26.2 -5529.1 79.7 26.4 -54.4 31.7 26.2 0.55 338 160 5294 124 127 0 NONE RIGHT |
In the above printout, you will notice that the horizontal scrollbar is much smaller than normal, indicating the line lengths are much longer than normal, and the portion that is visible is really really ugly!
So, what to do? I ran a search through my almost 7000 lines of code for ‘gl_pSerPort->printf(‘ to see how big of a problem I’m looking at, and the search came back with some 400+ hits – ouch! One thought would be to put an ‘if’ statement around each printf call and use an ‘EllapsedMillisec’ variable to limit calls to, say, every 100 or 200 msec, but doing that for 400+ calls would get pretty tedious. Another thought is to abstract all these print statements into a function, and have the time spacing internal to the function. So the function call would look something like:
1 |
LogPrint("%lu\t%2.1f\t.....\n", gl_ElapsedMillisec, gl_LeftCenterCm, ..... ); |
and the function internals would look something like:
1 2 3 4 5 6 7 8 |
LogPrint(char* formatstr, float arg1, float arg2) { if( MsecSinceLastLogPrint > PRINT_INTERVAL_MSEC) { MsecSinceLastLogPrint -= PRINT_INTERVAL_MSEC; gl_pSerPort->printf(formatstr, arg1, arg2); } } |
The problem with the function internals is the argument list would have to match the contents of ‘formatstr’, which means I would have to have an overload for every unique format, and changing anything would be a hassle, as I would have to find and edit the correct overload – yuck!
OK, more thought needed on this – maybe the ‘if’ statement is the way to go (maybe a macro?)
Another thought that just came up; if I filter all print statements by an elapsed time gate, that might actually filter out important one-time error information – ouch! This potential problem suggests adding a priority value to the ‘LogPrint()’ function, so the function might look like:
1 2 3 4 5 6 7 8 9 10 11 12 13 |
LogPrint(char* formatstr, float arg1, float arg2, PRIORITY_CODE) { if(PRIORITY_CODE > 1) { gl_pSerPort->printf(formatstr, arg1, arg2); } else if( MsecSinceLastLogPrint > PRINT_INTERVAL_MSEC) { MsecSinceLastLogPrint -= PRINT_INTERVAL_MSEC; gl_pSerPort->printf(formatstr, arg1, arg2); } } |
And good programming technique would demand that the PRIORITY_CODE have a default value, which (for Arduino programming) would require that every overload have a function declaration at the top of the program – yuck! yuck!
Maybe it would be easier to just put the
1 2 3 4 5 |
if( MsecSinceLastLogPrint > PRINT_INTERVAL_MSEC) { MsecSinceLastLogPrint -= PRINT_INTERVAL_MSEC; gl_pSerPort->printf(....); } |
around each and every ‘low priority’ print statement (all 400+ of them)? yuck! yuck! yuck!
After thinking about this some more, it occurs to me that this problem may be a lot smaller than I think. The primary culprit is the long telemetry string printed out each WALL_TRACK_UPDATE_INTERVAL_MSEC (currently set to 50mSec). It may well be that I only need to guard this one print statement and 99% of the time that will do the trick. As I find other printout statements that are causing problems, I can treat them as well.
25 September 2023 Update:
I did a search for ‘gl_pSerPort->printf(‘ but bypassed everything in setup() and loop(). Starting in TrackLeftWallOffset() in the ‘while (gl_LastAnomalyCode == ANOMALY_NONE )’ block I put an ‘if(mSecSinceLastTelemetryUpdate > PRINT_INTERVAL_MSEC)’ guard around the call to ‘OutputTelemetryLine(TRACKING_LEFT)’, as shown below:
1 2 3 4 5 6 |
//09/25/23 added guard to prevent telemetry printout garbles if (mSecSinceLastTelemetryUpdate > PRINT_INTERVAL_MSEC) { mSecSinceLastTelemetryUpdate -= PRINT_INTERVAL_MSEC; OutputTelemetryLine(TRACKING_LEFT); } |
26 September 2023 Update:
After guarding the ‘OutputTelemetry()’ call in both TrackLeftWallOffset() and TrackRightWallOffset(), I ran another field test, and saw that telemetry output was clean, and now coming in 0.1sec intervals, as intended – yay!
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 |
Sec LCen RCen Deg LF LR LStr Front Rear FVar RVar LSpd RSpd ACODE TRKDIR 0.7 36.8 107.6 0.2 35.9 37.0 -0.16 598 39 67332 12687 94 55 NONE LEFT 0.8 36.3 106.8 1.3 35.4 36.4 -0.09 602 39 63082 12593 66 83 NONE LEFT 0.9 36.8 106.8 1.5 35.9 36.3 -0.04 637 39 59075 12548 48 102 NONE LEFT 1.0 35.7 111.5 -1.2 34.9 35.7 -0.08 596 45 51354 12547 68 81 NONE LEFT 1.1 35.8 123.9 -1.3 35.0 36.0 -0.13 582 49 47749 12588 91 58 NONE LEFT 1.2 35.6 130.8 -0.8 34.8 36.1 -0.13 610 52 44343 12655 92 57 NONE LEFT 1.3 35.1 137.4 0.1 34.3 34.9 -0.06 581 58 38110 12854 59 90 NONE LEFT 1.4 34.2 142.3 -1.2 33.6 34.9 -0.13 574 63 35310 12980 97 52 NONE LEFT 1.5 34.1 147.0 -1.6 32.4 34.3 -0.19 575 67 32717 13113 125 24 NONE LEFT 1.6 33.0 149.5 -0.4 32.2 33.9 -0.14 571 69 30340 13266 111 39 NONE LEFT 1.7 32.5 149.5 5.4 32.3 33.0 -0.07 1000 79 28656 13581 87 62 NONE LEFT 1.8 32.5 149.4 7.2 32.2 32.9 -0.07 398 81 27950 13748 85 64 NONE LEFT 1.9 32.1 147.5 8.3 32.3 32.7 -0.04 392 86 27383 14295 75 75 NONE LEFT 2.0 32.6 149.2 8.3 32.9 33.4 -0.10 394 90 28592 14842 103 47 NONE LEFT 2.1 32.9 148.6 8.5 32.9 33.2 -0.04 382 95 31217 15300 74 75 NONE LEFT 2.2 33.2 149.9 8.0 33.2 33.5 -0.03 387 99 33390 15496 65 84 NONE LEFT |
Stay tuned,
Frank