From 3e8f43a0138b80376523bbaf3e3f482bb4b238bc Mon Sep 17 00:00:00 2001
From: Jan David Mol <mol@astron.nl>
Date: Thu, 9 Dec 2010 13:50:01 +0000
Subject: [PATCH] bug 1362: reduce logging in production, switchable through
 commandOLAP

---
 RTCP/FCNP/src/fcnp_ion.cc         |  6 +++---
 RTCP/IONProc/src/CommandServer.cc | 10 +++++++++-
 RTCP/IONProc/src/ION_main.cc      |  7 +++++++
 RTCP/IONProc/src/Job.cc           | 31 ++++++++++++++++++-------------
 RTCP/IONProc/src/LogThread.cc     |  8 +++++---
 RTCP/IONProc/src/LogThread.h      |  2 +-
 RTCP/IONProc/src/OutputSection.cc |  2 +-
 RTCP/IONProc/src/OutputThread.cc  |  6 +++---
 RTCP/IONProc/src/OutputThread.h   |  2 +-
 RTCP/Run/src/LOFAR/Core.py        |  1 -
 RTCP/Run/src/LOFAR/Parset.py      |  2 +-
 RTCP/Run/src/LOFAR/Sections.py    |  3 ++-
 12 files changed, 51 insertions(+), 29 deletions(-)

diff --git a/RTCP/FCNP/src/fcnp_ion.cc b/RTCP/FCNP/src/fcnp_ion.cc
index 63f7fd5ba2e..fc26ef65efd 100644
--- a/RTCP/FCNP/src/fcnp_ion.cc
+++ b/RTCP/FCNP/src/fcnp_ion.cc
@@ -471,7 +471,7 @@ static void *pollThread(void *)
   }
 
   if (useInterrupts) {
-    LOG_INFO_STR( "FCNP: Received " << nrInterrupts << " vc0 interrupts" );
+    LOG_DEBUG_STR( "FCNP: Received " << nrInterrupts << " vc0 interrupts" );
     stopped = true;
   }
 
@@ -602,7 +602,7 @@ static void drainFIFO()
   }
 
   if (quadsToRead > 0)
-    LOG_INFO_STR( "FCNP: Dropped " << quadsToRead << " lingering quadwords from packets of a previous job" );
+    LOG_DEBUG_STR( "FCNP: Dropped " << quadsToRead << " lingering quadwords from packets of a previous job" );
 
   while (-- quadsToRead >= 0)
     _bgp_QuadLoad(vc0 + _BGP_TRx_Sx, 0);
@@ -629,7 +629,7 @@ static void drainFIFO()
     }
 
   if (dropped > 0)
-    LOG_INFO_STR( "FCNP: Dropped " << dropped << " lingering packets from previous job" );
+    LOG_DEBUG_STR( "FCNP: Dropped " << dropped << " lingering packets from previous job" );
 }
 
 
