Issue #1785 Adding performance logging for bufrua, grib, obs, radar,

redbook, sfcobs, and satellite.

Amend: Made decoder performance logging consistent.  Cleaned up other logging.

Change-Id: I1f404583240a9427cfa3dbb82f9ba3f760b3a8d4

Former-commit-id: 871b2ceb2a6745369c1dc6e88d711e5e3a13cc37

edexOsgi/com.raytheon.edex.ingestsrv/META-INF/MANIFEST.MF

@@ -11,5 +11,6 @@ Require-Bundle: com.raytheon.edex.common,
 Export-Package: com.raytheon.edex.services
 Bundle-RequiredExecutionEnvironment: JavaSE-1.6
 Import-Package: com.raytheon.uf.common.message.response,
+ com.raytheon.uf.common.status,
  com.raytheon.uf.edex.core,
  com.raytheon.uf.edex.database.plugin

edexOsgi/com.raytheon.edex.ingestsrv/src/com/raytheon/edex/services/IndexSrv.java

@@ -25,6 +25,10 @@ import org.apache.commons.logging.LogFactory;
 
 import com.raytheon.uf.common.dataplugin.PluginDataObject;
 import com.raytheon.uf.common.dataplugin.PluginException;
+import com.raytheon.uf.common.status.IPerformanceStatusHandler;
+import com.raytheon.uf.common.status.PerformanceStatus;
+import com.raytheon.uf.common.time.util.ITimer;
+import com.raytheon.uf.common.time.util.TimeUtil;
 import com.raytheon.uf.edex.core.EDEXUtil;
 import com.raytheon.uf.edex.database.plugin.PluginDao;
 import com.raytheon.uf.edex.database.plugin.PluginFactory;
@@ -40,6 +44,7 @@ import com.raytheon.uf.edex.database.plugin.PluginFactory;
  * 20080408     1039       jkorman     Added traceId for tracing data.
  * Nov 11, 2008            chammack    Refactored for Camel
  * 02/06/09     1990       bphillip    Refactored to use plugin daos
+ * Mar 19, 2013 1785       bgonzale    Added performance status to indexOne and index.
  * </pre>
  * 
  * @author Frank Griffith
