Fix continuous trace function losing traces in high traffic condition.

Change-Id: I9444e222e89e44017bf3039a09ecb28e9409a389
RTC: 39164
Reviewed-on: http://gfw160.austin.ibm.com:8080/gerrit/917
Tested-by: Jenkins Server
Reviewed-by: A. Patrick Williams III <iawillia@us.ibm.com>

4 files changed, 193 insertions, 21 deletions

diff --git a/src/build/debug/Hostboot/ContTrace.pm b/src/build/debug/Hostboot/ContTrace.pm
index a9ba5eadb..1559199be 100755
--- a/src/build/debug/Hostboot/ContTrace.pm
+++ b/src/build/debug/Hostboot/ContTrace.pm
@@ -28,8 +28,12 @@ package Hostboot::ContTrace;
 use Exporter;
 our @EXPORT_OK = ('main');
 
+use constant MAX_NUM_CONT_TRACE_CTL_STRUCT => 2;
+use constant CONT_TRACE_CTL_STRUCT_SIZE => 16;
+use constant CONT_TRACE_ENABLE_FLAG_OFFSET => MAX_NUM_CONT_TRACE_CTL_STRUCT * CONT_TRACE_CTL_STRUCT_SIZE;
 use constant MAX_NUM_CONT_TRACE_BUFFERS => 2;
 use constant DDWORD_SIZE => 8;
+use constant WORD_SIZE => 4;
 use constant TRIG_BIT => 0x8000000000000000;
 
 use File::Temp ('tempfile');
@@ -46,6 +50,12 @@ sub main
         $args->{"fsp-trace"} = "fsp-trace";
     }
 
+    my $dbgMsg = 0;
+    if (defined $args->{"debug"})
+    {
+        $dbgMsg = 1;
+    }
+
     my $fsptrace_options = "";
     if (defined $args->{"with-file-names"})
     {
@@ -58,59 +68,184 @@ sub main
         $last = 1;
     }
 
-    my ($symAddr, $symSize) =
+    my $on2off = 0;
+    my $symAddr = 0;
+    my $symSize = 0;
+
+    if (defined $args->{"enable-cont-trace"})
+    {
+        my $new_enable = $args->{"enable-cont-trace"};
+        $new_enable = $new_enable ? 2 : 0;
+        ($symAddr, $symSize) =
+                      ::findSymbolAddress("TRACE::g_cont_trace_trigger_info");
+        if (not defined $symAddr)
+        {
+            ::userDisplay "Cannot find symbol.\n"; die;
+        }
+        my $enable = ::read64($symAddr + CONT_TRACE_ENABLE_FLAG_OFFSET);
+        if ($dbgMsg)
+        {
+            ::userDisplay("current Cont Trace Enable Flag = $enable\n");
+        }
+        if (($enable < 2) && ($new_enable == 2))
+        {
+            # truncate tracMERG to 0
+            system( "cp /dev/null tracMERG" );
+            ::write64($symAddr + CONT_TRACE_ENABLE_FLAG_OFFSET, $new_enable);
+            if ($dbgMsg)
+            {
+                $new_enable = ::read64($symAddr+CONT_TRACE_ENABLE_FLAG_OFFSET);
+                ::userDisplay("new Cont Trace Enable Flag = $new_enable\n");
+            }
+            return;
+        }
+        elsif (($enable == 2) && ($new_enable == 0))
+        {
+            $on2off = 1;
+            $last = 0;
+        }
+        else
+        {
+            return;
+        }
+    }
+
+    my $trigger = "simGETFAC B0.C0.S0.P0.E8.TPC.FSI.FSI_MAILBOX.FSXCOMP." .
+                  "FSXLOG.LBUS_MAILBOX.Q_GMB2E0.NLC.L2 32";
+    $trigger = `$trigger`;
+    $trigger =~ s/.*\n0xr(.*)\n.*/$1/g;
+    $trigger =~ s/\n//g;
+    if ($dbgMsg)
+    {
+        ::userDisplay("$trigger...\n");
+        my $cycles = `simgetcurrentcycle`;
+        $cycles =~ s/\n//g;
+        $cycles =~ s/.*is ([0-9]*).*/$1/g;
+        ::userDisplay("$cycles\n");
+        $cycles = `date`;
+        ::userDisplay("$cycles");
+    }
+    if (($trigger !~ /[1-9a-fA-F]+/) && ($last == 0))
+    {
+        if ($on2off)
+        {
+            ::write64($symAddr + CONT_TRACE_ENABLE_FLAG_OFFSET, 0);
+            if ($dbgMsg)
+            {
+                $on2off = ::read64($symAddr + CONT_TRACE_ENABLE_FLAG_OFFSET);
+                ::userDisplay("new Cont Trace Enable Flag = $on2off\n");
+            }
+        }
+        if ($dbgMsg)
+        {
+            my $cycles = `date`;
+            ::userDisplay("$cycles");
+        }
+        return;
+    }
+
+    ($symAddr, $symSize) =
                       ::findSymbolAddress("TRACE::g_cont_trace_trigger_info");
     if (not defined $symAddr) { ::userDisplay "Cannot find symbol.\n"; die; }
 
