Why won't LOG_printf() handle signed values correctly?

FastFourier

Expert 1915 points

Dear TI, I've been frustrated for so long that I couldn't get a solid behavior out of LOG_printf(). I'll explain my frustration with an example. Here are a few LOG printf outputs from a current application of mine. It's a digital receiver running in a C5510A.

// Here I have an actual measured frequency error of 41 Hz.  
// Also, my average error is 41 Hz, so my AFC is tracking well.  
// Happy day.  Also, the printf worked well.
,10446,,AFC : freq_error = 41     Average = 41 

// The 5510 is connected to two tuners.  
// The other tuner is exhibiting a frequency error of -79 Hz... but what is this?  
// My average error is 65511?  Well, not so!
// In fact, the average error is really 65511 - 2^16, or -25 Hz.
,10447,,AFC : freq_error = -79     Average = 65511 


...
...
...

// HA!  Both tuners are currently negative, and things aren't where I had 
// hoped they would be.  YET... the DISPLAY problem with LOG_printf persists.
,10412,,AFC : freq_error = -259     Average = 65413 
,10413,,AFC : freq_error = -59     Average = 65498 


Now... I know what you're thinking!  
You : "He's using %u when he should be using %d".  
Here's the code that produced this output...


int temp, tempavg;

// afc_delta_f is a 32 bit value and is signed.  
// It's a 20.11.  So, to be able to display the whole part, I
// downshift it and put it into an int (16-bit on 5510) for LOG_printf debugging
temp = (int)(p_tuner_s->afc_results.afc_delta_f >> 11) & 0xFFFF;

// The same is true for my average.  
// I down shift the 20.11 value, and 
// smush it into an int (16 bits) for LOG_printf() size happiness.
tempavg = (int)((p_tuner_s->afc_sum/p_tuner_s->afc_count) >> 11) & 0xFFFF;

// For Debug
TRACE( &trace, "AFC : freq_error = %d     Average = %d ",
   			temp, 
    			tempavg );

As you can see, both variables are signed integers. (In the C5510, that is a 16-bit value.) And the format string is correct with respect to %d vs %u. Yet the output fails miserably. TI... "what do I gotta do? Do I have to turn the sand into the sea? Is that what you want from me? To make LOG_printf() love me... make LOG_printf() love meeeeeeeeeee?" -The FFT

over 13 years ago

0 FastFourier over 13 years ago

Expert 1915 points

And for that matter... why won't my nice spacing and formatting in the post above stick? I had made it so legible! Yet my white space is gone. /head hanging down. edit : Guessed at the [ code ] forum tag (Take the space out) #winning

0 Chris McCormick over 13 years ago in reply to FastFourier

TI__Expert 4095 points

Are you using CCSv3 or v4? I assume you're viewing the formatted messages in RTA? Thanks, Chris

0 FastFourier over 13 years ago in reply to Chris McCormick

Expert 1915 points

I use CCSv4 as well as CCSv5 depending on the project. My newer projects are in CCSv5. My older ones I've kept in CCSv4. I was actually using the ROV view once breakpointed on errors. Occasionally, I have streamed using RTA, but I don't recall whether that performed differently. Also, I'm using DSP/BIOS 5.41.09.34 CGTools 4.3.5

0 FastFourier over 13 years ago in reply to Chris McCormick

Expert 1915 points

And thank you for the prompt attention Chris. I appreciate it.

0 Chris McCormick over 13 years ago in reply to FastFourier

TI__Expert 4095 points

It definitely doesn't seem right that it's displaying the value 65413 as a signed integer on a target with 16-bit ints. That value can only fit in a 16-bit integer if its unsigned. I'll see if I can reproduce this and take a look. I also saw the formatting disappear on my reply to your post, I'll try and bring that to someone's attention. Thanks, Chris

0 Chris McCormick over 13 years ago in reply to Chris McCormick

TI__Expert 4095 points

FYI: They're looking into the formatting issue. http://e2e.ti.com/group/helpcentral/int_helpcentral/f/683/t/103425.aspx

0 Robert Tivy over 13 years ago

TI__Mastermind 18260 points

Can you try casting your mis-displayed arguments to type 'long' in the LOG_printf() call (is your TRACE actually LOG_printf())? Regards, - Rob

0 FastFourier over 13 years ago in reply to Robert Tivy

Expert 1915 points

Sorry. I obfuscated that a little so I could just #define out all of the LOG_printfs when I went to production code.

