Commit f4aaebfa authored by Julien Michel's avatar Julien Michel

Merge branch '1515-refactor-logging' into 'develop'

Refactor logging for the whole library

Closes #1515

See merge request !20
parents 751d1724 ee7eac62
......@@ -231,10 +231,6 @@ mark_as_advanced(OTB_USE_DEPRECATED)
option(OTB_USE_OPENMP "Add openmp compiler and linker flags" OFF)
option(OTB_USE_SSE_FLAGS "Enable SIMD optimizations (hardware dependent)." ON)
#-----------------------------------------------------------------------------
# SHOW_ALL_MSG_DEBUG option
option(OTB_SHOW_ALL_MSG_DEBUG "Show all debug messages (very verbose)" OFF)
#mark_as_advanced(OTB_SHOW_ALL_MSG_DEBUG)
include(OTBSetStandardCompilerFlags)
#---------------------------------------------------------------
......
.. _extended-filenames:
Advanced Use
============
This section describes advanced configuration options and tricks.
Environment variables that affects Orfeo ToolBox
------------------------------------------------
The following environment variables are parsed by Orfeo ToolBox. Note
that they only affect default values, and that settings in extended
filenames, applications, monteverdi or custom C++ code might override
those values.
* ``OTB_DEM_DIRECTORY``: Default directory were DEM tiles are stored. It should only contain ```.hgt`` or or georeferenced ``.tif`` files. Empty if not set (no directory set)
* ``OTB_GEOID_FILE``: Default path to the geoid file that will be used to retrieve height of DEM above ellipsoid. Empty if not set (no geoid set)
* ``OTB_MAX_RAM_HINT``: Default maximum memory that OTB should use for processing, in MB. If not set, default value is 128 MB.
* ``OTB_LOGGER_LEVEL``: Default level of logging for OTB. Should be one of ``DEBUG``, ``INFO``, ``WARNING``, ``CRITICAL`` or ``FATAL``, by increasing order of priority. Only messages with a higher priority than the level of logging will be displayed. If not set, default level is ``INFO``.
Extended filenames
================================
------------------
.. _extended-filenames:
Extended filenames is an interesting feature of OTB. With it, you can control
several aspects of the beahvior of the OTB in the OTB-Applications or in our
......@@ -42,7 +59,6 @@ applications from the bash command line.**
Reader options
^^^^^^^^^^^^^^
::
&geom=<path/filename.geom>
......
......@@ -8,7 +8,7 @@ Table of Contents
Installation
OTB-Applications
Monteverdi
ExtendedFilenames
AdvancedUse
Recipes
Applications
FAQ
......@@ -241,8 +241,6 @@ ReadGeometryFromImage(const std::string& filename, bool checkRpcTag)
if (projection)
{
otbMsgDevMacro(<< "OSSIM plugin projection instantiated ! ");
hasMetaData = projection->saveState(geom_kwl);
otb_kwl.SetKeywordlist(geom_kwl);
}
......@@ -257,7 +255,6 @@ ReadGeometryFromImage(const std::string& filename, bool checkRpcTag)
->open(ossimFilename(filename.c_str())));
if (handler)
{
otbMsgDevMacro(<< "OSSIM Open Image SUCCESS ! ");
// Add ossimPlugins model
ossimProjectionFactoryRegistry::instance()->registerFactory(ossimplugins::ossimPluginProjectionFactory::instance());
......@@ -273,7 +270,6 @@ ReadGeometryFromImage(const std::string& filename, bool checkRpcTag)
// if the handler has found a sensor model, copy the tags found
if (hasMetaData && dynamic_cast<ossimSensorModel const*>(projection))
{
otbMsgDevMacro(<<"OSSIM sensor projection instantiated ! ");
otb_kwl.SetKeywordlist(geom_kwl);
// geom_kwl.print(std::cout);
}
......@@ -317,16 +313,6 @@ ReadGeometryFromImage(const std::string& filename, bool checkRpcTag)
// which uses ossimSensorModelFactory and ossimPluginProjectionFactory internally,
// thus by-passing the need for a valid ossimImageHandler.
if (!hasMetaData)
{
otbMsgDevMacro(<< "OSSIM MetaData not present ! ");
}
else
{
otbMsgDevMacro(<< "OSSIM MetaData present ! ");
//otbMsgDevMacro(<< geom_kwl);
}
return otb_kwl;
}
......@@ -479,7 +465,6 @@ WriteGeometry(const ImageKeywordlist& otb_kwl, const std::string& filename)
if (geom_kwl.getSize() > 0)
{
otbMsgDevMacro(<< "Exporting keywordlist ...");
ossimFilename geomFileName(filename);
geomFileName.setExtension(".geom");
geom_kwl.write(geomFileName.chars());
......
......@@ -31,7 +31,7 @@
#include <string>
#include <boost/cstdint.hpp>
#include "itkLoggerBase.h"
#include "OTBCommonExport.h"
namespace otb
......@@ -84,6 +84,27 @@ public:
*/
static RAMValueType GetMaxRAMHint();
/**
* Logger level controls the level of logging that OTB will output.
*
* This is used to set-up the otb::Logger class.
*
* If OTB_LOGGER_LEVEL environment variable is set to one of DEBUG,
* INFO, WARNING, CRITICAL or FATAL, the logger level will be
* set accordingly.
*
* Priority is DEBUG < INFO < WARNING < CRITICAL < FATAL.
*
* Only messages with a higher priority than the logger level will
* be displayed.
*
* By default (if OTB_LOGGER_LEVEL is not set or can not be
* decoded), level is INFO.
*
*/
static itk::LoggerBase::PriorityLevelType GetLoggerLevel();
private:
ConfigurationManager(); //purposely not implemented
~ConfigurationManager(); //purposely not implemented
......
......@@ -23,6 +23,7 @@
#include "itkLoggerBase.h"
#include "itkLogger.h"
#include "OTBCommonExport.h"
namespace otb {
......@@ -31,9 +32,9 @@ namespace otb {
*
* Sets OTB wide settings in its constructor
*
* \ingroup OTBApplicationEngine
* \ingroup OTBCommon
*/
class Logger : public itk::Logger
class OTBCommon_EXPORT Logger : public itk::Logger
{
public:
typedef Logger Self;
......@@ -41,15 +42,27 @@ public:
typedef itk::SmartPointer< Self > Pointer;
typedef itk::SmartPointer< const Self > ConstPointer;
itkTypeMacro(Logger, Object);
itkNewMacro(Self);
itkTypeMacro(Logger, itk::Logger);
static Pointer Instance();
itkNewMacro(Self);
// Overwrite this to provide custom formatting of log entries
std::string BuildFormattedEntry(itk::Logger::PriorityLevelType, std::string const&) ITK_OVERRIDE;
void LogSetupInformation();
protected:
Logger();
virtual ~Logger();
Logger();
virtual ~Logger() ITK_OVERRIDE;
private:
Logger(const Self &); //purposely not implemented
void operator =(const Self&); //purposely not implemented
static Pointer CreateInstance();
}; // class Logger
} // namespace otb
......
......@@ -31,6 +31,7 @@
#include "itkMacro.h"
#include "itkObject.h"
#include "otbConfigure.h"
#include "otbLogger.h"
/**
* \namespace otb
......@@ -42,86 +43,31 @@ namespace otb
{
} // end namespace otb - this is here for documentation purposes
/** This macro is used to print debug (or other information). They are
* also used to catch errors, etc. Example usage looks like:
* itkDebugMacro(<< "this is debug info" << this->SomeVariable); */
#define otbDebugMacro(x) itkDebugMacro(x)
/* { if ( this->GetDebug() && *::itk::Object::GetGlobalWarningDisplay()) \
{ std::ostringstream itkmsg; \
itkmsg << "Debug: In " __FILE__ ", line " << __LINE__ << "\n" \
<< this->GetNameOfClass() << " (" << this << "): " x \
<< "\n\n"; \
::itk::OutputWindowDisplayDebugText(itkmsg.str().c_str()); } \
}*/
#define otbMsgDebugMacro(x) \
{ \
if (this->GetDebug() && ::itk::Object::GetGlobalWarningDisplay()) \
{ \
std::ostringstream itkmsg; \
itkmsg << " Msg Debug: " x << "\n"; \
::itk::OutputWindowDisplayDebugText(itkmsg.str().c_str()); \
} \
}
#define otbFileContext(x) \
<< "file " __FILE__ ", line " << __LINE__<<", " x
#ifndef NDEBUG
#define otbGenericMsgDebugMacro(x) \
{ \
if (::itk::Object::GetGlobalWarningDisplay()) \
{ \
std::ostringstream itkmsg; \
itkmsg << " Generic Msg Debug: " x << "\n"; \
::itk::OutputWindowDisplayDebugText(itkmsg.str().c_str()); \
} \
}
#else
#define otbGenericMsgDebugMacro(x)
#endif
#define otbClassContext(x) \
<< this->GetNameOfClass() << " (" << this << "): " x
#define otbGenericMsgTestingMacro(x) \
{ \
std::cout x << std::endl; \
}
// Beware that to log to CRITICAL level, level should be passed as "Error"
#define otbLogMacro(level,msg) \
{ \
std::ostringstream itkmsg; \
itkmsg msg << "\n"; \
otb::Logger::Instance()->level(itkmsg.str().c_str()); \
}
#ifdef OTB_SHOW_ALL_MSG_DEBUG
#define otbMsgDevMacro(x) \
{ \
{ \
std::ostringstream itkmsg; \
itkmsg << " Msg Dev: (" << __FILE__ << ":" << __LINE__ << ") " x << "\n"; \
::itk::OutputWindowDisplayDebugText(itkmsg.str().c_str()); \
} \
}
#else
#define otbMsgDevMacro(x)
#endif
/** This macro is used to print warning information (i.e., unusual circumstance
* but not necessarily fatal.) Example usage looks like:
* itkWarningMacro(<< "this is warning info" << this->SomeVariable); */
#define otbWarningMacro(x) \
{ \
if (itk::Object::GetGlobalWarningDisplay()) \
{ \
std::ostringstream itkmsg; \
itkmsg << "WARNING: In " __FILE__ ", line " << __LINE__ << "\n" \
<< this->GetNameOfClass() << " (" << this << "): " x \
<< "\n\n"; \
itk::OutputWindowDisplayWarningText(itkmsg.str().c_str()); \
} \
}
#define otbGenericWarningMacro(x) \
{ \
if (itk::Object::GetGlobalWarningDisplay()) \
{ \
std::ostringstream itkmsg; \
itkmsg << "WARNING: In " __FILE__ ", line " << __LINE__ << ": " x <<"\n";\
itk::OutputWindowDisplayWarningText(itkmsg.str().c_str()); \
} \
}
// Re-definition of old log macros to use the otbLogMacro
#define otbDebugMacro(x) otbLogMacro(Debug,otbFileContext(otbClassContext(x)))
#define otbMsgDebugMacro(x) otbLogMacro(Debug,otbFileContext(x))
#define otbGenericMsgDebugMacro(x) otbLogMacro(Debug,x)
#define otbMsgDevMacro(x) otbLogMacro(Debug,otbFileContext(x))
#define otbWarningMacro(x) otbLogMacro(Warning,otbFileContext(otbClassContext(x)))
#define otbGenericWarningMacro(x) otbLogMacro(Warning,otbFileContext(x))
#define otbGenericMsgTestingMAcro(x) otbLogMacro(Info,"[testing] "<<x)
/** This macro is used to control condition. It use ONLY by the OTB developers
*
*/
......
......@@ -29,12 +29,12 @@ set(OTBCommon_SRC
otbWriterWatcherBase.cxx
otbStopwatch.cxx
otbStringToHTML.cxx
otbLogger.cxx
)
add_library(OTBCommon ${OTBCommon_SRC})
target_link_libraries(OTBCommon
${OTBITK_LIBRARIES}
${OTBITK_LIBRARIES} ${OTBGDAL_LIBRARIES}
)
otb_module_target(OTBCommon)
......@@ -20,9 +20,13 @@
#include "otbConfigurationManager.h"
#include "otbMacro.h"
#include "itksys/SystemTools.hxx"
#include <cstdlib>
#include <algorithm>
#include <string>
namespace otb
{
......@@ -59,6 +63,39 @@ ConfigurationManager::RAMValueType ConfigurationManager::GetMaxRAMHint()
}
return value;
}
itk::LoggerBase::PriorityLevelType ConfigurationManager::GetLoggerLevel()
{
std::string svalue;
// Default value is INFO
itk::LoggerBase::PriorityLevelType level = itk::LoggerBase::INFO;
if(itksys::SystemTools::GetEnv("OTB_LOGGER_LEVEL",svalue))
{
if(svalue.compare("DEBUG") == 0)
{
level = itk::LoggerBase::DEBUG;
}
else if(svalue.compare("INFO") == 0)
{
level = itk::LoggerBase::INFO;
}
else if(svalue.compare("WARNING") == 0)
{
level = itk::LoggerBase::WARNING;
}
else if(svalue.compare("CRITICAL") == 0)
{
level = itk::LoggerBase::CRITICAL;
}
else
{
otbLogMacro(Error,<<"Unknown value for OTB_LOGGER_LEVEL_MACRO. Possible values are DEBUG, INFO, WARNING, CRITICAL.");
}
}
return level;
}
}
......@@ -27,9 +27,6 @@
#cmakedefine OTB_BUILD_SHARED_LIBS
/* Show developer debug messages */
#cmakedefine OTB_SHOW_ALL_MSG_DEBUG
#cmakedefine OTB_USE_GDAL_20
#cmakedefine OTB_USE_OPENMP
......
......@@ -20,18 +20,42 @@
#include "otbLogger.h"
#include "itksys/SystemTools.hxx"
#include "otbConfigurationManager.h"
#include "itkStdStreamLogOutput.h"
#include <iostream>
#include "gdal.h"
#include "itkMultiThreader.h"
namespace otb
{
Logger::Logger() :
itk::Logger::Logger()
Logger::Pointer Logger::CreateInstance()
{
#if OTB_DEBUG
this->SetPriorityLevel(itk::LoggerBase::DEBUG);
#else
this->SetPriorityLevel(itk::LoggerBase::INFO);
#endif
Logger::Pointer instance = Logger::New();
// By default, redirect logs to std::cout
itk::StdStreamLogOutput::Pointer defaultOutput = itk::StdStreamLogOutput::New();
defaultOutput->SetStream(std::cout);
instance->AddLogOutput(defaultOutput);
// Log setup information
instance->LogSetupInformation();
return instance;
}
Logger::Pointer Logger::Instance()
{
// Static locales are initialized once in a thread-safe way
static Logger::Pointer instance = CreateInstance();
return instance;
}
Logger::Logger()
{
this->SetPriorityLevel(otb::ConfigurationManager::GetLoggerLevel());
this->SetLevelForFlushing(itk::LoggerBase::CRITICAL);
......@@ -43,6 +67,26 @@ Logger::~Logger()
{
}
void Logger::LogSetupInformation()
{
std::ostringstream oss;
oss<<"Default RAM limit for OTB is "<<otb::ConfigurationManager::GetMaxRAMHint()<<" MB"<<std::endl;
this->Info(oss.str());
oss.str("");
oss.clear();
oss<<"GDAL maximum cache size is "<<GDALGetCacheMax64()/(1024*1024)<<" MB"<<std::endl;
this->Info(oss.str());
oss.str("");
oss.clear();
oss<<"OTB will use at most "<<itk::MultiThreader::GetGlobalDefaultNumberOfThreads()<<" threads"<<std::endl;
this->Info(oss.str());
oss.str("");
oss.clear();
}
std::string Logger::BuildFormattedEntry(itk::Logger::PriorityLevelType level, std::string const & content)
{
static const std::string levelString[] = { "(MUSTFLUSH)", "(FATAL)", "(CRITICAL)",
......
......@@ -152,11 +152,6 @@ ExtractROIBase<TInputImage, TOutputImage>
}
requestedRegion.SetIndex(index);
inputPtr->SetRequestedRegion(requestedRegion);
otbMsgDevMacro(<< "InputRequestedRegion (otbExtractROIBase): ");
otbMsgDevMacro(<< " - index: " << requestedRegion.GetIndex());
otbMsgDevMacro(<< " - size: " << requestedRegion.GetSize());
}
/**
......
......@@ -72,7 +72,7 @@ RAMDrivenAdaptativeStreamingManager<TImage>::PrepareStreaming( itk::DataObject *
this->m_Splitter = splitter;
this->m_ComputedNumberOfSplits = this->m_Splitter->GetNumberOfSplits(region, nbDivisions);
otbMsgDevMacro(<< "Number of split : " << this->m_ComputedNumberOfSplits)
this->m_Region = region;
}
......
......@@ -227,11 +227,11 @@ StreamingImageVirtualWriter<TInputImage>
m_ObserverID = source->AddObserver(itk::ProgressEvent(), command);
m_IsObserving = true;
}
else
{
itkWarningMacro(<< "Could not get the source process object. Progress report might be buggy");
}
const auto firstSplitSize = m_StreamingManager->GetSplit(0).GetSize();
otbLogMacro(Info,<<"Estimation will be performed in "<<m_NumberOfDivisions<<" blocks of "<<firstSplitSize[0]<<"x"<<firstSplitSize[1]<<" pixels");
/**
* Loop over the number of pieces, execute the upstream pipeline on each
* piece, and copy the results into the output image.
......@@ -242,7 +242,6 @@ StreamingImageVirtualWriter<TInputImage>
m_CurrentDivision++, m_DivisionProgress = 0, this->UpdateFilterProgress())
{
streamRegion = m_StreamingManager->GetSplit(m_CurrentDivision);
otbMsgDevMacro(<< "Processing region : " << streamRegion )
//inputPtr->ReleaseData();
//inputPtr->SetRequestedRegion(streamRegion);
//inputPtr->Update();
......
......@@ -47,12 +47,9 @@ StreamingManager<TImage>::GetActualAvailableRAMInBytes(MemoryPrintType available
if (availableRAMInBytes == 0)
{
otbMsgDevMacro(<< "Retrieving available RAM size from configuration");
// Retrieve it from the configuration
availableRAMInBytes = 1024*1024*ConfigurationManager::GetMaxRAMHint();
}
otbMsgDevMacro("RAM used to estimate memory footprint : " << availableRAMInBytes / 1024 / 1024 << " MB")
return availableRAMInBytes;
}
......@@ -62,8 +59,6 @@ StreamingManager<TImage>::EstimateOptimalNumberOfDivisions(itk::DataObject * inp
MemoryPrintType availableRAM,
double bias)
{
otbMsgDevMacro(<< "availableRAM " << availableRAM)
MemoryPrintType availableRAMInBytes = GetActualAvailableRAMInBytes(availableRAM);
otb::PipelineMemoryPrintCalculator::Pointer memoryPrintCalculator;
......@@ -103,7 +98,6 @@ StreamingManager<TImage>::EstimateOptimalNumberOfDivisions(itk::DataObject * inp
if (smallRegionSuccess)
{
otbMsgDevMacro("Using an extract to estimate memory : " << smallRegion)
// the region is well behaved, inside the largest possible region
memoryPrintCalculator->SetDataToWrite(extractFilter->GetOutput() );
......@@ -114,7 +108,6 @@ StreamingManager<TImage>::EstimateOptimalNumberOfDivisions(itk::DataObject * inp
}
else
{
otbMsgDevMacro("Using the input region to estimate memory : " << region)
// the region is not well behaved
// use the full region
memoryPrintCalculator->SetDataToWrite(input);
......@@ -148,11 +141,8 @@ StreamingManager<TImage>::EstimateOptimalNumberOfDivisions(itk::DataObject * inp
unsigned int optimalNumberOfDivisions =
otb::PipelineMemoryPrintCalculator::EstimateOptimalNumberOfStreamDivisions(pipelineMemoryPrint, availableRAMInBytes);
otbMsgDevMacro( "Estimated Memory print for the full image : "
<< static_cast<unsigned int>(pipelineMemoryPrint * otb::PipelineMemoryPrintCalculator::ByteToMegabyte ) << std::endl)
otbMsgDevMacro( "Optimal number of stream divisions: "
<< optimalNumberOfDivisions << std::endl)
otbLogMacro(Info,<<"Estimated memory for full processing: "<<pipelineMemoryPrint * otb::PipelineMemoryPrintCalculator::ByteToMegabyte<<"MB (avail.: "<<availableRAMInBytes * otb::PipelineMemoryPrintCalculator::ByteToMegabyte<<" NB), optimal image partitioning: "<<optimalNumberOfDivisions<<" blocks");
return optimalNumberOfDivisions;
}
......
......@@ -105,7 +105,7 @@ PipelineMemoryPrintCalculator::MemoryPrintType
PipelineMemoryPrintCalculator
::EvaluateProcessObjectPrintRecursive(ProcessObjectType * process)
{
otbMsgDevMacro(<< "EvaluateMemoryPrint for " << process->GetNameOfClass() << " (" << process << ")")
otbLogMacro(Debug,<<"Recursive evaluation of memory print for ProcessObject" << process->GetNameOfClass() << " (" << process << ")");
// This variable will store the final print
MemoryPrintType print = 0;
......@@ -164,8 +164,9 @@ PipelineMemoryPrintCalculator::MemoryPrintType
PipelineMemoryPrintCalculator
::EvaluateDataObjectPrint(DataObjectType * data)
{
otbMsgDevMacro(<< "EvaluateMemoryPrint for " << data->GetNameOfClass() << " (" << data << ")")
otbLogMacro(Debug,<<"Evaluation of memory print for DataObject " << data->GetNameOfClass() << " (" << data << ")");
#define OTB_IMAGE_SIZE_BLOCK(type) \
if(dynamic_cast<itk::Image<type, 2> *>(data) != NULL) \
{ \
......
......@@ -263,9 +263,10 @@ otb_add_test(NAME feTvFourierMellinDescriptors COMMAND otbDescriptorsTestDriver
)
otb_add_test(NAME feTvImageToSIFTKeyPointSetFilterDistanceMap COMMAND otbDescriptorsTestDriver
--compare-ascii ${EPSILON_3}
--compare-ascii ${EPSILON_3}
${BASELINE_FILES}/feTvImageToSIFTKeyPointSetFilterDistanceMap.txt
${TEMP}/feTvImageToSIFTKeyPointSetFilterDistanceMap.txt
--ignore-lines-with 2 INFO DEBUG
otbImageToSIFTKeyPointSetFilterDistanceMap
${INPUTDATA}/scene.png
6 3 0.08 10.0
......
This diff is collapsed.
......@@ -107,7 +107,6 @@ void
ImageFileReader<TOutputImage, ConvertPixelTraits>
::SetImageIO( otb::ImageIOBase * imageIO)
{
itkDebugMacro("setting ImageIO to " << imageIO );
if (this->m_ImageIO != imageIO )
{
this->m_ImageIO = imageIO;
......@@ -207,12 +206,6 @@ ImageFileReader<TOutputImage, ConvertPixelTraits>
char * loadBuffer = new char[nbBytes];
otbMsgDevMacro(<< "buffer size for ImageIO::read = " << nbBytes << " = \n"
<< "ComponentSize ("<< this->m_ImageIO->GetComponentSize() << ") x " \
<< "Nb of Component ( max(" << this->m_ImageIO->GetNumberOfComponents() \
<< " , "<<m_BandList.size() << ") ) x " \
<< "Nb of Pixel to read (" << region.GetNumberOfPixels() << ")");
this->m_ImageIO->Read(loadBuffer);
if (m_FilenameHelper->BandRangeIsSet())
......@@ -410,13 +403,13 @@ ImageFileReader<TOutputImage, ConvertPixelTraits>
if (m_FilenameHelper->ExtGEOMFileNameIsSet())
{
otb_kwl = ReadGeometryFromGEOMFile(m_FilenameHelper->GetExtGEOMFileName());
otbMsgDevMacro(<< "Loading external kwl: "<< m_FilenameHelper->GetExtGEOMFileName());
otbLogMacro(Info,<< "Loading kwl metadata from external geom file "<< m_FilenameHelper->GetExtGEOMFileName());
}
// Case 2: attached geom (if present)
else if (itksys::SystemTools::FileExists(attachedGeom))
{
otb_kwl = ReadGeometryFromGEOMFile(attachedGeom);
otbMsgDevMacro(<< "Loading attached kwl");
otbLogMacro(Info,<< "Loading kwl metadata from attached geom file "<<attachedGeom);
}
// Case 3: find an ossimPluginProjection
// Case 4: find an ossimProjection
......@@ -424,7 +417,14 @@ ImageFileReader<TOutputImage, ConvertPixelTraits>
else
{
otb_kwl = ReadGeometryFromImage(lFileNameOssimKeywordlist,!m_FilenameHelper->GetSkipRpcTag());
otbMsgDevMacro(<< "Loading internal kwl");
if(!otb_kwl.Empty())
{
otbLogMacro(Info,<< "Loading kwl metadata from official product in file "<<lFileNameOssimKeywordlist);