Is there a simple way to log output serial data?

Finally got something to work. However, the use of SerialUSB1 totally screws up IDE2, at least my version. Once you use SerialUSB1, the IDE automatically switches to it and it won't switch back to Serial. I don't want to see SerialUSB1 on the IDE, only on my data logger. However, if I close the IDE, and open TyCommander, I can get it to work. Definitely cumbersome and slows down the work process.
Did you consider filing a bug report with Arduino ??

Mark J Culross
KD5RXT
 
Did you consider filing a bug report with Arduino ??

Mark J Culross
KD5RXT
No, I hadn't, but that is a good idea. I have managed to get TyCommander hooked to do the monitoring. I get two serial consoles now, which is what I want. Arduino should support the dual and triple USB ports.
 
The IDE lets you specify which port to connect to, look under Tools -> Ports -> Teensy and select a different port if it's using the wrong one.
 
The IDE lets you specify which port to connect to, look under Tools -> Ports -> Teensy and select a different port if it's using the wrong one.
True enough now that I checked. But it won't allow you to save the output to file, or cut and paste the entire output, like TyCommander will.

I just logged every step of the stepper with cycle count, every time the carriage moved 1um for 11mm of travel (with cycle count), and a calculated velocity of the stepper motor in TyCommander. Almost 1MB of data in the file.

Really can't do this in the IDE and get the data out conveniently.

There seems to be a glitch in the data occasionally. I am independently writing a message to SerialUSB1, from different ISR's. Every once in a while, they seem to interfere with each other. Fortunately, this didn't happen in a critical region that I want to examine. The printf statement from the previous statement is being overwritten. I can tell, because there's no CR and the line continues. The time has been converted to microseconds, using the CYC_TO_US macro. Maybe it's just that the printf didn't have time to finish and there was another printf executed.

Code:
3971324.153333, zloc = -0.070000, Zval = -0.002756, ztogo = 0.065000
3971384.085000, zloc = -0.071000, Zval = -0.002795, ztogo = 0.066000
3971462.953333, zloc = -0.072000, Zval = -0.002835, zt3971856.293333, zloc = -0.077000, Zval = -0.003031, ztogo = 0.072000
3971918.755000, zloc = -0.078000, Zval = -0.003071, ztogo = 0.073000

3971856.293333 - 3971462.953333 = 393.34 us, perhaps this is too fast for a SerialUSB1.printf to complete (with all those characters). Probably ought to format the data better, to reduce what is sent.
 
There seems to be a glitch in the data occasionally. I am independently writing a message to SerialUSB1, from different ISR's. Every once in a while, they seem to interfere with each other. Fortunately, this didn't happen in a critical region that I want to examine. The printf statement from the previous statement is being overwritten.

Generally you shouldn't use printf inside ISRs. In addition to being fairly slow it's not thread / ISR safe and you can get some undefined behaviour.
Instead store the values to be printed and set a flag, the background loop can then do the formatting and output the data outside of the ISR.

Or use puts / putc to output the values rather than printf. This does mean creating your own text formatting code but if you know the format and range of values required it's not that complicated and is far faster than printf.
 
Generally you shouldn't use printf inside ISRs. In addition to being fairly slow it's not thread / ISR safe and you can get some undefined behaviour.
Instead store the values to be printed and set a flag, the background loop can then do the formatting and output the data outside of the ISR.

Or use puts / putc to output the values rather than printf. This does mean creating your own text formatting code but if you know the format and range of values required it's not that complicated and is far faster than printf.
You are right. Hangs head in shame. Haven't had an issue since I shortened the length of the string that was printed. But it's not a good idea. Putting it in the main loop could result in out of order outputs, I'd think. At least that is what I was concerned with - parsing the output stream. Yes, it is offline, but /start_confession I'm not that good of a file parsing programmer. /end_confession
 
Hmm, well it took me a while, but I finally got what I wanted. Extracted the data and plotted a high resolution view of the position of the z axis of my lathe simulator vs time, using the ARM cycle counter. Had to compensate for the rollover of the 32bit counter, several times. Test was about 31 seconds long. I log every time the Z position moves, to a 1um resolution, over 10mm of travel. The velocity is logged on SerialUSB2, and the position on SerialUSB1, along with logging the time stamp of the start of the step pulse. Mechanical things sure do weird stuff, when you look at a 1 micron scale. Red star is time stamp of the step pulse to the stepper motor driver. It seems that last step pulse probably shouldn't have been generated, as I stepped past the stop point of 0.000 mm. This is why I wanted the logging ability, to visualize what was happening.
Screenshot 2025-03-24 at 9.30.28 PM.png
 
/start_confession I'm not that good of a file parsing programmer. /end_confession

Your lines start with a timestamp? Change the printf to pad them with leading 0's so everything is the same length.

cat log.txt | sort > logInTimeOrder.txt

