Remove excessive NVDIMM tracing from normal path

Tracing is causing a bottleneck when running NVDIMM
updates.  Should only trace the real failure and add
what is needed for debug into the error log.

Change-Id: Ifa75f85e1129efd9642a3fef0b842fc1f60cd182
Reviewed-on: http://rchgit01.rchland.ibm.com/gerrit1/75667
Tested-by: Jenkins Server <pfd-jenkins+hostboot@us.ibm.com>
Tested-by: FSP CI Jenkins <fsp-CI-jenkins+hostboot@us.ibm.com>
Reviewed-by: Glenn Miles <milesg@ibm.com>
Reviewed-by: Christian R. Geddes <crgeddes@us.ibm.com>
Reviewed-by: Daniel M. Crowell <dcrowell@us.ibm.com>
Reviewed-on: http://rchgit01.rchland.ibm.com/gerrit1/85499
Tested-by: Jenkins OP Build CI <op-jenkins+hostboot@us.ibm.com>
Tested-by: Jenkins OP HW <op-hw-jenkins+hostboot@us.ibm.com>
Reviewed-by: Daniel M Crowell <dcrowell@us.ibm.com>

1 files changed, 52 insertions, 20 deletions

diff --git a/src/usr/isteps/nvdimm/nvdimmdd.C b/src/usr/isteps/nvdimm/nvdimmdd.C
index 875c217d4..f2cee4a9c 100755
--- a/src/usr/isteps/nvdimm/nvdimmdd.C
+++ b/src/usr/isteps/nvdimm/nvdimmdd.C
@@ -498,7 +498,7 @@ errlHndl_t nvdimmRead ( TARGETING::Target * i_target,
         if( err )
         {
             TRACFCOMP(g_trac_nvdimm,
-                    "Failed reading data: original read");
+                    ERR_MRK"nvdimmRead(): Failed reading data: original read");
             break;
         }
 