@@ -53,6 +58,9 @@ public class IndexSrv {
 
     private Log logger = LogFactory.getLog(getClass());
 
+    private final IPerformanceStatusHandler perfLog = PerformanceStatus
+            .getHandler("DataBase:");
+
     /** The default constructor */
     public IndexSrv() {
     }
@@ -73,9 +81,14 @@ public class IndexSrv {
      */
     public PluginDataObject indexOne(PluginDataObject record)
             throws PluginException {
-        PluginDao dao = PluginFactory.getInstance().getPluginDao(
+        String pluginName = record.getPluginName();
-                record.getPluginName());
+        PluginDao dao = PluginFactory.getInstance().getPluginDao(pluginName);
+        ITimer timer = TimeUtil.getTimer();
+        timer.start();
         dao.persistToDatabase(record);
+        timer.stop();
+        perfLog.logDuration(pluginName + ": Saved a record: Time to Save",
+                timer.getElapsedTime());
         if (logger.isDebugEnabled()) {
             logger.debug("Persisted: " + record + " to database");
         }
@@ -100,10 +113,16 @@ public class IndexSrv {
         }
 
         try {
-            PluginDao dao = PluginFactory.getInstance().getPluginDao(
+            String pluginName = record[0].getPluginName();
-                    record[0].getPluginName());
+            PluginDao dao = PluginFactory.getInstance().getPluginDao(pluginName);
             EDEXUtil.checkPersistenceTimes(record);
+            ITimer timer = TimeUtil.getTimer();
+            timer.start();
             PluginDataObject[] persisted = dao.persistToDatabase(record);
+            timer.stop();
+            perfLog.logDuration(pluginName + ": Saved " + persisted.length
+                    + " record(s): Time to Save",
+                    timer.getElapsedTime());
             if (logger.isDebugEnabled()) {
                 for (PluginDataObject rec : record) {
                     logger.debug("Persisted: " + rec + " to database");

edexOsgi/com.raytheon.edex.ingestsrv/src/com/raytheon/edex/services/PersistSrv.java

@@ -33,6 +33,10 @@ import com.raytheon.uf.common.datastorage.DuplicateRecordStorageException;
 import com.raytheon.uf.common.datastorage.StorageException;
 import com.raytheon.uf.common.datastorage.StorageStatus;
 import com.raytheon.uf.common.datastorage.records.IDataRecord;
+import com.raytheon.uf.common.status.IPerformanceStatusHandler;
+import com.raytheon.uf.common.status.PerformanceStatus;
+import com.raytheon.uf.common.time.util.ITimer;
+import com.raytheon.uf.common.time.util.TimeUtil;
 import com.raytheon.uf.edex.core.EDEXUtil;
 import com.raytheon.uf.edex.database.plugin.PluginDao;
 import com.raytheon.uf.edex.database.plugin.PluginFactory;
@@ -47,6 +51,7 @@ import com.raytheon.uf.edex.database.plugin.PluginFactory;
  * Oct 31, 2008            chammack    Initial creation
  * 02/06/09     1990       bphillip    Refactored to use plugin specific daos
  * Nov 02, 2012 1302       djohnson    Remove unused method, fix formatting.
+ * Mar 19, 2013 1785       bgonzale    Added performance status to persist.
  * </pre>
  * 
  * @author chammack
@@ -62,6 +67,9 @@ public class PersistSrv {
         return instance;
     }
 
+    private final IPerformanceStatusHandler perfLog = PerformanceStatus
+            .getHandler("HDF5:");
+
     private PersistSrv() {
     }
 
@@ -75,9 +83,16 @@ public class PersistSrv {
         EDEXUtil.checkPersistenceTimes(pdo);
 
         try {
-            PluginDao dao = PluginFactory.getInstance().getPluginDao(
+            String pluginName = pdo[0].getPluginName();
-                    pdo[0].getPluginName());
+            PluginDao dao = PluginFactory.getInstance()
+                    .getPluginDao(pluginName);
+            ITimer timer = TimeUtil.getTimer();
+            timer.start();
             StorageStatus ss = dao.persistToHDF5(pdo);
+            timer.stop();
+            perfLog.logDuration(pluginName + ": Persisted " + pdo.length
+                    + " record(s): Time to Persist",
+                    timer.getElapsedTime());
             StorageException[] se = ss.getExceptions();
             pdoList.addAll(Arrays.asList(pdo));
             if (se != null) {

edexOsgi/com.raytheon.edex.plugin.bufrua/src/com/raytheon/edex/plugin/bufrua/BufrUADecoder.java

@@ -38,6 +38,10 @@ import com.raytheon.uf.common.pointdata.PointDataDescription;
 import com.raytheon.uf.common.pointdata.PointDataView;
 import com.raytheon.uf.common.pointdata.spatial.ObStation;
 import com.raytheon.uf.common.pointdata.spatial.SurfaceObsLocation;
+import com.raytheon.uf.common.status.IPerformanceStatusHandler;
+import com.raytheon.uf.common.status.PerformanceStatus;
+import com.raytheon.uf.common.time.util.ITimer;
+import com.raytheon.uf.common.time.util.TimeUtil;
 import com.raytheon.uf.edex.bufrtools.AbstractBUFRDecoder;
 import com.raytheon.uf.edex.database.DataAccessLayerException;
 import com.raytheon.uf.edex.decodertools.bufr.BUFRDataDocument;
@@ -72,6 +76,8 @@ import com.raytheon.uf.edex.wmo.message.WMOHeader;
  *                                     in findDuplicate.
  * 20080408           1039 jkorman     Added traceId for tracing data.
  * 11/25/08          #1684 chammack    Camel Refactor
+ * Mar 19, 2013 1785       bgonzale    Added performance status handler and added status
+ *                                     to decodeData.
  * </pre>
  * 
  * @author jkorman
@@ -86,6 +92,9 @@ public class BufrUADecoder extends AbstractBUFRDecoder {
 
     private BUFRUAAdapterFactory adapterFactory;
 
+    private final IPerformanceStatusHandler perfLog = PerformanceStatus
+            .getHandler("BufrUA:");
+
     /**
      * 
      * @param name
@@ -127,7 +136,9 @@ public class BufrUADecoder extends AbstractBUFRDecoder {
             Iterator<BUFRDataDocument> iterator = document.iterator();
 
             String cor = isCor(wmoHeader);
+            ITimer timer = TimeUtil.getTimer();
 
+            timer.start();
             while (iterator.hasNext()) {
 
                 logger.debug("Decoding one BUFRDataDocument");
@@ -151,6 +162,8 @@ public class BufrUADecoder extends AbstractBUFRDecoder {
                     }
                 }
             }
+            timer.stop();
+            perfLog.logDuration("Time to Decode", timer.getElapsedTime());
         }
         return decodedData;
     }

edexOsgi/com.raytheon.edex.plugin.grib/src/com/raytheon/edex/plugin/grib/GribDecoder.java

@@ -33,9 +33,13 @@ import com.raytheon.edex.plugin.grib.exception.GribException;
 import com.raytheon.uf.common.dataplugin.PluginDataObject;
 import com.raytheon.uf.common.dataplugin.PluginException;
 import com.raytheon.uf.common.dataplugin.grid.GridRecord;
+import com.raytheon.uf.common.status.IPerformanceStatusHandler;
 import com.raytheon.uf.common.status.IUFStatusHandler;
+import com.raytheon.uf.common.status.PerformanceStatus;
 import com.raytheon.uf.common.status.UFStatus;
 import com.raytheon.uf.common.status.UFStatus.Priority;
+import com.raytheon.uf.common.time.util.ITimer;
+import com.raytheon.uf.common.time.util.TimeUtil;
 import com.raytheon.uf.edex.python.decoder.PythonDecoder;
 
 /**
@@ -47,6 +51,8 @@ import com.raytheon.uf.edex.python.decoder.PythonDecoder;
  * ------------ ---------- ----------- --------------------------
  * 3/12/10      4758       bphillip     Initial creation
  * 02/12/2013   1615       bgonzale     public decode method to a Processor exchange method.
+ * Mar 19, 2013 1785       bgonzale     Added performance status handler and added status
+ *                                      to process.
  * </pre>
  * 
  * @author njensen
@@ -57,6 +63,11 @@ public class GribDecoder implements Processor {
     private static final transient IUFStatusHandler statusHandler = UFStatus
             .getHandler(GribDecoder.class);
 
+    private static final String[] DecoderNames = { "Grib1", "Grib2" };
+
+    private final IPerformanceStatusHandler perfLog = PerformanceStatus
+            .getHandler("");
+
     /**
      * @see org.apache.camel.Processor.process(Exchange)
      */
@@ -72,16 +83,22 @@ public class GribDecoder implements Processor {
         int edition = 0;
         GridRecord[] records = null;
         try {
+            ITimer timer = TimeUtil.getTimer();
+            String decoderName;
+
             raf = new RandomAccessFile(file.getAbsolutePath(), "r");
             raf.order(RandomAccessFile.BIG_ENDIAN);
             edition = GribChecker.getEdition(raf);
             exchange.getIn().setHeader(DATA_TYPE, GRIB + edition);
 
+            timer.start();
             switch (edition) {
             case 1:
+                decoderName = DecoderNames[0];
                 records = new Grib1Decoder().decode(file.getAbsolutePath());
                 break;
             case 2:
+                decoderName = DecoderNames[1];
                 records = decodeGrib2(file);
                 break;
             default:
@@ -108,6 +125,9 @@ public class GribDecoder implements Processor {
                     record.constructDataURI();
                 }
             }
+            timer.stop();
+            perfLog.logDuration(decoderName + ": Time to Decode",
+                    timer.getElapsedTime());
         } catch (Exception e) {
             statusHandler.handle(Priority.ERROR, "Failed to decode file: ["
                     + file.getAbsolutePath() + "]", e);

edexOsgi/com.raytheon.edex.plugin.obs/src/com/raytheon/edex/plugin/obs/ObsDecoder.java

@@ -26,9 +26,9 @@ package com.raytheon.edex.plugin.obs;
  * 
  * <pre>
  *                     
- * OFTWARE HISTORY
+ * SOFTWARE HISTORY
  * 
- * ate          Ticket#     Engineer    Description
+ * Date          Ticket#     Engineer    Description
  * -----------  ----------  ----------- --------------------------
  * 4/27/07      199         bphillip    Initial creation
  * 07/31/2007          411  jkorman     Added addition logging
@@ -37,6 +37,8 @@ package com.raytheon.edex.plugin.obs;
  * 20080314            995  jkorman     Changed setDecoderStrategy to check for
  *                                      empty data.
  * 20080408           1039  jkorman     Added traceId for tracing data.  
+ * Mar 19, 2013       1785  bgonzale    Added performance status handler and added
+ *                                      status to decode.
  * </pre>
  * 
  * @author bphillip
@@ -50,6 +52,10 @@ import com.raytheon.edex.exception.DecoderException;
 import com.raytheon.edex.plugin.AbstractDecoder;
 import com.raytheon.edex.plugin.obs.metar.MetarDecoder;
 import com.raytheon.uf.common.dataplugin.PluginDataObject;
+import com.raytheon.uf.common.status.IPerformanceStatusHandler;
+import com.raytheon.uf.common.status.PerformanceStatus;
+import com.raytheon.uf.common.time.util.ITimer;
+import com.raytheon.uf.common.time.util.TimeUtil;
 import com.raytheon.uf.edex.wmo.message.WMOHeader;
 
 public class ObsDecoder extends AbstractDecoder {
@@ -58,6 +64,9 @@ public class ObsDecoder extends AbstractDecoder {
 
     private final String PLUGIN_NAME;
 
+    private final IPerformanceStatusHandler perfLog = PerformanceStatus
+            .getHandler("Obs:");
+
     private String traceId = null;
 
     /**
@@ -84,6 +93,8 @@ public class ObsDecoder extends AbstractDecoder {
         try {
 
             if (decoder != null) {
+                ITimer timer = TimeUtil.getTimer();
+                timer.start();
                 reports = decoder.decode(data, headers);
 
                 if (reports != null) {
@@ -91,6 +102,8 @@ public class ObsDecoder extends AbstractDecoder {
                         report.setTraceId(traceId);
                     }
                 }
+                timer.stop();
+                perfLog.logDuration("Time to Decode", timer.getElapsedTime());
             }
         } catch (Exception e) {
             logger.error(traceId + "- Error in ObsDecoder", e);

edexOsgi/com.raytheon.edex.plugin.radar/src/com/raytheon/edex/plugin/radar/RadarDecoder.java

@@ -65,10 +65,14 @@ import com.raytheon.uf.common.dataplugin.radar.util.TiltAngleBin;
 import com.raytheon.uf.common.localization.IPathManager;
 import com.raytheon.uf.common.localization.LocalizationContext;
 import com.raytheon.uf.common.localization.PathManagerFactory;
+import com.raytheon.uf.common.status.IPerformanceStatusHandler;
 import com.raytheon.uf.common.status.IUFStatusHandler;
+import com.raytheon.uf.common.status.PerformanceStatus;
 import com.raytheon.uf.common.status.UFStatus;
 import com.raytheon.uf.common.status.UFStatus.Priority;
 import com.raytheon.uf.common.time.DataTime;
+import com.raytheon.uf.common.time.util.ITimer;
+import com.raytheon.uf.common.time.util.TimeUtil;
 import com.raytheon.uf.edex.core.EDEXUtil;
 import com.raytheon.uf.edex.database.cluster.ClusterLockUtils;
 import com.raytheon.uf.edex.database.cluster.ClusterTask;
@@ -87,7 +91,8 @@ import com.raytheon.uf.edex.wmo.message.WMOHeader;
  * Dec 17, 2007 600         bphillip    Added dao pool usage
  * Dec 03, 2010 2235        cjeanbap    EDEXUtility.sendMessageAlertViz() signature changed.
  * Mar 19, 2013 1804        bsteffen    Optimize decoder performance.
- * 
+ * Mar 19, 2013 1785        bgonzale    Added performance status handler and added status
+ *                                      to decode.
  * </pre>
  * 
  * @author bphillip
@@ -131,6 +136,9 @@ public class RadarDecoder extends AbstractDecoder {
 
     private final String RADAR = "RADAR";
 
+    private final IPerformanceStatusHandler perfLog = PerformanceStatus
+            .getHandler("Radar:");
+
     public RadarDecoder() throws DecoderException {
 
         String dir = "";
@@ -170,6 +178,9 @@ public class RadarDecoder extends AbstractDecoder {
         // decode the product
         String arch = new String(messageData, 0, 4);
         try {
+            ITimer timer = TimeUtil.getTimer();
+
+            timer.start();
             // for level2 data, this does not happen very often
             if (LEVEL_TWO_IDENTS.contains(arch)) {
                 decodeLevelTwoData(messageData, recordList);
@@ -421,8 +432,11 @@ public class RadarDecoder extends AbstractDecoder {
                     logger.error(e);
                     return new PluginDataObject[0];
                 }
-                recordList.add(record);
 
+                timer.stop();
+                perfLog.logDuration("Time to Decode", timer.getElapsedTime());
+
+                recordList.add(record);
             }
         } catch (Exception e) {
             theHandler.handle(Priority.ERROR, "Couldn't properly handle "

edexOsgi/com.raytheon.edex.plugin.redbook/src/com/raytheon/edex/plugin/redbook/RedbookDecoder.java

@@ -30,6 +30,10 @@ import com.raytheon.edex.plugin.redbook.dao.RedbookDao;
 import com.raytheon.edex.plugin.redbook.decoder.RedbookParser;
 import com.raytheon.uf.common.dataplugin.PluginDataObject;
 import com.raytheon.uf.common.dataplugin.PluginException;
+import com.raytheon.uf.common.status.IPerformanceStatusHandler;
+import com.raytheon.uf.common.status.PerformanceStatus;
+import com.raytheon.uf.common.time.util.ITimer;
+import com.raytheon.uf.common.time.util.TimeUtil;
 import com.raytheon.uf.edex.database.plugin.PluginFactory;
 import com.raytheon.uf.edex.wmo.message.WMOHeader;
 
@@ -49,6 +53,8 @@ import com.raytheon.uf.edex.wmo.message.WMOHeader;
  * 20090327           2019 jkorman     Added code to check for non-redbook data.
  * 20120524           #647 dgilling    Update persistence time in 
  *                                     createdBackDatedVersionIfNeeded.
+ * Mar 19, 2013       1785 bgonzale    Added performance status handler and added
+ *                                     status to decode.
  * </pre>
  * 
  * @author jkorman
@@ -79,13 +85,16 @@ public class RedbookDecoder extends AbstractDecoder {
 
     private static final String GIF87A_SIG = "GIF87a";
 
-    private static final String GIF89A_SIG = "GIF89a";
+    // This sig is currently not used.
+    // private static final String GIF89A_SIG = "GIF89a";
 
     private static final String DIFAX_SIG = "DFAX";
 
     // Name of the plugin controlling this decoder.
     private final String PLUGIN_NAME;
 
+    private final IPerformanceStatusHandler perfLog = PerformanceStatus
+            .getHandler("Redbook:");
     private String traceId = null;
 
     /**
@@ -117,6 +126,9 @@ public class RedbookDecoder extends AbstractDecoder {
 
             WMOHeader wmoHeader = new WMOHeader(rawMessage, headers);
             if (wmoHeader.isValid()) {
+                ITimer timer = TimeUtil.getTimer();
+                timer.start();
+
                 int start = wmoHeader.getMessageDataStart();
 
                 int len = rawMessage.length - start;
@@ -145,6 +157,8 @@ public class RedbookDecoder extends AbstractDecoder {
                                 e);
                     }
                 }
+                timer.stop();
+                perfLog.logDuration("Time to Decode", timer.getElapsedTime());
             } else {
                 logger.error(traceId + "- No valid WMO header found in data.");
             }

edexOsgi/com.raytheon.edex.plugin.satellite/src/com/raytheon/edex/plugin/satellite/SatelliteDecoder.java

@@ -44,7 +44,11 @@ import com.raytheon.uf.common.dataplugin.satellite.SatMapCoverage;
 import com.raytheon.uf.common.dataplugin.satellite.SatelliteMessageData;
 import com.raytheon.uf.common.dataplugin.satellite.SatelliteRecord;
 import com.raytheon.uf.common.datastorage.records.IDataRecord;
+import com.raytheon.uf.common.status.IPerformanceStatusHandler;
+import com.raytheon.uf.common.status.PerformanceStatus;
 import com.raytheon.uf.common.time.DataTime;
+import com.raytheon.uf.common.time.util.ITimer;
+import com.raytheon.uf.common.time.util.TimeUtil;
 import com.raytheon.uf.edex.decodertools.time.TimeTools;
 import com.raytheon.uf.edex.wmo.message.WMOHeader;
 
@@ -53,7 +57,7 @@ import com.raytheon.uf.edex.wmo.message.WMOHeader;
  * 
  * <pre>
  * 
- * OFTWARE HISTORY
+ * SOFTWARE HISTORY
  * 
  * Date         Ticket#     Engineer    Description
  * -----------  ----------  ----------- --------------------------
@@ -74,6 +78,9 @@ import com.raytheon.uf.edex.wmo.message.WMOHeader;
  * 06/27/2012    798        jkorman     Using SatelliteMessageData to "carry" the decoded image.
  * 01/03/2013  15294        D. Friedman Start with File instead of byte[] to
  *                                      reduce memory usage.
+ * Mar 19, 2013 1785        bgonzale    Added performance status handler and added status
+ *                                      to decode.
+ * 
  * </pre>
  * 
  * @author bphillip
@@ -91,6 +98,9 @@ public class SatelliteDecoder extends AbstractDecoder {
 
     private static final int INITIAL_READ = GINI_HEADER_SIZE + 128;
 
+    private final IPerformanceStatusHandler perfLog = PerformanceStatus
+            .getHandler("Satellite:");
+
     private SatelliteDao dao;
 
     public PluginDataObject[] decode(File file) throws Exception {
@@ -103,6 +113,8 @@ public class SatelliteDecoder extends AbstractDecoder {
             return new PluginDataObject[0];
         RandomAccessFile f = new RandomAccessFile(file, "r");
         try {
+            ITimer timer = TimeUtil.getTimer();
+            timer.start();
             // Read in enough data to cover the WMO heading and GINI header.
             ByteBuffer byteBuffer = ByteBuffer.allocate(INITIAL_READ);
             f.getChannel().read(byteBuffer);
@@ -427,6 +439,8 @@ public class SatelliteDecoder extends AbstractDecoder {
                     record.setMessageData(dataRec);
                 }
             }
+            timer.stop();
+            perfLog.logDuration("Time to Decode", timer.getElapsedTime());
         } finally {
             try {
                 f.close();

edexOsgi/com.raytheon.edex.plugin.sfcobs/META-INF/MANIFEST.MF

@@ -17,4 +17,5 @@ Import-Package: com.raytheon.uf.common.dataplugin.sfcobs,
  com.raytheon.uf.common.dataplugin.sfcobs.dao,
  com.raytheon.uf.common.pointdata,
  com.raytheon.uf.common.pointdata.spatial,
- com.raytheon.uf.edex.pointdata
+ com.raytheon.uf.edex.pointdata,
+ com.raytheon.uf.common.status

edexOsgi/com.raytheon.edex.plugin.sfcobs/src/com/raytheon/edex/plugin/sfcobs/SfcObsDecoder.java

@@ -35,6 +35,10 @@ import com.raytheon.edex.plugin.sfcobs.decoder.SfcObsDecoderFactory;
 import com.raytheon.uf.common.dataplugin.PluginDataObject;
 import com.raytheon.uf.common.dataplugin.PluginException;
 import com.raytheon.uf.common.dataplugin.sfcobs.ObsCommon;
+import com.raytheon.uf.common.status.IPerformanceStatusHandler;
+import com.raytheon.uf.common.status.PerformanceStatus;
+import com.raytheon.uf.common.time.util.ITimer;
+import com.raytheon.uf.common.time.util.TimeUtil;
 import com.raytheon.uf.edex.decodertools.core.DecoderTools;
 import com.raytheon.uf.edex.decodertools.time.TimeTools;
 import com.raytheon.uf.edex.wmo.message.WMOHeader;
@@ -66,6 +70,8 @@ import com.raytheon.uf.edex.wmo.message.WMOHeader;
  *                                     time in the future.
  * 20080215     887        jkorman     Added null checks in decode.
  * 20080218     887        jkorman     Reverse null checks in findDuplicate.
+ * Mar 19, 2013 1785       bgonzale    Added performance status handler and added status
+ *                                     to decode.
  * </pre>
  * 
  * @author jkorman
@@ -77,6 +83,9 @@ public class SfcObsDecoder extends AbstractDecoder {
     // Name of the plugin controlling this decoder.
     public static final String PLUGIN_NAME = "sfcobs";
 
+    private final IPerformanceStatusHandler perfLog = PerformanceStatus
+            .getHandler("SfcObs:");
+
     /** The logger */
     private Log logger = LogFactory.getLog(getClass());
 
@@ -124,6 +133,9 @@ public class SfcObsDecoder extends AbstractDecoder {
         SfcObsSeparator separator = SfcObsSeparator.separate(data, headers);
         List<PluginDataObject> retVal = new ArrayList<PluginDataObject>();
         HashMap<String, Boolean> obsMap = new HashMap<String, Boolean>();
+        ITimer timer = TimeUtil.getTimer();
+
+        timer.start();
         while (separator.hasNext()) {
             SfcObsDecoderInput input = separator.next();
             PluginDataObject report = null;
@@ -169,7 +181,8 @@ public class SfcObsDecoder extends AbstractDecoder {
                 }
             }
         }
-
+        timer.stop();
+        perfLog.logDuration("Time to Decode", timer.getElapsedTime());
         return retVal.toArray(new PluginDataObject[retVal.size()]);
     }