diff --git a/RTCP/IONProc/src/CommandServer.cc b/RTCP/IONProc/src/CommandServer.cc
index ab034a4caa6..d394e1f6c97 100644
--- a/RTCP/IONProc/src/CommandServer.cc
+++ b/RTCP/IONProc/src/CommandServer.cc
@@ -65,6 +65,12 @@ static void handleCommand(const std::string &command)
     }
   } else if (command == "quit") {
     quit = true;
+#if defined HAVE_BGP    
+  } else if (command == "debug") {
+    LOGCOUT_SETLEVEL(8);
+  } else if (command == "nodebug") {
+    LOGCOUT_SETLEVEL(4);
+#endif    
   } else if (command == "") {
     // quietly drop empty commands
   } else if (myPsetNumber == 0) {
@@ -82,12 +88,14 @@ static void commandMaster()
 
   SocketStream sk("0.0.0.0", 4000, SocketStream::TCP, SocketStream::Server);
 
+  LOG_INFO( "Command server ready" );
+
   while (!quit) {
     std::string command;
 
     try {
       command = sk.readLine();
-      LOG_DEBUG_STR("read command: " << command);
+      LOG_INFO_STR("read command: " << command);
     } catch (Stream::EndOfStreamException &) {
       sk.reaccept();
       continue;
diff --git a/RTCP/IONProc/src/ION_main.cc b/RTCP/IONProc/src/ION_main.cc
index 3e31fc00602..5eb1048a56b 100644
--- a/RTCP/IONProc/src/ION_main.cc
+++ b/RTCP/IONProc/src/ION_main.cc
@@ -439,6 +439,13 @@ int main(int argc, char **argv)
   
 #if defined HAVE_BGP
   INIT_LOGGER_WITH_SYSINFO(str(format("IONProc@%02d") % myPsetNumber));
+  bool isProduction = argc > 1 && argv[1][0] == '1';
+
+  if (isProduction) {
+    LOGCOUT_SETLEVEL(4); // do not show debug info
+  } else {
+    LOGCOUT_SETLEVEL(8); // show debug info
+  }
 #elif defined HAVE_LOG4CPLUS
   // do nothing
 #elif defined HAVE_LOG4CXX
diff --git a/RTCP/IONProc/src/Job.cc b/RTCP/IONProc/src/Job.cc
index 7eaa72bdc8f..c2890e78153 100644
--- a/RTCP/IONProc/src/Job.cc
+++ b/RTCP/IONProc/src/Job.cc
@@ -42,6 +42,8 @@
 #include <boost/format.hpp>
 using boost::format;
 
+#define LOG_CONDITION (myPsetNumber == 0)
+
 namespace LOFAR {
 namespace RTCP {
 
@@ -63,11 +65,13 @@ Job::Job(const char *parsetName)
 
   checkParset();
 
-  LOG_INFO_STR(itsLogPrefix << "----- Creating new observation");
-  LOG_DEBUG_STR(itsLogPrefix << "usedCoresInPset = " << itsParset.usedCoresInPset());
-
   itsNrRuns = static_cast<unsigned>(ceil((itsParset.stopTime() - itsParset.startTime()) / itsParset.CNintegrationTime()));
-  LOG_DEBUG_STR(itsLogPrefix << "itsNrRuns = " << itsNrRuns);
+
+  if (LOG_CONDITION) {
+    LOG_INFO_STR(itsLogPrefix << "----- Creating new job");
+    LOG_DEBUG_STR(itsLogPrefix << "usedCoresInPset = " << itsParset.usedCoresInPset());
+    LOG_DEBUG_STR(itsLogPrefix << "itsNrRuns = " << itsNrRuns);
+  }
 
   // synchronize roughly every 5 seconds to see if the job is cancelled
   itsNrRunTokensPerBroadcast = static_cast<unsigned>(ceil(5.0 / itsParset.CNintegrationTime()));
@@ -86,7 +90,8 @@ Job::~Job()
   delete itsJobThread;
   jobQueue.remove(this);
 
-  LOG_INFO_STR(itsLogPrefix << "----- Observation " << (itsIsRunning ? "ended" : "cancelled") << " successfully");
+  if (LOG_CONDITION)
+    LOG_INFO_STR(itsLogPrefix << "----- Job " << (itsIsRunning ? "finished" : "cancelled") << " successfully");
 }
 
 
@@ -498,7 +503,7 @@ bool Job::configureCNs()
 void Job::unconfigureCNs()
 {
   CN_Command command(CN_Command::POSTPROCESS);
-
+ 
   LOG_DEBUG_STR(itsLogPrefix << "Unconfiguring cores " << itsParset.usedCoresInPset() << " ...");
 
   for (unsigned core = 0; core < itsCNstreams.size(); core ++)
@@ -530,14 +535,15 @@ template <typename SAMPLE_TYPE> void Job::doObservation()
   unsigned nrparts = itsParset.nrPartsPerStokes();
   unsigned nrbeams = itsParset.flysEye() ? itsParset.nrMergedStations() : itsParset.nrPencilBeams();
 
-
-  LOG_INFO_STR(itsLogPrefix << "----- Observation start");
+  if (LOG_CONDITION)
+    LOG_INFO_STR(itsLogPrefix << "----- Observation start");
 
   // first: send configuration to compute nodes so they know what to expect
   if (!configureCNs()) {
     unconfigureCNs();
 
-    LOG_INFO_STR(itsLogPrefix << "----- Observation finished");
+    if (LOG_CONDITION)
+      LOG_INFO_STR(itsLogPrefix << "----- Observation finished");
     return;
   }
 
@@ -626,8 +632,6 @@ template <typename SAMPLE_TYPE> void Job::doObservation()
         continue;
     }
 
-    LOG_DEBUG_STR(itsLogPrefix << "Setting up output " << p.outputNr << " (" << p.name << ")");
-
     outputSections[output] = new OutputSection(itsParset, cores, list, maxlistsize, p, &createCNstream);
   }
 
@@ -666,8 +670,9 @@ template <typename SAMPLE_TYPE> void Job::doObservation()
     detachFromInputSection<SAMPLE_TYPE>();
 
   unconfigureCNs();
-
-  LOG_INFO_STR(itsLogPrefix << "----- Observation finished");
+ 
+  if (LOG_CONDITION)
+    LOG_INFO_STR(itsLogPrefix << "----- Observation finished");
 }
 
 
diff --git a/RTCP/IONProc/src/LogThread.cc b/RTCP/IONProc/src/LogThread.cc
index 5c1de2a0130..b5d3bc583c4 100644
--- a/RTCP/IONProc/src/LogThread.cc
+++ b/RTCP/IONProc/src/LogThread.cc
@@ -54,6 +54,8 @@ LogThread::LogThread(unsigned nrRspBoards, std::string stationName)
 LogThread::~LogThread()
 {
   itsShouldStop = true;
+
+  itsThread.abort(); // mainly to shorten the sleep() call
 }
 
 
@@ -123,7 +125,7 @@ void LogThread::mainLoop()
   readCPUstats(previousLoad);
 #endif
 
-  LOG_DEBUG("LogThread running");
+  //LOG_DEBUG("LogThread running");
 
   // non-atomic updates from other threads cause race conditions, but who cares
 
@@ -160,11 +162,11 @@ void LogThread::mainLoop()
     writeCPUstats(logStr);
 #endif
 
-    LOG_INFO(logStr.str());
+    LOG_INFO_STR(logStr.str());
     sleep(1);
   }
 
-  LOG_DEBUG("LogThread stopped");
+  //LOG_DEBUG("LogThread stopped");
 }
 
 } // namespace RTCP
