Update logging for enabled devices

The previous implementation of `RuntimeDeviceTracker` occasionally
outputted a log at level `Info` about devices being enabled or disabled.
The problem was that the information given was inconsistent (so it would
sometimes announce one change but not announce a different corrective
change). This could cause weird confusions. For example, when you used a
`ColorTable`, it would use a `ScopedRuntimeDeviceTracker` to temporarily
force the device to `Serial`. The log will just tell you that the device
was forced to `Serial` but never tell you that the devices where
restored to include actual parallel devices.

This change helps correct these with the following changes:

* Added a new log level, `DevicesEnabled`, that is a higher level than
  `Info`. All logging from `RuntimeDeviceTracker` goes to this log
  level.
* Change the logging output of `RuntimeDeviceTracker` to output a list
  of currently enabled devices whenever a change happens. That way you
  don't have to guess what happend for each change.
* Change `ScopedRuntimeDeviceTracker` to log whenever the scope is
  entered or left.

vtkm/cont/Logging.cxx

@@ -111,6 +111,7 @@ void InitLogging(int& argc, char* argv[])
   SetLogLevelName(vtkm::cont::LogLevel::Error, "ERR");
   SetLogLevelName(vtkm::cont::LogLevel::Warn, "WARN");
   SetLogLevelName(vtkm::cont::LogLevel::Info, "Info");
+  SetLogLevelName(vtkm::cont::LogLevel::DevicesEnabled, "Dev");
   SetLogLevelName(vtkm::cont::LogLevel::Perf, "Perf");
   SetLogLevelName(vtkm::cont::LogLevel::MemCont, "MemC");
   SetLogLevelName(vtkm::cont::LogLevel::MemExec, "MemE");

vtkm/cont/Logging.h

@@ -322,6 +322,9 @@ enum class LogLevel
   /// The range 1-255 are reserved to application use.
   UserLast = 255,
 
+  /// Information about which devices are enabled/disabled
+  DevicesEnabled,
+
   /// General timing data and algorithm flow information, such as filter
   /// execution, worklet dispatches, and device algorithm calls.
   Perf,

vtkm/cont/RuntimeDeviceTracker.cxx

@@ -86,8 +86,6 @@ void RuntimeDeviceTracker::SetDeviceState(vtkm::cont::DeviceAdapterId deviceId,
 {
   this->CheckDevice(deviceId);
 
-  VTKM_LOG_S(vtkm::cont::LogLevel::Info,
-             "Setting device '" << deviceId.GetName() << "' to " << state);
   this->Internals->RuntimeAllowed[deviceId.GetValue()] = state;
 }
 
@@ -102,6 +100,7 @@ VTKM_CONT void RuntimeDeviceTracker::ResetDevice(vtkm::cont::DeviceAdapterId dev
   {
     vtkm::cont::RuntimeDeviceInformation runtimeDevice;
     this->SetDeviceState(deviceId, runtimeDevice.Exists(deviceId));
+    this->LogEnabledDevices();
   }
 }
 
@@ -122,10 +121,9 @@ void RuntimeDeviceTracker::Reset()
     {
       const bool state = runtimeDevice.Exists(device);
       this->Internals->RuntimeAllowed[device.GetValue()] = state;
-      VTKM_LOG_S(vtkm::cont::LogLevel::Info,
-                 "Reset device '" << device.GetName() << "' to " << state);
     }
   }
+  this->LogEnabledDevices();
 }
 
 VTKM_CONT void RuntimeDeviceTracker::DisableDevice(vtkm::cont::DeviceAdapterId deviceId)
@@ -138,6 +136,7 @@ VTKM_CONT void RuntimeDeviceTracker::DisableDevice(vtkm::cont::DeviceAdapterId d
   {
     this->SetDeviceState(deviceId, false);
   }
+  this->LogEnabledDevices();
 }
 
 VTKM_CONT
@@ -160,12 +159,10 @@ void RuntimeDeviceTracker::ForceDevice(DeviceAdapterId deviceId)
       throw vtkm::cont::ErrorBadValue(message.str());
     }
 
-    VTKM_LOG_S(vtkm::cont::LogLevel::Info,
-               "Forcing execution to occur on device '" << deviceId.GetName() << "'");
-
     std::fill_n(this->Internals->RuntimeAllowed, VTKM_MAX_DEVICE_ADAPTER_ID, false);
 
     this->Internals->RuntimeAllowed[deviceId.GetValue()] = runtimeExists;
+    this->LogEnabledDevices();
   }
 }
 
@@ -180,12 +177,35 @@ void RuntimeDeviceTracker::PrintSummary(std::ostream& out) const
   }
 }
 
