Add %s string formatting support to trace

Change-Id: I14ea6717dfd8e98895345e86e32e82c637c26289
Reviewed-on: http://gfw160.austin.ibm.com:8080/gerrit/234
Tested-by: Jenkins Server
Reviewed-by: CAMVAN T. NGUYEN <ctnguyen@us.ibm.com>

4 files changed, 179 insertions, 41 deletions

diff --git a/src/include/usr/trace/trace.H b/src/include/usr/trace/trace.H
index e4ea8922c..f30f2c0a3 100644
--- a/src/include/usr/trace/trace.H
+++ b/src/include/usr/trace/trace.H
@@ -22,6 +22,7 @@
 /******************************************************************************/
 
 const uint32_t TRACE_BUF_VERSION = 0x01;    // Trace buffer version
+const uint32_t TRACE_COMP_TRACE  = 0x434F;  // Component Field Trace - "CO"
 const uint32_t TRACE_FIELDTRACE  = 0x4654;  // Field Trace - "FT"
 const uint32_t TRACE_FIELDBIN    = 0x4644;  // Binary Field Trace - "FD"
 
@@ -265,8 +266,6 @@ private:
      *
      *  @param [in] i_comp Component name to retrieve trace descriptor for.
      *
-     *  TODO - Not Supported Yet
-     *
      *  @return Valid trace descriptor on success, NULL on failure.
      */
     trace_desc_t * getTd(const char *i_comp);
diff --git a/src/include/util/align.H b/src/include/util/align.H
new file mode 100644
index 000000000..3edbff09a
--- /dev/null
+++ b/src/include/util/align.H
@@ -0,0 +1,6 @@
+#ifndef __UTIL_ALIGN_H
+#define __UTIL_ALIGN_H
+
+#define ALIGN_4(u) ((u + 0x3ull) & ~0x3ull)
+
+#endif
diff --git a/src/usr/trace/test/tracetest.H b/src/usr/trace/test/tracetest.H
index 06c9f9ea3..3082242b3 100644
--- a/src/usr/trace/test/tracetest.H
+++ b/src/usr/trace/test/tracetest.H
@@ -188,6 +188,52 @@ public:
     }
 
     /**
+     * @test Test String Trace Interface
+     */
+    void testTracString(void)
+    {
+        trace_desc_t *g_trac_test = NULL;
+        TRAC_INIT_BUFFER(&g_trac_test, "STRING", 4096);
+
+        if(g_trac_test == NULL)
+        {
+            TS_FAIL("g_trac_test was returned as NULL!");
+        }
+        else
+        {
+            TRACFCOMP(g_trac_test,"String at end '%s'", "Last");
+            TRACFCOMP(g_trac_test,"%s: String at beginning", "FIRST");
+            TRACFCOMP(g_trac_test,"Test '%s' string", "middle");
+
+            const char * str = "This is a \tlong string\nwith horizontal tab and newline.";
+            TRACFCOMP(g_trac_test,"Testing (c,u,s,X): %c, %u, %s 0x%X", 'b',0x11,str,10);
+
+            TRACFCOMP(g_trac_test,"Testing string len 1: %s, %s, %s", "A", "B", "C");
+            TRACFCOMP(g_trac_test,"Testing NULL string: %s", "");
+
+            TRACFCOMP(g_trac_test,"Testing string alignment: %s %s", "hello", "world");
+            TRACFCOMP(g_trac_test,"Testing string alignment: %s %s", "Hostboot", "Software");
+            TRACFCOMP(g_trac_test,"Testing string alignment: %s %s", "Hostboot2", "Software3");
+
+            TRACFCOMP(g_trac_test,"%s %s %s %s", "Four", "strings", "by", "themselves");
+
+            TRACFCOMP(g_trac_test,"Testing special characters: %s",
+                      "?!@#$%^&*()\"/\'\\<>.,:;");
+
+            TRACFCOMP(g_trac_test,"Testing percent: %% %%%d %%%s 100%%", 50, "hello");
+
+            TRACFCOMP(g_trac_test, INFO_MRK"Testing all number types (s,c,u,X,d): %s, %c %u 0x%X %d",
+                      "hello",'a',10,11,12);
+            TRACFCOMP(g_trac_test, "Testing all number types (c,u,s,X,d): %c %u %s 0x%X %d",
+                      'b',13,"world!",14,15);
+            TRACFCOMP(g_trac_test, "Testing all number types (c,u,X,d,s): %c %u 0x%X %d %s",
+                      'c',16,17,18,"Hostboot");
+            TRACFCOMP(g_trac_test, "Testing all number types (s,c,s,u,s,X): %s %c %s %u %s 0x%X",
+                      "Astring",'d',"Bstring12",19,"Cstring123",20);
+        }
+    }
+
+    /**
      * @test Test max number of buffers
      */
     void testTracMaxBuffers(void)
diff --git a/src/usr/trace/trace.C b/src/usr/trace/trace.C
index d52274473..dcc48ca27 100644
--- a/src/usr/trace/trace.C
+++ b/src/usr/trace/trace.C
@@ -21,6 +21,7 @@
 #include <sys/task.h>
 #include <sys/sync.h>
 #include <string.h>