diff --git a/RTCP/IONProc/src/LogThread.h b/RTCP/IONProc/src/LogThread.h
index 8537de731dd..f27a1228420 100644
--- a/RTCP/IONProc/src/LogThread.h
+++ b/RTCP/IONProc/src/LogThread.h
@@ -54,7 +54,7 @@ class LogThread
     std::string   itsStationName;
   
     volatile bool itsShouldStop;
-    Thread	  itsThread;
+    InterruptibleThread	itsThread;
 
 #if defined HAVE_BGP_ION
     struct CPUload {
diff --git a/RTCP/IONProc/src/OutputSection.cc b/RTCP/IONProc/src/OutputSection.cc
index beb7f73dff4..f1c1562405e 100644
--- a/RTCP/IONProc/src/OutputSection.cc
+++ b/RTCP/IONProc/src/OutputSection.cc
@@ -171,7 +171,7 @@ void OutputSection::droppingData(unsigned subband)
 void OutputSection::notDroppingData(unsigned subband)
 {
   if (itsDroppedCount[subband] > 0) {
-    LOG_WARN_STR(itsLogPrefix << " index " << setw(3) << itsItemList[subband].second << "] Dropped " << itsDroppedCount[subband] << " integration time(s)" );
+    LOG_WARN_STR(itsLogPrefix << " index " << setw(3) << itsItemList[subband].second << "] Dropped " << itsDroppedCount[subband] << " blocks" );
     itsDroppedCount[subband] = 0;
   }
 }
diff --git a/RTCP/IONProc/src/OutputThread.cc b/RTCP/IONProc/src/OutputThread.cc
index b7ef57acf13..8f7c8e7d681 100644
--- a/RTCP/IONProc/src/OutputThread.cc
+++ b/RTCP/IONProc/src/OutputThread.cc
@@ -144,12 +144,12 @@ void OutputThread::mainLoop()
   std::auto_ptr<Stream> streamToStorage;
   std::string		outputDescriptor = getStreamDescriptorBetweenIONandStorage(itsParset, itsServer, itsFilename);
 
-  LOG_INFO_STR(itsLogPrefix << "Creating connection to " << outputDescriptor << "...");
+  LOG_DEBUG_STR(itsLogPrefix << "Creating connection to " << outputDescriptor << "...");
 
   try {
     streamToStorage.reset(createStream(outputDescriptor, false));
 
-    LOG_INFO_STR(itsLogPrefix << "Creating connection to " << outputDescriptor << ": done");
+    LOG_DEBUG_STR(itsLogPrefix << "Creating connection to " << outputDescriptor << ": done");
   } catch (SystemCallException &ex) {
     if (ex.error == EINTR) {
       LOG_WARN_STR(itsLogPrefix << "Connection to " << outputDescriptor << " aborted");
@@ -194,7 +194,7 @@ void OutputThread::mainLoop()
 
   delete streamToStorage.release(); // close socket
 
-  LOG_INFO_STR(itsLogPrefix << "Connection to " << outputDescriptor << " closed");
+  LOG_DEBUG_STR(itsLogPrefix << "Connection to " << outputDescriptor << " closed");
 }
 
 } // namespace RTCP
diff --git a/RTCP/IONProc/src/OutputThread.h b/RTCP/IONProc/src/OutputThread.h
index dd8960ca2e3..d71ad356928 100644
--- a/RTCP/IONProc/src/OutputThread.h
+++ b/RTCP/IONProc/src/OutputThread.h
@@ -51,7 +51,7 @@ class OutputThread
     bool                    waitForDone(const struct timespec &timespec);                        
     void                    abort();
 
-    static const unsigned   maxSendQueueSize = 2; // use 2 if you run out of memory, but test carefully to avoid data loss
+    static const unsigned   maxSendQueueSize = 3; // use 2 if you run out of memory, but test carefully to avoid data loss
 
     Queue<StreamableData *> itsFreeQueue, itsSendQueue;
 
diff --git a/RTCP/Run/src/LOFAR/Core.py b/RTCP/Run/src/LOFAR/Core.py
index 93ca782eee4..882bd34235a 100644
--- a/RTCP/Run/src/LOFAR/Core.py
+++ b/RTCP/Run/src/LOFAR/Core.py
@@ -9,7 +9,6 @@ from CommandClient import sendCommand
 from ObservationID import ObservationID
 from Parset import Parset
 from Stations import Stations,overrideRack
-from util.Hosts import ropen,rmkdir,rexists,runlink,rsymlink
 from util.dateutil import format
 import sys
 import signal
diff --git a/RTCP/Run/src/LOFAR/Parset.py b/RTCP/Run/src/LOFAR/Parset.py
index a07e994c5b9..8217a88016a 100644
--- a/RTCP/Run/src/LOFAR/Parset.py
+++ b/RTCP/Run/src/LOFAR/Parset.py
@@ -129,7 +129,7 @@ class Parset(util.Parset.Parset):
 
         self.setdefault("OLAP.Correlator.integrationTime",1);
         if "OLAP.Stokes.channelsPerSubband" not in self or int(self["OLAP.Stokes.channelsPerSubband"]) == 0:
-          self["OLAP.Stokes.channelsPerSubband"] = self["Observation.nrChannelsPerSubband"]
+          self["OLAP.Stokes.channelsPerSubband"] = self["Observation.channelsPerSubband"]
 
 
         self.setdefault('OLAP.Storage.Filtered.namemask','L${OBSID}_SB${SUBBAND}.filtered')
diff --git a/RTCP/Run/src/LOFAR/Sections.py b/RTCP/Run/src/LOFAR/Sections.py
index f1a880947f7..d52971dd2f0 100644
--- a/RTCP/Run/src/LOFAR/Sections.py
+++ b/RTCP/Run/src/LOFAR/Sections.py
@@ -2,7 +2,7 @@
 
 from util.Commands import SyncCommand,AsyncCommand,mpikill,backquote,PIPE
 from util.Aborter import runUntilSuccess,runFunc
-from Locations import Locations,Hosts
+from Locations import Locations,Hosts,isProduction
 import Logger
 import os
 import Partitions
@@ -182,6 +182,7 @@ class IONProcSection(Section):
       "%s" % (Locations.files["ionproc"],),
 
       # arguments
+      "%d" % (int(isProduction()),),
     ]
 
 
-- 
GitLab