+VTKM_CONT
+void RuntimeDeviceTracker::LogEnabledDevices() const
+{
+  std::stringstream message;
+  message << "Enabled devices:";
+  bool atLeastOneDeviceEnabled = false;
+  for (vtkm::Int8 deviceIndex = 1; deviceIndex < VTKM_MAX_DEVICE_ADAPTER_ID; ++deviceIndex)
+  {
+    vtkm::cont::DeviceAdapterId device = vtkm::cont::make_DeviceAdapterId(deviceIndex);
+    if (this->CanRunOn(device))
+    {
+      message << " " << device.GetName();
+      atLeastOneDeviceEnabled = true;
+    }
+  }
+  if (!atLeastOneDeviceEnabled)
+  {
+    message << " NONE!";
+  }
+  VTKM_LOG_S(vtkm::cont::LogLevel::DevicesEnabled, message.str());
+}
+
 VTKM_CONT
 ScopedRuntimeDeviceTracker::ScopedRuntimeDeviceTracker(vtkm::cont::DeviceAdapterId device,
                                                        RuntimeDeviceTrackerMode mode)
   : RuntimeDeviceTracker(GetRuntimeDeviceTracker().Internals, false)
   , SavedState(new detail::RuntimeDeviceTrackerInternals())
 {
+  VTKM_LOG_S(vtkm::cont::LogLevel::DevicesEnabled, "Entering scoped runtime region");
   std::copy_n(
     this->Internals->RuntimeAllowed, VTKM_MAX_DEVICE_ADAPTER_ID, this->SavedState->RuntimeAllowed);
 
@@ -211,6 +231,7 @@ ScopedRuntimeDeviceTracker::ScopedRuntimeDeviceTracker(
   : RuntimeDeviceTracker(tracker.Internals, false)
   , SavedState(new detail::RuntimeDeviceTrackerInternals())
 {
+  VTKM_LOG_S(vtkm::cont::LogLevel::DevicesEnabled, "Entering scoped runtime region");
   std::copy_n(
     this->Internals->RuntimeAllowed, VTKM_MAX_DEVICE_ADAPTER_ID, this->SavedState->RuntimeAllowed);
   if (mode == RuntimeDeviceTrackerMode::Force)
@@ -233,6 +254,7 @@ ScopedRuntimeDeviceTracker::ScopedRuntimeDeviceTracker(
   : RuntimeDeviceTracker(tracker.Internals, false)
   , SavedState(new detail::RuntimeDeviceTrackerInternals())
 {
+  VTKM_LOG_S(vtkm::cont::LogLevel::DevicesEnabled, "Entering scoped runtime region");
   std::copy_n(
     this->Internals->RuntimeAllowed, VTKM_MAX_DEVICE_ADAPTER_ID, this->SavedState->RuntimeAllowed);
 }
@@ -240,8 +262,10 @@ ScopedRuntimeDeviceTracker::ScopedRuntimeDeviceTracker(
 VTKM_CONT
 ScopedRuntimeDeviceTracker::~ScopedRuntimeDeviceTracker()
 {
+  VTKM_LOG_S(vtkm::cont::LogLevel::DevicesEnabled, "Leaving scoped runtime region");
   std::copy_n(
     this->SavedState->RuntimeAllowed, VTKM_MAX_DEVICE_ADAPTER_ID, this->Internals->RuntimeAllowed);
+  this->LogEnabledDevices();
 }
 
 VTKM_CONT

vtkm/cont/RuntimeDeviceTracker.h

@@ -131,6 +131,9 @@ private:
 
   VTKM_CONT
   void SetDeviceState(vtkm::cont::DeviceAdapterId deviceId, bool state);
+
+  VTKM_CONT
+  void LogEnabledDevices() const;
 };
 
 

vtkm/cont/testing/Testing.h

@@ -38,7 +38,7 @@ public:
   template <class Func>
   static VTKM_CONT int Run(Func function, int& argc, char* argv[])
   {
-    vtkm::cont::Initialize(argc, argv);
+    vtkm::cont::Initialize(argc, argv, vtkm::cont::InitializeOptions::Strict);
 
     try
     {
@@ -71,7 +71,8 @@ public:
   template <class Func>
   static VTKM_CONT int RunOnDevice(Func function, int argc, char* argv[])
   {
-    auto opts = vtkm::cont::InitializeOptions::RequireDevice;
+    auto opts =
+      vtkm::cont::InitializeOptions::RequireDevice | vtkm::cont::InitializeOptions::Strict;
     auto config = vtkm::cont::Initialize(argc, argv, opts);
 
     try