@@ -562,12 +562,10 @@ errlHndl_t nvdimmReadData( TARGETING::Target * i_target,
 
                 if( l_err )
                 {
-                    TRACFCOMP(g_trac_nvdimm,
-                              ERR_MRK"nvdimmReadData(): I2C Read-Offset failed on "
-                              "%d/%d/0x%X, aS=%d",
-                              i_i2cInfo.port, i_i2cInfo.engine,
-                              i_i2cInfo.devAddr,
-                              i_byteAddressSize);
+                    TRACFCOMP(g_trac_nvdimm, ERR_MRK"nvdimmReadData(): "
+                        "I2C Read-Offset failed on %d/%d/0x%X, aS=%d",
+                        i_i2cInfo.port, i_i2cInfo.engine,
+                        i_i2cInfo.devAddr, i_byteAddressSize);
 
                     // Printing mux info separately, if combined, nothing is displayed
                     char* l_muxPath = i_i2cInfo.i2cMuxPath.toString();
@@ -600,7 +598,7 @@ errlHndl_t nvdimmReadData( TARGETING::Target * i_target,
 
                 if( l_err )
                 {
-                    TRACFCOMP(g_trac_nvdimm,
+                    TRACUCOMP(g_trac_nvdimm,
                               ERR_MRK"nvdimmReadData(): I2C Read failed on "
                               "%d/%d/0x%0X",
                               i_i2cInfo.port, i_i2cInfo.engine,
@@ -608,7 +606,7 @@ errlHndl_t nvdimmReadData( TARGETING::Target * i_target,
 
                     // Printing mux info separately, if combined, nothing is displayed
                     char* l_muxPath = i_i2cInfo.i2cMuxPath.toString();
-                    TRACFCOMP(g_trac_nvdimm, ERR_MRK"nvdimmReadData(): "
+                    TRACUCOMP(g_trac_nvdimm, ERR_MRK"nvdimmReadData(): "
                               "muxSelector=0x%X, muxPath=%s",
                               i_i2cInfo.i2cMuxBusSelector,
                               l_muxPath);
@@ -647,9 +645,9 @@ errlHndl_t nvdimmReadData( TARGETING::Target * i_target,
                     // Save original retryable error
                     err_retryable = l_err;
 
-                    TRACFCOMP( g_trac_nvdimm, ERR_MRK"nvdimmReadData(): "
+                    TRACUCOMP( g_trac_nvdimm, ERR_MRK"nvdimmReadData(): "
                                "Retryable Error rc=0x%X, eid=0x%X, tgt=0x%X, "
-                               "retry/MAX=%d/%d. Save error and retry",
+                               "retry=%d. Save error and retry",
                                err_retryable->reasonCode(),
                                err_retryable->eid(),
                                TARGETING::get_huid(i_target),
@@ -686,13 +684,29 @@ errlHndl_t nvdimmReadData( TARGETING::Target * i_target,
                                                .addToLog(err_retryable);
 
                 errlCommit(err_retryable, NVDIMM_COMP_ID);
+
+                // Add trace of what operation failed for returned error
+                TRACFCOMP(g_trac_nvdimm,
+                          ERR_MRK"nvdimmReadData(): I2C Read failed on "
+                          "%d/%d/0x%0X",
+                          i_i2cInfo.port, i_i2cInfo.engine, i_i2cInfo.devAddr );
+
+                // Printing mux info separately, if combined, nothing is displayed
+                char* l_muxPath = i_i2cInfo.i2cMuxPath.toString();
+                TRACFCOMP(g_trac_nvdimm, ERR_MRK"nvdimmReadData(): "
+                          "muxSelector=0x%X, muxPath=%s",
+                          i_i2cInfo.i2cMuxBusSelector,
+                          l_muxPath);
+                free(l_muxPath);
+                l_muxPath = nullptr;
             }
             else
             {
                 // Since we eventually succeeded, delete original retryable error
-                TRACFCOMP(g_trac_nvdimm, "nvdimmReadData(): Op successful, "
-                          "deleting saved retryable err eid=0x%X, plid=0x%X",
-                          err_retryable->eid(), err_retryable->plid());
+                TRACUCOMP(g_trac_nvdimm, "nvdimmReadData(): Op successful, "
+                          "after %d retries. Deleting saved retryable err eid="
+                          "0x%X, plid=0x%X",
+                          retry, err_retryable->eid(), err_retryable->plid());
 
                 delete err_retryable;
                 err_retryable = nullptr;
@@ -890,7 +904,7 @@ errlHndl_t nvdimmWrite ( TARGETING::Target * i_target,
         io_buflen = total_bytes_written;
 
 
-        TRACSCOMP( g_trac_nvdimmr,
+        TRACUCOMP( g_trac_nvdimmr,
                    "NVDIMM WRITE END   : Offset %.2X : Len %d",
                    i_i2cInfo.offset, io_buflen );
     } while( 0 );
@@ -1000,7 +1014,7 @@ errlHndl_t nvdimmWriteData( TARGETING::Target * i_target,
              }
              else // Handle retryable error
              {
-                 TRACFCOMP(g_trac_nvdimm, ERR_MRK"nvdimmWriteData(): I2C "
+                 TRACUCOMP(g_trac_nvdimm, ERR_MRK"nvdimmWriteData(): I2C "
                            "Write retryable fail %d/%d/0x%X, "
                            "ldl=%d, offset=0x%X, aS=%d, writePageSize = %x",
                            i_i2cInfo.port, i_i2cInfo.engine,
@@ -1010,7 +1024,7 @@ errlHndl_t nvdimmWriteData( TARGETING::Target * i_target,
 
                  // Printing mux info separately, if combined, nothing is displayed
                  char* l_muxPath = i_i2cInfo.i2cMuxPath.toString();
-                 TRACFCOMP(g_trac_nvdimm, ERR_MRK"nvdimmWriteData(): "
+                 TRACUCOMP(g_trac_nvdimm, ERR_MRK"nvdimmWriteData(): "
                            "muxSelector=0x%X, muxPath=%s",
                            i_i2cInfo.i2cMuxBusSelector,
                            l_muxPath);
@@ -1026,7 +1040,7 @@ errlHndl_t nvdimmWriteData( TARGETING::Target * i_target,
                          // Save original retryable error
                          err_retryable = err;
 
-                         TRACFCOMP( g_trac_nvdimm, ERR_MRK"nvdimmWriteData(): "
+                         TRACUCOMP( g_trac_nvdimm, ERR_MRK"nvdimmWriteData(): "
                                     "Error rc=0x%X, eid=0x%X plid=0x%X, "
                                     "tgt=0x%X, retry/MAX=%d/%d. Save error "
                                     "and retry",
@@ -1041,7 +1055,7 @@ errlHndl_t nvdimmWriteData( TARGETING::Target * i_target,
                      else
                      {
                          // Add data to original retryable error
-                         TRACFCOMP( g_trac_nvdimm, ERR_MRK"nvdimmWriteData(): "
+                         TRACUCOMP( g_trac_nvdimm, ERR_MRK"nvdimmWriteData(): "
                                     "Another Retryable Error rc=0x%X, eid=0x%X "
                                     "plid=0x%X, tgt=0x%X, retry/MAX=%d/%d. "
                                     "Delete error and retry",
@@ -1086,6 +1100,24 @@ errlHndl_t nvdimmWriteData( TARGETING::Target * i_target,
          {
              if (err)
              {
+                 // Trace failure write parameters
+                 TRACFCOMP(g_trac_nvdimm, ERR_MRK"nvdimmWriteData(): I2C "
+                           "Write retryable fail %d/%d/0x%X, "
+                           "ldl=%d, offset=0x%X, aS=%d, writePageSize = %x",
+                           i_i2cInfo.port, i_i2cInfo.engine,
+                           i_i2cInfo.devAddr, i_dataLen,
+                           i_i2cInfo.offset, i_i2cInfo.addrSize,
+                           i_i2cInfo.writePageSize);
+
+                 // Printing mux info separately, if combined, nothing is displayed
+                 char* l_muxPath = i_i2cInfo.i2cMuxPath.toString();
+                 TRACFCOMP(g_trac_nvdimm, ERR_MRK"nvdimmWriteData(): "
+                           "muxSelector=0x%X, muxPath=%s",
+                           i_i2cInfo.i2cMuxBusSelector,
+                           l_muxPath);
+                 free(l_muxPath);
+                 l_muxPath = nullptr;
+
                  // commit original retryable error with new err PLID
                  err_retryable->plid(err->plid());
                  TRACFCOMP(g_trac_nvdimm, "nvdimmWriteData(): Committing saved "
@@ -1101,7 +1133,7 @@ errlHndl_t nvdimmWriteData( TARGETING::Target * i_target,
              else
              {
                  // Since we eventually succeeded, delete original retryable error
-                 TRACFCOMP(g_trac_nvdimm, "nvdimmWriteData(): Op successful, "
+                 TRACUCOMP(g_trac_nvdimm, "nvdimmWriteData(): Op successful, "
                            "deleting saved retryable err eid=0x%X, plid=0x%X",
                            err_retryable->eid(), err_retryable->plid());