-    my ($fh,$fname) = tempfile();
-    binmode($fh);
+    my @fh;
+    my @fname;
+    ($fh[0],$fname[0]) = tempfile();
+    binmode($fh[0]);
+    ($fh[1],$fname[1]) = tempfile();
+    binmode($fh[1]);
 
     # read the g_cont_trace_trigger_info structure
     my $result = ::readData($symAddr, $symSize);
 
     my $addrOff = 0;
     my $lenOff = $addrOff + DDWORD_SIZE;
+    my $seqOff = $lenOff + WORD_SIZE;
     my $foundBuffer = 0;
+    my @seqNum;
 
     for (my $i = 0; $i < MAX_NUM_CONT_TRACE_BUFFERS; $i++)
     {
         # get the pointer to the continuous trace buffer
         my $buffAddr = substr $result, $addrOff, DDWORD_SIZE;
         $buffAddr= hex (unpack('H*',$buffAddr));
-        my $buffLen = substr $result, $lenOff, DDWORD_SIZE;
+        my $buffLen = substr $result, $lenOff, WORD_SIZE;
         $buffLen= hex (unpack('H*',$buffLen));
-        #::userDisplay("Trigger [".$i."] = $buffAddr\n");
-        #::userDisplay("Length  [".$i."] = $buffLen\n");
+        $seqNum[$i] = substr $result, $seqOff, WORD_SIZE;
+        $seqNum[$i]= hex (unpack('H*',$seqNum[$i]));
+        if ($dbgMsg)
+        {
+            ::userDisplay("Trigger [".$i."] = $buffAddr\n");
+            ::userDisplay("Length  [".$i."] = $buffLen\n");
+            ::userDisplay("SeqNum  [".$i."] = $seqNum[$i]\n");
+        }
 
+        my $fhandle = $fh[$i];
         # If trigger bit is set, or last call and buffer has trace data
         if ((0 != ($buffAddr & TRIG_BIT)) || (($last == 1) && ($buffLen > 1)))
         {
-            $foundBuffer = 1;
+            $foundBuffer |= (1 << $i);
             $buffAddr &= ~TRIG_BIT;
-            print $fh (::readData($buffAddr, $buffLen));
+            print $fhandle (::readData($buffAddr, $buffLen));
 
             # reset trigger bit
             ::write64($symAddr + $addrOff, $buffAddr);
 
             # reset count to 1
-            ::write64($symAddr + $lenOff, 1);
+            ::write32($symAddr + $lenOff, 1);
         }
 
         # increment to next element in g_cont_trace_trigger_info.triggers[]
         $addrOff += (2 * DDWORD_SIZE);
         $lenOff = $addrOff + DDWORD_SIZE;
+        $seqOff = $lenOff + WORD_SIZE;
     }
 
-    if ($foundBuffer)
+    if ($dbgMsg)
     {
-        open TRACE, ($args->{"fsp-trace"}." -s ".
-                    ::getImgPath()."hbotStringFile $fsptrace_options $fname |");
-        while (my $line = <TRACE>)
+        my $cycles = `simgetcurrentcycle`;
+        $cycles =~ s/\n//g;
+        $cycles =~ s/.*is ([0-9]*).*/$1/g;
+        ::userDisplay("$cycles\n");
+    }
+
+    if ($on2off)
+    {
+        ::write64($symAddr + CONT_TRACE_ENABLE_FLAG_OFFSET, 0);
+        if ($dbgMsg)
         {
-            ::userDisplay $line;
+            $on2off = ::read64($symAddr + CONT_TRACE_ENABLE_FLAG_OFFSET);
+            ::userDisplay("new Cont Trace Enable Flag = $on2off\n");
         }
     }
 
