Simics continuous trace

Change-Id: I5f5d9c30b4cc0f0d8704fb99c10757e0f41018bf
Reviewed-on: http://gfw160.austin.ibm.com:8080/gerrit/603
Tested-by: Jenkins Server
Reviewed-by: A. Patrick Williams III <iawillia@us.ibm.com>
Reviewed-by: Mark W. Wenning <wenning@us.ibm.com>
Reviewed-by: MIKE J. JONES <mjjones@us.ibm.com>

6 files changed, 291 insertions, 25 deletions

diff --git a/src/build/debug/simics-debug-framework.py b/src/build/debug/simics-debug-framework.py
index dcd05cee1..8f4e0de78 100755
--- a/src/build/debug/simics-debug-framework.py
+++ b/src/build/debug/simics-debug-framework.py
@@ -260,6 +260,83 @@ def register_hb_debug_framework_tools():
                     doc = usage)
         print "Hostboot Debug Framework: Registered tool:", "hb-" + tool
 
+
+# Return a number/address built from the input list elements. Each element
+# in the input is a string representation of a byte-sized hex number, for 
+# example '0x2b' or '0x0' or '0xa'.  This does no endian conversion, thus
+# the input needs to be big endian.  The length of the input list can be 
+# any size, usually 2, 4, or 8.
+def hexDumpToNumber(hexlist):
+    strNumber=""
+    for i in range(len(hexlist)):
+        # take away 0x for this byte
+        hexlist[i] = hexlist[i][2:]
+        # zero-fill leading zeroes to make a 2-char string
+        hexlist[i] = hexlist[i].zfill(2)
+        # concatenate onto addr
+        strNumber += hexlist[i]
+    return int(strNumber,16)
+
+
+# Read simics memory and return a list of strings such as ['0x0','0x2b','0x8']
+# representing the data read from simics. The list returned may be handed
+# to hexDumpToNumber() to turn the list into a number. 
+def dumpSimicsMemory(address,bytecount):
+    hexlist = map(hex,conf.phys_mem.memory[[address,address+bytecount-1]])
+    return hexlist
+
+
+# Read the 64-bit big endian at the address given, return it as a number.
+def readLongLong(address):
+    hexlist = dumpSimicsMemory(address,8)
+    return hexDumpToNumber(hexlist)
+
+
+# MAGIC_INSTRUCTION hap handler 
+# arg contains the integer parameter n passed to MAGIC_INSTRUCTION(n)
+# See src/include/arch/ppc.H for the definitions of the magic args.
+# Hostboot magic args should range 7000..7999.
+def magic_instruction_callback(user_arg, cpu, arg):
+    if arg == 7006:   # MAGIC_SHUTDOWN
+        # KernelMisc::shutdown()
+        print "KernelMisc::shutdown() called."
+        # Could break/stop/pause the simics run, but presently 
+        # shutdown() is called four times. --Monte Jan 2012
+        # SIM_break_simulation( "Shutdown. Simulation stopped." )
+
+    if arg == 7007:   # MAGIC_BREAK
+        # Stop the simulation, much like a hard-coded breakpoint 
+        SIM_break_simulation( "Simulation stopped. (hap 7007)"  )
+
+    if arg == 7055:   # MAGIC_CONTINUOUS_TRACE 
+        # Continuous trace.
+        # Residing at tracBinaryInfoAddr is the pointer to the tracBinary buffer
+        pTracBinaryBuffer = readLongLong(tracBinaryInfoAddr)
+        # Read the count of bytes used in the tracBinary buffer
+        cbUsed = readLongLong(tracBinaryInfoAddr+8)
+        # Save the tracBinary buffer to a file named tracBINARY in current dir
+        saveCommand = "memory_image_ln0.save tracBINARY 0x%x %d"%(pTracBinaryBuffer,cbUsed)
+        SIM_run_alone(run_command, saveCommand )
+        # Run fsp-trace on tracBINARY file (implied), append output to tracMERG
+        os.system( "fsp-trace ./ -s hbotStringFile >>tracMERG  2>/dev/null" )
+
+
+# Continuous trace:  Open the symbols and find the address for 
+# "g_tracBinaryInfo"  Convert to a number and save in tracBinaryInfoAddr
+for line in open('hbicore.syms'):
+    if "g_tracBinaryInfo" in line:
+        words=line.split(",")
+        tracBinaryInfoAddr=int(words[1],16)
+        break
+
+# Continuous trace: Clear these files.
+rc = os.system( "rm -f tracMERG" )
+rc = os.system( "rm -f tracBINARY" )
+
+# Register the magic instruction hap handler (a callback).
+SIM_hap_add_callback_range( "Core_Magic_Instruction", magic_instruction_callback, None, 7000, 7999 )
+
+
 # Run the registration automatically whenever this script is loaded.
 register_hb_debug_framework_tools()
 
