System time tag of printf in xTIMEcomposer debug console

[aclassifier]

Is there any possibility to get system time before each line of printf lines?

This could be tagged on in the Preferences window.

Or will this slow the log, and thus make time tagging irrelevant?

Or is there any other way to do it?

[larry]

The most primitive timestamped print would be to get the current timer value, print it out and then follow with the actual printf.

Code: Select all

#include <stdio.h>
#include <print.h>

#define timed_printf \
  { timer t; int u; t :> u; /* GETTIME instruction */ \
    printint(u); printstr(" "); \
  } printf

int main(void)
{
  timed_printf("hello world\n");
  timed_printf("hello world\n");
  return 0;
}

[aclassifier]

What a trick! Thanks!

The format though is the 32-bit 100 MHz system counter ticking around the clock through, not formatted.

Probably more people than I would like an output with __TIME__-like format, relative to the start. I guess the macro would need to call a function with the necessary code.

I suggest: DD_23:59:01_000.000.000
DD = day number
000 = ms
000 = us
000 = ns

[Gothmag]

I think to get formatting with that resolution you'd probably want to write your own relative-time keeping thread. Or an RTC which would skew your time a little more since there are more delays in reading, but you can get the time at startup to keep as a reference.

[aclassifier]

That's a good idea. Especially since one can then print out time tags when actually needed, not necessarily in front of every line.

However, I stil wish a tick on/off of "Include system time tag" in the console setup. I guess this is something for Eclipse?

[aclassifier]

Showing this to a guy at work triggered the question whether the timed_printf macro containing several printf's will be thread-safe on XCORE? Meaning that a task gets it full line alone.

[Gothmag]

As far as I know you can have eclipse printout the sytem time for console output, so you would probably have pc system time, xmos time, message as the format. Awkward but if you need all the info that might be easiest. I think the macro should be safe as far as concurrency. I'm not sure what the line after your question means though. You could always write a sample program and see what your output is.

[aclassifier]

This is to trace long timing matters. I am controlling an aquarium, where the PWM of the LED control is nice with xScope, rate of rise of the temperature would be nice with a system time. A tick box in the console setup would do the trick. Just a tip for your next release.

Also, for protocolling between apps running on the OS that communicate with XMOS, a common time line is really needed.

Do you mean to say that the severel printf will run atomically? ("Full line") I did try it, it certainly works, but the thread-safeness is harder to test. My guess is that each printf is atomic, but not between them?

[Gothmag]

Ok I understand. I'm actually not sure if it is since I've never printed from more than a single thread at a time. This is where I'd create a test program where they all run using the same clkblk for timing, and have each of them put out a couple of prints, using the macro, and check the output. If you output strict known sequences from each thread you'll be able to see if your prints from one thread are interspersed with data from another. I'm not familiar enough with the system print function to predict what it does though. I don't think a single print will be interrupted by another, but I'm not sure if 8 sets of prints from different threads at about the same time will. If after a time you don't notice anything you're ok. Probably no official xmos responses for a couple days so if you have time, try it.

[aclassifier]

The above suggesion is not thread safe. However, this is, usable in a .xc file (timer defined):

Code: Select all

// Wraps at 2exp32 = 4294967296 100 MHz counts (42949 ms)
#define debug_tprintf(fmt, ...) \ /* is thread safe */
do { \
    if(DEBUG_TIWISL_SERVER) { \
        timer p_time; \
        unsigned p_time_now; \
        p_time :> p_time_now; \
        printf("[%u ms] " fmt, p_time_now/XS1_TIMER_KHZ, __VA_ARGS__); \
    } \
} while (0) // gcc-type ##__VA_ARGS__ doesn't work

// Shortest usage since ## not allowed for XC: 
debug_tprintf ("%s", "Hello World!\n");

It prints out ms. The clue was to have one printf.

I got help on stackoverflow for this (see https://stackoverflow.com/questions/459 ... in-a-macro). The discussion there is very interesting!

I also have made atomic timed printing possible in a .c file (no timer defined). First add this in some .xc file and include it:

Code: Select all

unsigned get_time_now (void) {
    timer p_time;
    unsigned p_time_now;
    p_time :> p_time_now;
    return p_time_now; // Wraps at 2expp32 = 4294967296 100 MHz counts (42949 ms)
}

Then add this and use it in a .c file:

Code: Select all

// Wraps at 2exp32 = 4294967296 100 MHz counts (42949 ms)
#define debug_tcprintf(fmt, ...) \ /* is thread safe */
do { \
    if(DEBUG_PRINT_HTTPD) { \
        unsigned p_time_now = get_time_now(); \
        printf("[%u ms] " fmt, p_time_now/XS1_TIMER_KHZ, ##__VA_ARGS__); \
    } \
} while (0) // gcc-type ##__VA_ARGS__ allowed

// Shortest usage since ## is allowed for C: 
debug_tcprintf ("Hello World!\n");

Aside: More at http://www.teigfam.net/oyvind/home/tech ... kit-notes/ (Disclaimer: No ad, no money, no gifts, just hobby)