+    if (($foundBuffer == 3) && ($seqNum[1] < $seqNum[0]))
+    {
+        my $tmp = $fname[0];
+        $fname[0] =$fname[1];
+        $fname[1] = $tmp;
+    }
+
+    for (my $i = 0; $i < MAX_NUM_CONT_TRACE_BUFFERS; $i++)
+    {
+        if (($foundBuffer & (1 << $i)))
+        {
+            #my $cmd = "cp " . $fname[$i] . " tracMERG." . $seqNum[$i];
+            #system ( $cmd );
+            open TRACE, ($args->{"fsp-trace"}." -s ".
+               ::getImgPath()."hbotStringFile $fsptrace_options $fname[$i] |");
+            while (my $line = <TRACE>)
+            {
+                ::userDisplay $line;
+            }
+        }
+    }
+
+    if ($dbgMsg)
+    {
+        my $cycles = `date`;
+        ::userDisplay("$cycles");
+    }
 }
 
 sub helpInfo
@@ -123,6 +258,8 @@ sub helpInfo
                     "with-file-names" => ["Trace statements will include file name of place the",
                                           "trace was defined."],
                     "last" => ["Shutdown call to offload remaining traces."],
-                   },
+                    "enable-cont-trace=<1|0>" => ["Turn on|off continuous trace"],
+                    "debug" => ["Turn on debug messages"],
+                   }
     );
 }
diff --git a/src/build/debug/simics-debug-framework.py b/src/build/debug/simics-debug-framework.py
index 9453440a6..39a186666 100755
--- a/src/build/debug/simics-debug-framework.py
+++ b/src/build/debug/simics-debug-framework.py
@@ -342,6 +342,8 @@ def magic_instruction_callback(user_arg, cpu, arg):
         SIM_break_simulation( "Simulation stopped. (hap 7007)"  )
 
     if arg == 7055:   # MAGIC_CONTINUOUS_TRACE 
+        # Set execution environment flag to 0
+        writeLongLong(contTraceTrigInfo+32,0)
         # Continuous trace.
         # Residing at tracBinaryInfoAddr is the pointer to the tracBinary buffer
         pTracBinaryBuffer = readLongLong(tracBinaryInfoAddr)
@@ -378,6 +380,13 @@ for line in open('hbicore.syms'):
         words=line.split(",")
         tracBinaryInfoAddr=int(words[1],16)
         break
+# Find the address of the g_cont_trace_trigger_info and save it in
+# contTraceTrigInfo
+for line in open('hbicore.syms'):
+    if "g_cont_trace_trigger_info" in line:
+        words=line.split(",")
+        contTraceTrigInfo=int(words[1],16)
+        break
 
 # Continuous trace: Clear these files.
 rc = os.system( "rm -f tracMERG" )
diff --git a/src/build/vpo/do_sprint b/src/build/vpo/do_sprint
index 1d6690eb6..8e4a2af87 100755..100644
--- a/src/build/vpo/do_sprint
+++ b/src/build/vpo/do_sprint
@@ -176,6 +176,7 @@ sim_clocks=${AUTOVBU_SIMCLOCKS-2000000}
 loopstart=${AUTOVBU_START-0}
 loopmax=`expr $loopstart '+' ${AUTOVBU_LOOPS-2000}`
 lines=${AUTOVBU_PRINTK_LINES-50}
+sample=${AUTOVBU_PRINTK_SAMPLE-30}
 
 # If we requested checkpoints after loops or isteps, force a checkpoint after the hbitest as well
 test "$chkpt_after_loops" = "--chkpt_after_loops" && chkpt_after_hbitest="--chkpt_after_hbitest"
@@ -397,6 +398,7 @@ if [ "$start_after_hbitest" != "--start_after_hbitest" ]; then
 	
 	
 		echo >$printk_tmp1
+		cat /dev/null >printk_out
 	
 		if [ $loopcnt -ne 0 -a -d $AUTOVBU_TEST_DIR/trace_after_loop${loopcnt} ]; then
 			echo
@@ -420,12 +422,16 @@ if [ "$start_after_hbitest" != "--start_after_hbitest" ]; then
 		echo "       export AUTOCHKPT_VERSION=$AUTOCHKPT_VERSION"
 		echo
 	
+                $HB_TOOLS/hb-ContTrace --enable-cont-trace=1 --mute > /dev/null
+
 		while [ ! -f "$testloop_stop" -a $loopcnt -lt $loopmax ]; do
 			loopcnt=`expr $loopcnt + 1`
 	
 			simclock $sim_clocks  -quiet || exit 1
 			cur_cia=`GET_CIA`
 			echo "$loopcnt:	$cur_cia"