diff --git a/src/include/arch/ppc.H b/src/include/arch/ppc.H
index 94b0d3e1b..ae70f3547 100644
--- a/src/include/arch/ppc.H
+++ b/src/include/arch/ppc.H
@@ -258,4 +258,64 @@ inline void doze()
     asm volatile("doze");
 }
 
+/** @brief  This is a special assembler instruction that is a nop on 
+ *  regular hardware, but has special meaning to Simics.  Code that
+ *  executes this instruction in Simics will cause a "hap," a 
+ *  Simics term.  If there is no hap handler registered, and magic
+ *  breakpoints have not been enabled with
+ *      simics> enable-magic-breakpoint 
+ *  then this instruction is also a nop in Simics. 
+ * 
+ *  If magic breakpoints are enabled, and there is no hap handler, then
+ *  when Hostboot code executes this instruction in Simics, Simics will
+ *  stop the simulation. (Prompt changes from running> to simics> )
+ * 
+ *  If a hap is registered, then Simics will call the hap handler.  Hap
+ *  handlers are written in Python, and the best place for them is
+ * 
+ *     src/build/debug/simics-debug-framework.py
+ *
+ *  Sample code to register the hap handler:
+ *        # arg contains the integer parameter n passed to MAGIC_INSTRUCTION(n)
+ *        def magic_instruction_callback(user_arg, cpu, arg):
+ *            # print to console works...
+ *            print "Hit magic instruction ", arg
+ *            # Or else stop the simulation...
+ *            SIM_break_simulation( "Stopped at magic instruction" )
+ * 
+ *        # Register the magic instruction callback.
+ *        SIM_hap_add_callback( "Core_Magic_Instruction", magic_instruction_callback, None )
+ *
+ *        # Better to register the Hostboot range 7000-7999
+ *        # so that PHYP and others won't be affected.
+ *        SIM_hap_add_callback_range( "Core_Magic_Instruction", magic_instruction_callback, None, 7000, 7999 )
+ * 
+ *  The argument n is an integer from 0..8191 which Simics passes to the hap
+ *  handler in parameter 3, or "arg" in the sample code above. 
+ */ 
+ALWAYS_INLINE
+inline void MAGIC_INSTRUCTION(int _n)
+{
+    register int n = _n;
+    asm volatile("rlwimi %0,%0,0,%1,%2"       \
+        :: "i" (((n) >> 8) & 0x1f),           \
+        "i" (((n) >> 4) & 0xf),               \
+        "i" ((((n) >> 0) & 0xf) | 16));
+}
+
+// Arguments to MAGIC_INSTRUCTION(). 
+// To ensure they do not conflict with haps from other groups (PHYP 
+// for example), assign hap numbers in the range 7000..7999 (decimal).
+// Presently, the hap handler for magic instruction is found in 
+// src/build/debug/simics-debug-framework.py
+// Jan 2012 Monte
+
+enum
+{
+    MAGIC_SHUTDOWN            =  7006, // KernelMisc::shutdown() called.
+    MAGIC_BREAK               =  7007, // hard-code a breakpoint
+    MAGIC_CONTINUOUS_TRACE    =  7055  // extract mixed trace buffer 
+};
+
+
 #endif
diff --git a/src/include/usr/trace/trace.H b/src/include/usr/trace/trace.H
index ccc3449f0..6caa472b5 100644
--- a/src/include/usr/trace/trace.H
+++ b/src/include/usr/trace/trace.H
@@ -372,8 +372,11 @@ private:
                               const int32_t i_type);
 
 
-    // Global Mutex
-    mutex_t    iv_trac_mutex;
+    // Mutex protecting/serializing writes to trace buffers.
+    mutex_t iv_trac_mutex;
+
+    // Controls writing to tracBinary
+    bool iv_ContinuousTrace; 
 
 };
 
diff --git a/src/kernel/misc.C b/src/kernel/misc.C
index 7357bb565..082e45020 100644
--- a/src/kernel/misc.C
+++ b/src/kernel/misc.C
@@ -57,6 +57,14 @@ namespace KernelMisc
                          :: "r" (scratch_address), "r" (status));
         }
 