+#include <util/align.H>
 
 #include <trace/trace.H>
 
@@ -280,83 +281,169 @@ void Trace::trace_adal_write_all(trace_desc_t *io_td,
     /*  Local Variables                                                       */
     /*------------------------------------------------------------------------*/
     uint32_t                l_entry_size = 0;
-    trace_entire_entry_t    l_entry;
+    uint32_t                l_data_size= 0;
+    //trace_entire_entry_t    l_entry;
+    trace_bin_entry_t       l_entry;
+    uint64_t                l_str_map = 0;
+
 
     /*------------------------------------------------------------------------*/
     /*  Code                                                                  */
     /*------------------------------------------------------------------------*/
 
-    // This code is incorrect for determining formatting but will work for now.
     uint32_t num_args = 0;
+    uint32_t num_4byte_args = 0; //fsp-trace counts 8-byte args as 2 4-byte args
     const char* _fmt = i_fmt;
-    while ('\0' != *_fmt)
-    {
-        if ('%' == *_fmt)
-            num_args++;
-        _fmt++;
-    }
 
-    if((num_args <= TRAC_MAX_ARGS) && (io_td != NULL))
+    va_list args;
+    va_start(args, i_type);
+    for (size_t i = 0; i <= strlen(_fmt); i++)
     {
+        if ('%' == _fmt[i])
+        {
+            i++;
 
-        // Calculate total space needed
-        l_entry_size = sizeof(trace_entry_stamp_t);
-        l_entry_size += sizeof(trace_entry_head_t);
+            if ('%' == _fmt[i])
+            {
+                continue;
+            }
+            else if ('s' == _fmt[i])
+            {
+                // Set flag to indicate argument is a string
+                l_str_map = l_str_map | (1 << num_args);
 
-        // We always add the size of the entry at the end of the trace entry
-        // so the parsing tool can easily walk the trace buffer stack so we
-        // need to add that on to total size
-        l_entry_size += sizeof(uint32_t);
+                // String counts as one 4-byte arg
+                num_args++;
+                num_4byte_args++;
 
-        // Now add on size for actual number of arguments we're tracing
-        l_entry_size += (num_args * sizeof(uint64_t));
+                char * l_str = va_arg(args, char *);
+                size_t l_strLen = strlen(l_str);
 
-        // Word align the entry
-        l_entry_size = (l_entry_size + 3) & ~3;
+                // Add to total size of number of arguments we're tracing
+                // and account for word alignment
+                l_data_size += l_strLen + 1;
+                l_data_size = ALIGN_4(l_data_size);
+
+                //printk("Trace: STRING %s: strlen %d num_args %d l_data_size %d\n",
+                //       l_str, static_cast<uint32_t>(l_strLen),
+                //       num_args, l_data_size);
+                //printk("Trace: l_str_map 0x%16llX\n", static_cast<long long>(l_str_map));
+            }
+            else
+            {
+                // Numbers count as two 4-byte arg
+                num_args++;
+                num_4byte_args += 2;
+
+                // Retrieve the argument to increment to next one
+                uint64_t l_tmpData = va_arg(args, uint64_t);
 
+                // Add to total size; data is word aligned
+                l_data_size += sizeof(l_tmpData);
+            }
+        }
+    }
+    va_end(args);
+
+    if((num_4byte_args <= TRAC_MAX_ARGS) && (io_td != NULL))
+    {
         // Fill in the entry structure
         l_entry.stamp.tid = static_cast<uint32_t>(task_gettid());
 
         // Length is equal to size of data
-        l_entry.head.length = (num_args * sizeof(uint64_t));
-        l_entry.head.tag = TRACE_FIELDTRACE;
+        l_entry.head.length = l_data_size;
+        //l_entry.head.tag = TRACE_FIELDTRACE;
+        l_entry.head.tag = TRACE_COMP_TRACE;
         l_entry.head.hash = i_hash;
         l_entry.head.line = i_line;
 
         // Time stamp
         convertTime(&l_entry.stamp);
 
-        uint64_t* data = &l_entry.args[0];
+        // Calculate total space needed
+        l_entry_size = l_data_size;
+        l_entry_size += sizeof(trace_entry_stamp_t);
+        l_entry_size += sizeof(trace_entry_head_t);
+
+        // We always add the size of the entry at the end of the trace entry
+        // so the parsing tool can easily walk the trace buffer stack so we
+        // need to add that on to total size
+        l_entry_size += sizeof(uint32_t);
+
+        // Word align the entry
+        l_entry_size = ALIGN_4(l_entry_size);
+
+        // Allocate buffer for the arguments we're tracing
+        void * l_buffer = malloc(l_data_size);
+        memset(l_buffer, 0, l_data_size);
+        char * l_ptr = static_cast<char *> (l_buffer);
 
+        // Now copy the arguments to the buffer
         va_list args;
         va_start(args, i_type);
         for (size_t i = 0; i < num_args; i++)
         {
-            *data = va_arg(args, uint64_t);
-            data++;
+            uint32_t l_strLen = 0;
+
+            if (l_str_map & (1 << i))
+            {
+                // Save string to buffer
+                strcpy(l_ptr, va_arg(args, char *));
+
+                //printk("Trace: Saved String %s Arg[%d]\n", l_ptr, static_cast<uint32_t>(i));
+
+                // Length = string length + NULL termination
+                l_strLen += (strlen(l_ptr) + 1);
+
+                // Increment pointer to next word alignment
+                l_ptr += l_strLen;
+                l_ptr = reinterpret_cast<char *>(
+                        ALIGN_4(reinterpret_cast<uint64_t>(l_ptr)) );
+
+                //printk("Trace::trace_adal_write_all - l_buffer %p l_ptr %p l_strLen %d\n",
+                //       l_buffer, l_ptr, l_strLen);
+                //printk("Trace::trace_adal_write_all - num_args %d l_data_size %d l_entry_size %d\n",
+                //       num_args, l_data_size, l_entry_size);
+            }
+            else
+            {
+                // Save number to buffer & increment pointer (no need to align)
+                *(reinterpret_cast<uint64_t *>(l_ptr)) = va_arg(args, uint64_t);
+                l_ptr += sizeof(uint64_t);
+            }
         }
         va_end(args);
 
-        // Now put total size at end of buffer
-        // Note that fsp-trace assumes this to be a 32 bit long word
-        uint32_t *l_size = reinterpret_cast<uint32_t *>
-                            (&(l_entry.args[num_args]));
-        *l_size = l_entry_size;
-
         // We now have total size and need to reserve a part of the trace
         // buffer for this
 
         // CRITICAL REGION START
         mutex_lock(&iv_trac_mutex);
+
         // Update the entry count
         io_td->te_count++;
 
+        // First write the header
         writeData(io_td,
                   static_cast<void *>(&l_entry),
-                  l_entry_size);
+                  sizeof(l_entry));
+
+        // Now write the actual data
+        writeData(io_td,
+                  l_buffer,
+                  l_data_size);
+
+        // Now write the size at the end
+        // Note that fsp-trace assumes this to be a 32 bit long word
+        writeData(io_td,
+                  static_cast<void *>(&l_entry_size),
+                  sizeof(l_entry_size));
 
         mutex_unlock(&iv_trac_mutex);
         // CRITICAL REGION END
+
+        // Free allocated memory
+        free(l_buffer);
     }
 
     return;