+                        $HB_TOOLS/hb-ContTrace --mute > /dev/null
+                        cat hb-ContTrace.output >> tracMERG
 			if [ "$use_hb_trace" = "--use_hb_trace" ]; then
 				p8_ins_stop
 				$HB_TOOLS/hb-trace $test_arg --out $printk_tmp3 2>&1 | egrep -v "^FAPI DBG>:|^FAPI IMP>:|Using deprecated ReturnCode function to assign integer" >$printk_tmp2
@@ -436,13 +442,19 @@ if [ "$start_after_hbitest" != "--start_after_hbitest" ]; then
 			elif [ "$use_dump_l3" = "--use_dump_l3" ]; then
 				DUMP_L3_PRINTK ${addr} ${lines} >$printk_tmp2
 			else
-				p8_ins_stop
-				$HB_TOOLS/hb-printk $test_arg --out $printk_tmp3 2>&1 | egrep -v "^FAPI DBG>:|^FAPI IMP>:|Using deprecated ReturnCode function to assign integer" >$printk_tmp2
-				p8_ins_start
+                           if [ `expr $loopcnt % $sample` -eq 0 ];
+                           then
+                               $HB_TOOLS/hb-printk --mute > /dev/null
+                               diff hb-Printk.output printk_out | sed -e 's/< //g' -e '1d'
+                               mv hb-Printk.output printk_out
+                           fi
+                        fi
+                        if [ -f $printk_tmp2 ];
+                        then
+                                echo >>$printk_tmp2
+                                diff -a $printk_tmp1 $printk_tmp2 | egrep -a "^> " | sed -e 's/[Ee][Rr][Rr][Oo][Rr]/ERR*R/g' -e 's/FAIL/F*IL/g'
+                                mv $printk_tmp2 $printk_tmp1
 			fi
-			echo >>$printk_tmp2
-			diff -a $printk_tmp1 $printk_tmp2 | egrep -a "^> " | sed -e 's/[Ee][Rr][Rr][Oo][Rr]/ERR*R/g' -e 's/FAIL/F*IL/g'
-			mv $printk_tmp2 $printk_tmp1
 	
 			grep 'HypeEmu: Illegal instruction' $printk_tmp1 >/dev/null
 			if [ $? -eq 0 ]; then
@@ -491,6 +503,10 @@ if [ "$start_after_hbitest" != "--start_after_hbitest" ]; then
 				simecho "Renew Tokens: `date`" -quiet
 			fi
 		done
+                $HB_TOOLS/hb-ContTrace --mute > /dev/null
+                cat hb-ContTrace.output >> tracMERG
+                $HB_TOOLS/hb-ContTrace --mute --last > /dev/null
+                cat hb-ContTrace.output >> tracMERG
 		date
 		rm -f $printk_tmp2 $printk_tmp1
 	
diff --git a/src/build/vpo/hb-istep b/src/build/vpo/hb-istep
index 6bbcae7a3..81d96e190 100755
--- a/src/build/vpo/hb-istep
+++ b/src/build/vpo/hb-istep
@@ -132,6 +132,12 @@ my  $g_SeqNum   =   int(rand(64));
 my  $pgmDir  =   `dirname $0`;
 chomp( $pgmDir );
 
+my $hbToolsDir = $ENV{'HB_TOOLS'};
+if ( ! defined( $hbToolsDir) || ( $hbToolsDir eq "" ) )
+{
+    $hbToolsDir = $pgmDir;         ##  Set to tool directory
+}     
+
 my $hbDir = $ENV{'HB_IMGDIR'};
 if ( ! defined( $hbDir) || ( $hbDir eq "" ) )
 {
@@ -487,6 +493,8 @@ sub getSyncStatus( )
         ##  sequence number to see if it has changed.  rinse and repeat.
         ##  Note:  RunClocks will start instructions 
         VBU_Cacheline::RunClocks();
+        system ("$hbToolsDir/hb-ContTrace --mute > /dev/null");
+        system ("cat hb-ContTrace.output >> tracMERG");
 
         ##  Stop instructions, flush L2
         VBU_Cacheline::P8_Ins_Stop();
@@ -742,6 +750,8 @@ sub setMode( $ )
         ##  advance HostBoot code by a certain # of cycles, then check the 
         ##  sequence number to see if it has changed.  rinse and repeat.
         VBU_Cacheline::RunClocks();
+        system ("$hbToolsDir/hb-ContTrace --mute > /dev/null");
+        system ("cat hb-ContTrace.output >> tracMERG");
 
         ##  Stop instructions, flush L2
          VBU_Cacheline::P8_Ins_Stop();