+        // dump whatever is left in g_tracBinary
+        MAGIC_INSTRUCTION(MAGIC_CONTINUOUS_TRACE);
+
+        // See magic_instruction_callback() in 
+        // src/build/debug/simics-debug-framework.py 
+        // for exactly how this is handled.
+        MAGIC_INSTRUCTION(MAGIC_SHUTDOWN);
+
         while(1)
         {
             doze();
diff --git a/src/usr/trace/makefile b/src/usr/trace/makefile
index b18e48661..c025957c0 100644
--- a/src/usr/trace/makefile
+++ b/src/usr/trace/makefile
@@ -23,7 +23,7 @@
 ROOTPATH = ../../..
 MODULE = trace
 
-OBJS = trace.o tracebuffer.o assert.o
+OBJS = trace.o assert.o
 
 SUBDIRS = test.d
 
diff --git a/src/usr/trace/trace.C b/src/usr/trace/trace.C
index bb3ca81e5..6efe9fbd6 100644
--- a/src/usr/trace/trace.C
+++ b/src/usr/trace/trace.C
@@ -75,7 +75,7 @@ const uint32_t TRAC_TIME_167MHZ = 3;  // 166666667Hz
 
 
 
-// WARNING: Changing the size of the trace buffer name string requires a 
+// WARNING: Changing the size of the trace buffer name string requires a
 // changing OFFSET_BUFFER_ADDRESS in src/build/debug/Hostboot/Trace.pm.
 const uint32_t COMP_NAME_SIZE   = 16; // includes NULL terminator, so 15 max
 
@@ -87,15 +87,15 @@ const uint64_t     TRAC_DEFAULT_BUFFER_SIZE = 0x0800;  //2KB
 
 // The number of trace buffers.
 // NOTE: This constant should only be changed to an even number for now.
-// WARNING: Changing the count of buffers requires a co-req change 
+// WARNING: Changing the count of buffers requires a co-req change
 // in src/build/debug/Hostboot/Trace.pm  which has this count hard coded.
 const uint64_t TRAC_MAX_NUM_BUFFERS = 48;
 
 // An array of these structs accounts for all the trace buffers in Hostboot.
-// WARNING: Changing the size of trace_desc_array requires a co-req change 
+// WARNING: Changing the size of trace_desc_array requires a co-req change
 // in src/build/debug/Hostboot/Trace.pm  which has hard-coded the size of
-// this structure. 
-typedef struct trace_desc_array 
+// this structure.
+typedef struct trace_desc_array
 {
     char comp[COMP_NAME_SIZE];        // the buffer name
     trace_desc_t * td_entry;          // pointer to the buffer
@@ -105,6 +105,21 @@ typedef struct trace_desc_array
 trace_desc_array_t g_desc_array[TRAC_MAX_NUM_BUFFERS];
 
 
+// Set up a structure to hold information about the mixed-trace
+// or continuous-trace buffer, aka tracBINARY.
+
+// WARNING: Changes to this structure will require co-req changes to 
+// src/build/debug/simics-debug-framework.py which contains the simics
+// hap handler for extracting this buffer.
+struct mixed_trace_info
+{
+    char *     pBuffer;
+    uint64_t   cbUsed;
+};
+typedef struct mixed_trace_info mixed_trace_info_t; 
+const uint64_t TRAC_BINARY_SIZE = 4096;
+mixed_trace_info_t g_tracBinaryInfo;
+
 
 /******************************************************************************/
 // TracInit::TracInit()
@@ -139,6 +154,17 @@ Trace::Trace()
 
     // compiler inits global vars to zero
     // memset(g_desc_array, 0, sizeof(g_desc_array));
+
+    g_tracBinaryInfo.pBuffer  =  static_cast<char*>(malloc(TRAC_BINARY_SIZE));
+
+    // fsp-trace convention expects a 2 in the first byte of tracBINARY
+    g_tracBinaryInfo.pBuffer[0] = 2;
+    g_tracBinaryInfo.cbUsed     = 1;  
+
+    // tracBINARY buffer appending is always on.
+    // TODO figure a way to control continuous trace on/off, perhaps
+    // unregister the hap handler for it. 
+    iv_ContinuousTrace = 1;
 }
 
 /******************************************************************************/
@@ -428,22 +454,18 @@ void Trace::_trace_adal_write_all(trace_desc_t *io_td,
         l_entry.head.hash = i_hash;
         l_entry.head.line = i_line;
 
-        // Time stamp
-        convertTime(&l_entry.stamp);
 
         // Calculate total space needed for the entry, which is a
         // combination of the data size from above, the entry
         // headers, and an overall length field.
-        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 = l_data_size +
+                       sizeof(trace_entry_stamp_t) +
+                       sizeof(trace_entry_head_t)  +
+                       // Allow for a uint32 at the end of the trace entry
+                       // so parsers may walk the trace buffer backwards
+                       sizeof(uint32_t);
+
+        // Round up the size to the next word boundary
         l_entry_size = ALIGN_4(l_entry_size);
 
         // Allocate buffer for the arguments we're tracing
@@ -502,12 +524,14 @@ void Trace::_trace_adal_write_all(trace_desc_t *io_td,
 
         va_end(l_args);
 
-        // We now have total size and need to reserve a part of the trace
-        // buffer for this
+        // Write entry to the trace buffer.
 
         // CRITICAL REGION START
         mutex_lock(&iv_trac_mutex);
 
+        // time stamp the entry with time-base register
+        convertTime(&l_entry.stamp);
+
         // Update the entry count
         io_td->te_count++;
 
@@ -527,6 +551,46 @@ void Trace::_trace_adal_write_all(trace_desc_t *io_td,
                   static_cast<void *>(&l_entry_size),
                   sizeof(l_entry_size));
 
+
+
+        // Write to the combined trace buffer, a stream of traces.
+        if( iv_ContinuousTrace )
+        {
+            // This entry requires this many bytes to fit.
+            uint64_t l_cbCompName = 1 + strlen( io_td->comp );
+            uint64_t l_cbRequired = l_cbCompName +
+                                    sizeof( l_entry ) +
+                                    l_data_size;
+
+            if( (g_tracBinaryInfo.cbUsed + l_cbRequired) >  TRAC_BINARY_SIZE  )
+            {
+                // does not fit, so call somebody to collect it.
+                // TODO how to do this in VBU
+                MAGIC_INSTRUCTION(MAGIC_CONTINUOUS_TRACE);
+
+                // start over
+                g_tracBinaryInfo.cbUsed = 1;
+            }
+
+            // Copy the entry piecemeal to the destination.
+            char * l_pchDest = g_tracBinaryInfo.pBuffer + g_tracBinaryInfo.cbUsed;
+
+            // component name and its trailing nil byte
+            strcpy( l_pchDest, io_td->comp );
+            l_pchDest += l_cbCompName;
+
+            // trace entry
+            memcpy( l_pchDest, &l_entry, sizeof(l_entry));
+            l_pchDest += sizeof(l_entry);
+
+            // trace entry data
+            memcpy( l_pchDest, l_buffer, l_data_size );
+
+            // adjust for next time
+            g_tracBinaryInfo.cbUsed += l_cbRequired;
+        }
+
+
         mutex_unlock(&iv_trac_mutex);
         // CRITICAL REGION END
 
@@ -606,12 +670,13 @@ void Trace::_trace_adal_write_bin(trace_desc_t *io_td,const trace_hash_val i_has
         // We now have total size and need to reserve a part of the trace
         // buffer for this
 
-        // Time stamp
-        convertTime(&l_entry.stamp);
-
         // CRITICAL REGION START
         mutex_lock(&iv_trac_mutex);
 
+
+        // time stamp the entry with time-base register
+        convertTime(&l_entry.stamp);
+
         // Increment trace counter
         io_td->te_count++;
 
@@ -630,6 +695,58 @@ void Trace::_trace_adal_write_bin(trace_desc_t *io_td,const trace_hash_val i_has
                   static_cast<void *>(&l_entry_size),
                   sizeof(l_entry_size));
 
+        // Write to the combined trace buffer, a stream of traces.
+        // A while() here affords use of break to break out on
+        // an error condition.
+        while( iv_ContinuousTrace )
+        {
+            // This entry requires this many bytes to fit.
+            uint64_t l_cbCompName = 1 + strlen( io_td->comp );
+            uint64_t l_cbRequired = l_cbCompName +
+                                    sizeof( l_entry ) +
+                                    i_size;
+
+            if( l_cbRequired > TRAC_BINARY_SIZE )
+            {
+                // caller is logging more binary data than the
+                // size of the tracBinary buffer.
+                // TODO need to increase the buffer size, or else
+                // document its limits.
+                break;
+            }
+
+            if( (g_tracBinaryInfo.cbUsed + l_cbRequired) >  TRAC_BINARY_SIZE  )
+            {
+                // does not fit, so call somebody to collect it.
+                // TODO
+                MAGIC_INSTRUCTION(MAGIC_CONTINUOUS_TRACE);
+
+                // start over
+                g_tracBinaryInfo.cbUsed = 1;
+            }
+
+            // Copy the entry piecemeal to the destination.
+            char * l_pchDest = g_tracBinaryInfo.pBuffer + g_tracBinaryInfo.cbUsed;
+
+            // component name and its trailing nil byte
+            strcpy( l_pchDest, io_td->comp );
+            l_pchDest += l_cbCompName;
+
+            // trace entry
+            memcpy( l_pchDest, &l_entry, sizeof(l_entry));
+            l_pchDest += sizeof(l_entry);
+
+            // trace entry data
+            memcpy( l_pchDest, i_ptr, i_size );
+
+            // adjust for next time
+            g_tracBinaryInfo.cbUsed += l_cbRequired;
+
+            // break from while() which was used much like an if()
+            break;
+        }
+
+
         // CRITICAL REGION END
         mutex_unlock(&iv_trac_mutex);
 
@@ -745,6 +862,7 @@ void Trace::convertTime(trace_entry_stamp_t *o_entry)
 
 
 
+
 /******************************************************************************/
 // findTdByName
 /******************************************************************************/