That does assume unix comand line tools (cat and sort specifically) are installed. But you can easily find windows builds of them if needed. Personally the first thing I do on an new windows machine is install all the standard unix/linux command line text parsing tools. sort, grep, cut etc... are a bit old school these days but are stupidly fast and are often the quickest way to get what you need out of a huge text log file.


Just out of interest when looking at 1um resolution positions are you having to compensate / allow for thermal expansion in tooling bit or in the frame work holding the tool relative to the material being cut?
 
Your lines start with a timestamp? Change the printf to pad them with leading 0's so everything is the same length.

cat log.txt | sort > logInTimeOrder.txt

That does assume unix comand line tools (cat and sort specifically) are installed. But you can easily find windows builds of them if needed. Personally the first thing I do on an new windows machine is install all the standard unix/linux command line text parsing tools. sort, grep, cut etc... are a bit old school these days but are stupidly fast and are often the quickest way to get what you need out of a huge text log file.


Just out of interest when looking at 1um resolution positions are you having to compensate / allow for thermal expansion in tooling bit or in the frame work holding the tool relative to the material being cut?
Not always. Occasionally that doesn't happen, because I'm muxing several outputs together. Which is why I had to write a parsing routine to separate the parameters.
Code:
# USBSerial1
time[us], ztogo

Step, 3711407.260000
3713285.671667, 10.191
3713920.935000, 10.192
3715065.831667, 10.193
3715192.195000, 10.194
3715284.785000, 10.195
3715362.128333, 10.196
Step, 3715370.260000
3715412.241667, 10.197
3715446.298333, 10.198
...
3026354.805000, 0.005
3080892.466667, 0.004
Step, 3092090.306667
3093441.723333, 0.003
3093567.345000, 0.002
3093650.411667, 0.001
3093717.076667, -0.000
3093782.265000, -0.001
3093855.733333, -0.002
3093955.825000, -0.003
3094123.406667, -0.004
3094418.905000, -0.005
3094839.128333, -0.006
3095633.846667, -0.005
3095856.111667, Stepper disabled
3095883.588333, -0.004
...
Can't sort (yet) because the uint32_t timer timestamp is rolling over every 7 seconds, so that needs to be corrected first. Since this is a 30 second long log, it needs to be corrected at least 4 times. Need to look into a 64bit cycle counter. I'm using a Mac, so I have access to some of the tools you mentioned.

Right now, I'm not dealing with that level of mechanical or thermal effects. First trying to get the carriage to move as I want. It's proving to be tough to stop on a dime, ie. within 1um. This is for feeding the lathe carriage and stopping precisely at a point. Compensation for thermal is different. Technically, one would need to know the temperature of the work piece, and that's not going to happen.

My (ongoing) project is not for a CNC lathe, so I'm not dealing with multiple axes. I am controlling the Z axis, although I have position information (1um resolution) for both the Z and X axes. Z is the direction along the spindle axis, X is the cross slide axis, in the horizontal plane and perpendicular to the spindle axis.

All of this is a feature I call feed to stop. Eventually I hope to add thread to stop. Already have feeding and threading working (for over a year and a half). I can make any metric or "imperial" thread or feed I want at the touch of a couple of soft keys. My ELS (electronic lead screw) controller shows the DRO (digital read out) positions, thread or feed information and spindle RPM. It's purpose (for me) is to be a smart manual lathe, not a CNC machine. So some controls depend on operator interaction, same as a manual machine. The idea is for the operation to be familiar to a manual lathe operator, but have enhanced functions. I've cut threads in steel from 4 threads per inch to 40 and they fit perfectly. Same for metric threads. To date, the ELS has worked far better than I anticipated. Hopefully, this feed to stop will exceed my expectations as well. Been a lot of work though!
 
Last edited:
There are a lot of C++ "chrono" things you can do with HiResClock, but here's a very simple way to use it for elapsed seconds from some arbitrary start time. Function getTicks() effectively provides a 64-bit version of ARM_DWT_CYCCNT.

Code:
#include "HiResClock.h"

uint64_t t0, t1;
elapsedMillis ms;

void setup()
{
  Serial.begin(9600);
  while (!Serial && millis()<3000) {}
 
  HiResClock::begin(); // start the clock and sync to rtc (works with and without battery)
  t0 = T4X_Source::getTicks(); // get 64-bit start time from ARM_DWT_CYCCNT
  ms = 0;
}

void loop()
{
  // every second, get 64-bit count from ARM_DWT_CYCCNT and compute seconds since t0
  if (ms >= 1000) {
    t1 = T4X_Source::getTicks();
    Serial.printf( "%15.7lf\n", (t1-t0)*(1.0/F_CPU_ACTUAL) );
    ms -= 1000;
  }
}
 
Thanks. Appreciate it. I implemented a variation of this, and my time base of measurements seems reasonable now. I've found some interesting things going on in the system (ELS) as a result. So this exercise has been very helpful.
 
Back
Top