@@ -397,11 +484,11 @@ void Trace::trace_adal_write_bin(trace_desc_t *io_td,const trace_hash_val i_hash
         // need to add that on to total size
         l_entry_size += sizeof(uint32_t);
 
-        // Now add on size for acutal size of the binary data
+        // Now add on size for actual size of the binary data
         l_entry_size += i_size;
 
         // Word align the entry
-        l_entry_size = (l_entry_size + 3) & ~3;
+        l_entry_size = ALIGN_4(l_entry_size);
 
         // Fill in the entry structure
         l_entry.stamp.tid = static_cast<uint32_t>(task_gettid());
@@ -480,8 +567,8 @@ void Trace::writeData(trace_desc_t *io_td,
             // Get the pointer to current location in buffer
             l_buf_ptr = reinterpret_cast<char *>(io_td) + io_td->next_free;
             // Figure out the alignment
-            l_align = ( (reinterpret_cast<uint64_t>(l_buf_ptr) + 3) & ~3) -
-                          reinterpret_cast<uint64_t>(l_buf_ptr);
+            l_align = ALIGN_4(reinterpret_cast<uint64_t>(l_buf_ptr)) -
+                      reinterpret_cast<uint64_t>(l_buf_ptr);
             // Add on the alignment
             l_buf_ptr = reinterpret_cast<void *>(reinterpret_cast<uint64_t>
                          (l_buf_ptr) + l_align);
@@ -500,8 +587,8 @@ void Trace::writeData(trace_desc_t *io_td,
         // Get the pointer to current location in buffer
         l_buf_ptr = reinterpret_cast<char *>(io_td) + io_td->next_free;
         // Figure out the alignment
-        l_align = ( (reinterpret_cast<uint64_t>(l_buf_ptr) + 3) & ~3) -
-                                  reinterpret_cast<uint64_t>(l_buf_ptr);
+        l_align = ALIGN_4(reinterpret_cast<uint64_t>(l_buf_ptr)) -
+                  reinterpret_cast<uint64_t>(l_buf_ptr);
         // Add on the alignment
         l_buf_ptr = reinterpret_cast<void *>(reinterpret_cast<uint64_t>
                                  (l_buf_ptr) + l_align);
@@ -514,7 +601,7 @@ void Trace::writeData(trace_desc_t *io_td,
         // has the potential to be un-word aligned.  If two parts of the binary
         // trace had this problem then this code would not work.
         // Note that fsp-trace will ignore garbage data in the unaligned areas.
-        l_total_size = (l_total_size + 3) & ~3;
+        l_total_size = ALIGN_4(l_total_size);
         io_td->next_free += l_total_size;
 
     }while(0);