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: 8c309840a3 [formerly f7debfc55f [formerly cd39fcf122] [formerly 8c309840a3 [formerly 871b2ceb2a6745369c1dc6e88d711e5e3a13cc37]]]
Former-commit-id: f7debfc55f [formerly cd39fcf122]
Former-commit-id: f7debfc55f
Former-commit-id: 237dc5ea14
This commit is contained in:
Brad Gonzales 2013-03-20 19:00:25 -05:00
parent 3e227a7ee8
commit 157f1ae524
11 changed files with 163 additions and 26 deletions

View file

@ -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

View file

@ -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;
@ -36,10 +40,11 @@ import com.raytheon.uf.edex.database.plugin.PluginFactory;
* SOFTWARE HISTORY
* Date Ticket# Engineer Description
* ------------ ---------- ----------- --------------------------
* fgriffit Initial Creation.
* 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
* fgriffit Initial Creation.
* 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(
record.getPluginName());
String pluginName = 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(
record[0].getPluginName());
String pluginName = 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");

View file

@ -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;
@ -44,9 +48,10 @@ import com.raytheon.uf.edex.database.plugin.PluginFactory;
* SOFTWARE HISTORY
* Date Ticket# Engineer Description
* ------------ ---------- ----------- --------------------------
* Oct 31, 2008 chammack Initial creation
* 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(
pdo[0].getPluginName());
String pluginName = 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) {

View file

@ -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;
}

View file

@ -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);

View file

@ -26,17 +26,19 @@ package com.raytheon.edex.plugin.obs;
*
* <pre>
*
* OFTWARE HISTORY
*
* ate Ticket# Engineer Description
* SOFTWARE HISTORY
*
* Date Ticket# Engineer Description
* ----------- ---------- ----------- --------------------------
* 4/27/07 199 bphillip Initial creation
* 4/27/07 199 bphillip Initial creation
* 07/31/2007 411 jkorman Added addition logging
* 08/10/2007 379 jkorman Added disposal behavior.
* 20071217 453 jkorman Added code to check for duplicate obs.
* 20080314 995 jkorman Changed setDecoderStrategy to check for
* empty data.
* 20080408 1039 jkorman Added traceId for tracing 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);

View file

@ -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 "

View file

@ -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.");
}

View file

@ -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,15 +57,15 @@ import com.raytheon.uf.edex.wmo.message.WMOHeader;
*
* <pre>
*
* OFTWARE HISTORY
*
* SOFTWARE HISTORY
*
* Date Ticket# Engineer Description
* ----------- ---------- ----------- --------------------------
* 006 garmenda Initial Creation
* /14/2007 139 Phillippe Modified to follow refactored plugin pattern
* 8/30/07 njensen Added units, commented out data that
* is currently decoded but not used.
* 12/01/07 555 garmendariz Modified decompress method.
* is currently decoded but not used.
* 12/01/07 555 garmendariz Modified decompress method.
* 12/06/07 555 garmendariz Modifed start point to remove satellite header
* Dec 17, 2007 600 bphillip Added dao pool usage
* 04Apr2008 1068 MW Fegan Modified decompression routine to prevent
@ -69,11 +73,14 @@ import com.raytheon.uf.edex.wmo.message.WMOHeader;
* 11/11/2008 chammack Refactored to be thread safe in camel
* 02/05/2010 4120 jkorman Modified removeWmoHeader to handle WMOHeader in
* various start locations.
* 04/17/2012 14724 kshresth This is a temporary workaround - Projection off CONUS
* 04/17/2012 14724 kshresth This is a temporary workaround - Projection off CONUS
* - AWIPS2 Baseline Repository --------
* 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();

View file

@ -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

View file

@ -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()]);
}