#ifdef DO_LOGGING
#define TRACE(log, format, v...) \
    do {    \
            LOG_printf(log, format, ##v);\
    } while(0)
#else
#define TRACE(log, format, v...) ((void)0)
#endif /* DO_LOGGING */

So TRACE is actually a LOG_printf(). Yes. I could cast it to a long, however, I thought 32-bit LOG_printfs weren't supposed to work, unless it's a %p format? From the C55x DSPBIOS_5 API Reference Guide (SPRU404p), page 2-191...

Since LOG_printf does not provide a conversion character for long integers, you may want to use 0x%p instead. Another solution is to use bitwise shifting and ANDing to break a 32-bit number into its 16-bit counterparts. In following example, (Int)(maincount >> 16) is the upper 16 bits of maincount shifted into the 16-bits of an Int. And, (Int)(maincount & 0xffff) is the lower 16 bits of maincount.

0 Norman Wong over 13 years ago in reply to FastFourier

Guru 26430 points

The DSP BIOs APU Ref Guide is sort of vague about log message format when the C55xx memory model is large or huge. The fields in the log message double from 16-bits to 32 bits. The guide doesn't say what happened when you feed 32 bit args to LOG_printf(). I think Rob may be thinking that your "int"s are getting promoted to 32-bit signed integers. All this implies that real printf code on the host side is grabbing 32 bits. It does seem odd that temp and tempavg are treated differently. The behaviour would suggest the "temp" and "tempavg" are really 32-bit register variables and that optimization may be removing the 0xFFFF masking on "temp" but not from "tempavg". Can CCS produce a C/Assembler listing? That should show what the compiler is really doing.

0 FastFourier over 13 years ago in reply to Norman Wong

Expert 1915 points

I just ran it casting temp and tempavg as follows :

int temp, tempavg;

temp = (int)((p_tuner_s->afc_results.afc_delta_f >> 11) & 0xFFFF);

tempavg = (int)(((p_tuner_s->afc_sum/p_tuner_s->afc_count) >> 11) & 0xFFFF);

// For Debug
TRACE( &trace, "AFC : freq_error = %d     Average = %d ",
   			(long int)temp, 
    			(long int)tempavg );

Now I get the following output :

AFC : freq_error = 0    Average = 24
AFC : freq_error = 0    Average = 28
AFC : freq_error = 0    Average = 23
AFC : freq_error = 0    Average = 20

This is obviously erroneous. The chances of my frequency error consistently being 0 is itself 0. Also, with the averages not equal to 0, and the instantaneous freq error always equal to 0, the universe is about to explode. Then, when it goes negative, we have :

AFC : freq_error = -1    Average = 65336
AFC : freq_error = -1    Average = 65341
AFC : freq_error = -1    Average = 65345
AFC : freq_error = -1    Average = 65351

Also obviously wrong. I've never been able to print a 32-bit value using LOG_printf(). Also, for everyone's info, I am indeed using the large data model.

0 FastFourier over 13 years ago in reply to FastFourier

Expert 1915 points

I did a little code reshuffle just to make sure my casts weren't getting affected by the compiler.

long int temp, tempavg;

temp = ((p_tuner_s->afc_results.afc_delta_f >> 11));

tempavg = (((p_tuner_s->afc_sum/p_tuner_s->afc_count) >> 11));

// For Debug
TRACE( &trace, "AFC : freq_error = %d     Average = %d ",
  			temp, 
    			tempavg );

Same results as the previous post. Here's the assembly for the 16-bit version.


    5256              ;----------------------------------------------------------------------
    5257              ; 1080 | temp = (p_tuner_s->afc_results.afc_delta_f >> 11) & 0xFFFF; 
    5258              ;----------------------------------------------------------------------
    5259 000f65 ED04          MOV dbl(*SP(#2)), XAR3
         000f67 BF   
    5260 000f68 ED6D          MOV dbl(*AR3(#1448)), AC0 ; |1080| 
         000f6a 0805 
         000f6c A8   
    5261 000f6d 1005          SFTS AC0, #-11, AC0 ; |1080| 
         000f6f 35   
TMS320C55x Assembler PC v4.3.8 Thu Mar 31 09:42:24 2011

Tools Copyright (c) 1996-2010 Texas Instruments Incorporated
tuner.asm                                                         PAGE  116

    5262 000f70 7DFF          AND #0xffff, AC0, AC0 ; |1080| 
         000f72 FF00 
    5263 000f74 C008          MOV AC0, *SP(#4) ; |1080| 
    5264                      .dwpsn  file "../tuner/tuner.c",line 1081,column 5,is_stmt
    5265              ;----------------------------------------------------------------------
    5266              ; 1081 | tempavg = ((p_tuner_s->afc_sum/p_tuner_s->afc_count) >> 11) & 0xFFFF;  
    5267              ; 1082 | // For Debug                                                           
    5268              ;----------------------------------------------------------------------
    5269 000f76 ED04          MOV dbl(*SP(#2)), XAR3
         000f78 BF   
    5270 000f79 A16D          MOV *AR3(#1389), AC1 ; |1081| 
         000f7b 056D 
    5271 000f7d ED6D          MOV dbl(*AR3(#1386)), AC0 ; |1081| 
         000f7f 0805 
         000f81 6A   
    5272              $C$DW$298       .dwtag  DW_TAG_TI_branch
    5273                      .dwattr $C$DW$298, DW_AT_low_pc(0x00)
    5274                      .dwattr $C$DW$298, DW_AT_name("__divli")
    5275                      .dwattr $C$DW$298, DW_AT_TI_call
    5276 000f82 6C00          CALL #__divli ; |1081| 
         000f84 0000!
    5277                                                      ; call occurs [#__divli] ; |1081| 
    5278 000f86 1005          SFTS AC0, #-11, AC0 ; |1081| 
         000f88 35   
    5279 000f89 7DFF          AND #0xffff, AC0, AC0 ; |1081| 
         000f8b FF00 
    5280 000f8d C00A          MOV AC0, *SP(#5) ; |1081| 
    5281                      .dwpsn  file "../tuner/tuner.c",line 1083,column 5,is_stmt
    5282              ;----------------------------------------------------------------------
    5283              ; 1083 | TRACE( &trace, "AFC : freq_error = %d     Average = %d ",              
    5284              ; 1084 |                     temp,                                              
    5285              ; 1085 |                     tempavg );                                         
    5286              ;----------------------------------------------------------------------
    5287                      .dwpsn  file "../tuner/tuner.c",line 1086,column 1,is_stmt
    5288 000f8f 4E07          AADD #7, SP
    5289                      .dwcfi  cfa_offset, 1
    5290              $C$DW$299       .dwtag  DW_TAG_TI_branch
    5291                      .dwattr $C$DW$299, DW_AT_low_pc(0x00)
    5292                      .dwattr $C$DW$299, DW_AT_TI_return
    5293 000f91 4804          RET
    5294                                                      ; return occurs

0 Norman Wong over 13 years ago in reply to FastFourier

Guru 26430 points

I am not an expert with assembler but it looks okay up to the call to LOG_printf. There isn't a CALL nor any stack layup or register load. Maybe stuff happening behind the scenes.

0 Chris McCormick over 13 years ago in reply to FastFourier

TI__Expert 4095 points

I reproduced your issue with the following code:

int temp = 0xFF85;

LOG_printf(&trace, "val a:%d, val b: %d\n", -79, temp);

I did this with the 55x simulator and BIOS 5.41.10.36, and saw the issue both in ROV and RTA.

I think there is a bug in the ROV and RTA formatting code here. I've filed bug SDOCM00080166; this should get addressed in the next BIOS 5 release.

In the meantime, I found that you can work around this by splitting this into two LOG_printf calls, since it appears to format the first the argument correctly. For example, the following code works correctly.

int temp = 0xFF85;

LOG_printf(&trace, "val b:%d", temp);

Thanks,

Chris

0 FastFourier over 13 years ago in reply to Chris McCormick

Expert 1915 points

Great. Thanks for letting me know what the issue is! I notice that my formatting toolbar is back here on e2e posts. Nice.

So, since we're on the subject of LOG_printf, do you have any idea how to make the timestamp field get filled in? I see veiled references to it in SPRU404, and I see the field in ROV and RTA, but I can't figure out how to populate that. I ask, because I have multiple logs (not just "trace), and absent any timestamping, it makes it hard to figure out the order of how things happened across multiple logs. I realize this is a whole new subject relative to the thread we just worked out, but it's actually what led me to great frustration with signed vs. unsigned... and since the brain trust is assembled... why not ask?

Thanks again Chris et al. Thanks Norman.

0 Chris McCormick over 13 years ago in reply to FastFourier

TI__Expert 4095 points

Unfortunately, the timestamp is only supported on 6x targets in BIOS 5.

We addressed this in BIOS 6, where the timestamp is always present on all targets (though BIOS 6 does not support 55x).

If you have a way to get a timestamp value, you could log it yourself in your LOG_printf statements.

Something you also may find helpful is that, in RTA, there are features for filtering the log events in the display to just focus on the ones you want. You can also export the contents of the RTA Raw Logs view, for example, to .csv, and then play with the data in Excel.

Chris

0 FastFourier over 13 years ago in reply to Chris McCormick

Expert 1915 points

What would be really handy is if, (and maybe this is possible, and I haven't figured out how) in RTA, I could make all LOG_printf() statements appear sequentially. It seems like it services all of my trace logs kind of round robin. So I get clumps of each one together, when they actually occurred interleaved in time. We had put in some preprocessor magic to insert a global sequence number at the beginning of the format for the LOG_printf, but it interfered with signed vs unsigned which is how we ended up talking in this thread.

0 Chris McCormick over 13 years ago in reply to FastFourier

TI__Expert 4095 points

I believe I have a patch ready for this signed value issue.

2251.LOG.xs.txt

Remove the '.txt' extension from the attached file and save it as LOG.xs in the following location in your BIOS 5 install.

C:\Program Files\Texas Instruments\bios_5_41_09_34\packages\ti\bios\rov\LOG.xs

It's probably a good idea to rename the original copy of the file before saving this patched one.

I think that should do it; let me know if you encounter any new formatting issues.

Thanks!

Chris

P.S. - Note that this will only patch your ROV LOG view. If you're interested in a patch for RTA as well, let me know. Otherwise it will be in the next BIOS 5 release.

0 FastFourier over 13 years ago in reply to Chris McCormick

Expert 1915 points

BEAUTIFUL! Works perfectly in CCSv5. Haven't tried CCSv4 yet, but I'm confident it will work. (Famous last words.) Thanks so much Chris!

Processors

Processors forum

Why won't LOG_printf() handle signed values correctly?