Repository: pints-team/pints

Issue:
Header of logged "time" field is wrong
When we log to CSV the header says `Time m:s` but the value shown is a float representing seconds

Discussion:

Patch:
diff --git a/CHANGELOG.md b/CHANGELOG.md
index d7258a69..cdeb4523 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -7,6 +7,7 @@ All notable changes to this project will be documented in this file.
 ### Added
 - [#1499](https://github.com/pints-team/pints/pull/1499) Added a log-uniform prior class.
 ### Changed
+- [#1503](https://github.com/pints-team/pints/pull/1503) Stopped showing time units in controller logs, because the units change depending on the output type (see #1467).
 ### Deprecated
 ### Removed
 ### Fixed
diff --git a/pints/_abc/__init__.py b/pints/_abc/__init__.py
index 2313f88c..a3e49a89 100644
--- a/pints/_abc/__init__.py
+++ b/pints/_abc/__init__.py
@@ -235,7 +235,9 @@ class ABCController(object):
             logger.add_counter('Eval.', max_value=max_eval_guess)
             logger.add_float('Acceptance rate')
             self._sampler._log_init(logger)
-            logger.add_time('Time m:s')
+            # Note: removed units from time field, see
+            # https://github.com/pints-team/pints/issues/1467
+            logger.add_time('Time')
 
         # Start sampling
         timer = pints.Timer()
diff --git a/pints/_mcmc/__init__.py b/pints/_mcmc/__init__.py
index f0ec64ba..ff566bf5 100644
--- a/pints/_mcmc/__init__.py
+++ b/pints/_mcmc/__init__.py
@@ -665,7 +665,9 @@ class MCMCController(object):
             logger.add_counter('Eval.', max_value=max_eval_guess)
             for sampler in self._samplers:
                 sampler._log_init(logger)
-            logger.add_time('Time m:s')
+            # Note: deleted time units from header, see
+            # https://github.com/pints-team/pints/issues/1467
+            logger.add_time('Time')
 
         # Pre-allocate arrays for chain storage
         # Note: we store the inverse transformed (to model space) parameters
diff --git a/pints/_nested/__init__.py b/pints/_nested/__init__.py
index a7a15259..c8c24462 100644
--- a/pints/_nested/__init__.py
+++ b/pints/_nested/__init__.py
@@ -409,7 +409,9 @@ class NestedController(object):
             # Add fields to log
             self._logger.add_counter('Iter.', max_value=self._iterations)
             self._logger.add_counter('Eval.', max_value=self._iterations * 10)
-            self._logger.add_time('Time m:s')
+            # Note: removed units from time field, see
+            # https://github.com/pints-team/pints/issues/1467
+            self._logger.add_time('Time')
             self._logger.add_float('Delta_log(z)')
             self._logger.add_float('Acceptance rate')
 
diff --git a/pints/_optimisers/__init__.py b/pints/_optimisers/__init__.py
index 5887051d..363a4ee2 100644
--- a/pints/_optimisers/__init__.py
+++ b/pints/_optimisers/__init__.py
@@ -635,7 +635,9 @@ class OptimisationController(object):
             logger.add_float('Best')
             logger.add_float('Current')
             self._optimiser._log_init(logger)
-            logger.add_time('Time m:s')
+            # Note: No units shown in time field, for the reason why see
+            # https://github.com/pints-team/pints/issues/1467
+            logger.add_time('Time')
 
         # Start searching
         timer = pints.Timer()


Test patch:
diff --git a/pints/tests/test_abc_controller.py b/pints/tests/test_abc_controller.py
index 1d7e2f7a..6ca494d9 100755
--- a/pints/tests/test_abc_controller.py
+++ b/pints/tests/test_abc_controller.py
@@ -18,7 +18,7 @@ from shared import StreamCapture, TemporaryDirectory
 LOG_SCREEN_1 = [
     'Using Rejection ABC',
     'Running in sequential mode.',
-    'Iter. Eval. Acceptance rate Time m:s',
+    'Iter. Eval. Acceptance rate Time    ',
     '1     127    0.00787401575    0:00.0',
     '2     167    0.0119760479     0:00.0',
     '3     209    0.014354067      0:00.0',
@@ -28,7 +28,7 @@ LOG_SCREEN_1 = [
 LOG_SCREEN_2 = [
     'Using Rejection ABC',
     'Running in parallel with 2 worker processess.',
-    'Iter. Eval. Acceptance rate Time m:s',
+    'Iter. Eval. Acceptance rate Time    ',
     '1     20     0.05             0:00.0',
     '2     22     0.0909090909     0:00.0',
     '3     144    0.0208333333     0:00.0',
@@ -38,7 +38,7 @@ LOG_SCREEN_2 = [
 ]
 
 LOG_FILE = [
-    'Iter. Eval. Acceptance rate Time m:s',
+    'Iter. Eval. Acceptance rate Time    ',
     '1     127    0.00787401575    0:00.0',
     '2     167    0.0119760479     0:00.0',
     '3     209    0.014354067      0:00.0',
@@ -46,7 +46,7 @@ LOG_FILE = [
 ]
 
 LOG_FILE_CSV = [
-    '"Iter.","Eval.","Acceptance rate","Time m:s"',
+    '"Iter.","Eval.","Acceptance rate","Time"',
     '1,127,7.87401574803149595e-03,0:00.0',
     '2,167,0.0119760479,0:00.0',
     '3,209,0.014354067,0:00.0',
diff --git a/pints/tests/test_mcmc_adaptive.py b/pints/tests/test_mcmc_adaptive.py
index 77de5597..a89a4bd8 100755
--- a/pints/tests/test_mcmc_adaptive.py
+++ b/pints/tests/test_mcmc_adaptive.py
@@ -145,7 +145,7 @@ class TestAdaptiveCovarianceMC(unittest.TestCase):
         self.assertIn('Accept.', text)
         self.assertIn('Eval.', text)
         self.assertIn('Iter.', text)
-        self.assertIn('Time m:s', text)
+        self.assertIn('Time', text)
 
     def test_replace(self):
         # Tests the replace() method
diff --git a/pints/tests/test_mcmc_controller.py b/pints/tests/test_mcmc_controller.py
index fb03de62..98220805 100755
--- a/pints/tests/test_mcmc_controller.py
+++ b/pints/tests/test_mcmc_controller.py
@@ -14,6 +14,7 @@ import unittest
 import unittest.mock
 import numpy as np
 import numpy.testing as npt
+import warnings
 
 from shared import StreamCapture, TemporaryDirectory
 
@@ -24,7 +25,7 @@ LOG_SCREEN = [
     'Using Haario-Bardenet adaptive covariance MCMC',
     'Generating 3 chains.',
     'Running in sequential mode.',
-    'Iter. Eval. Accept.   Accept.   Accept.   Time m:s',
+    'Iter. Eval. Accept.   Accept.   Accept.   Time    ',
     '0     3      0         0         0          0:00.0',
     '1     6      0         0         0.5        0:00.0',
     '2     9      0         0         0.333      0:00.0',
@@ -35,7 +36,7 @@ LOG_SCREEN = [
 ]
 
 LOG_FILE = [
-    'Iter. Eval. Accept.   Accept.   Accept.   Time m:s',
+    'Iter. Eval. Accept.   Accept.   Accept.   Time    ',
     '0     3      0         0         0          0:00.0',
     '1     6      0         0         0.5        0:00.0',
     '2     9      0         0         0.333      0:00.0',
@@ -791,8 +792,11 @@ class TestMCMCController(unittest.TestCase):
 
     def test_deprecated_alias(self):
 
-        mcmc = pints.MCMCSampling(
-            self.log_posterior, 1, [self.real_parameters])
+        with warnings.catch_warnings(record=True) as w:
+            mcmc = pints.MCMCSampling(
+                self.log_posterior, 1, [self.real_parameters])
+        self.assertEqual(len(w), 1)
+        self.assertIn('deprecated', str(w[-1].message))
         self.assertIsInstance(mcmc, pints.MCMCController)
 
     def test_exception_on_multi_use(self):
diff --git a/pints/tests/test_nested_controller.py b/pints/tests/test_nested_controller.py
index eb238962..e6efdfe6 100755
--- a/pints/tests/test_nested_controller.py
+++ b/pints/tests/test_nested_controller.py
@@ -160,7 +160,7 @@ class TestNestedController(unittest.TestCase):
         self.assertEqual(lines[1], 'Number of active points: 400')
         self.assertEqual(lines[2], 'Total number of iterations: 20')
         self.assertEqual(lines[3], 'Total number of posterior samples: 2')
-        self.assertEqual(lines[4], ('Iter. Eval. Time m:s Delta_log(z) ' +
+        self.assertEqual(lines[4], ('Iter. Eval. Time     Delta_log(z) ' +
                                     'Acceptance rate'))
         pattern = re.compile('[0-9]+[ ]+[0-9]+[ ]+[0-9]{1}:[0-9]{2}.[0-9]{1}')
         for line in lines[5:]:
@@ -182,7 +182,7 @@ class TestNestedController(unittest.TestCase):
                     lines = f.read().splitlines()
             self.assertEqual(c.text(), '')
         self.assertEqual(len(lines), 23)
-        self.assertEqual(lines[0], ('Iter. Eval. Time m:s Delta_log(z) ' +
+        self.assertEqual(lines[0], ('Iter. Eval. Time     Delta_log(z) ' +
                                     'Acceptance rate'))
         pattern = re.compile('[0-9]+[ ]+[0-9]+[ ]+[0-9]{1}:[0-9]{2}.[0-9]{1}')
         for line in lines[5:]:
diff --git a/pints/tests/test_opt_adam.py b/pints/tests/test_opt_adam.py
index eba59a71..39f541c4 100755
--- a/pints/tests/test_opt_adam.py
+++ b/pints/tests/test_opt_adam.py
@@ -19,15 +19,15 @@ debug = False
 method = pints.Adam
 
 
-log_1 = '''
-Minimising error measure
-Using Adam
-Running in sequential mode.
-Iter. Eval. Best      Current   b1        b2        Time m:s
-0     1      0.02      0.02      0.9       0.999      0:00.0
-1     2      5e-17     5e-17     0.81      0.998001   0:00.0
-2     3      5e-17     0.00898   0.729     0.997003   0:00.0
-'''.strip()
+log_1 = '\n'.join((
+    'Minimising error measure',
+    'Using Adam',
+    'Running in sequential mode.',
+    'Iter. Eval. Best      Current   b1        b2        Time    ',
+    '0     1      0.02      0.02      0.9       0.999      0:00.0',
+    '1     2      5e-17     5e-17     0.81      0.998001   0:00.0',
+    '2     3      5e-17     0.00898   0.729     0.997003   0:00.0',
+))
 
 
 class TestAdam(unittest.TestCase):
diff --git a/pints/tests/test_opt_controller.py b/pints/tests/test_opt_controller.py
index dec7cc15..eae324d2 100755
--- a/pints/tests/test_opt_controller.py
+++ b/pints/tests/test_opt_controller.py
@@ -251,7 +251,7 @@ class TestOptimisationController(unittest.TestCase):
         self.assertEqual(lines[2], 'Running in sequential mode.')
         self.assertEqual(lines[3], 'Population size: 6')
         self.assertEqual(lines[4],
-                         'Iter. Eval. Best      Current   Time m:s')
+                         'Iter. Eval. Best      Current   Time    ')
         self.assertEqual(lines[5][:-3],
                          '0     3     -4.140462 -4.140462   0:0')
         self.assertEqual(lines[6][:-3],
@@ -290,7 +290,7 @@ class TestOptimisationController(unittest.TestCase):
         self.assertEqual(lines[2], 'Running in sequential mode.')
         self.assertEqual(lines[3], 'Population size: 4')
         self.assertEqual(lines[4],
-                         'Iter. Eval. Best      Current   Time m:s')
+                         'Iter. Eval. Best      Current   Time    ')
         self.assertEqual(lines[5][:-3],
                          '0     4      6.471867  6.471867   0:0')
         self.assertEqual(lines[6][:-3],
diff --git a/pints/tests/test_opt_irpropmin.py b/pints/tests/test_opt_irpropmin.py
index cc2dbb5a..4a4a3089 100755
--- a/pints/tests/test_opt_irpropmin.py
+++ b/pints/tests/test_opt_irpropmin.py
@@ -19,25 +19,25 @@ debug = False
 method = pints.IRPropMin
 
 
-log_1 = '''
-Minimising error measure
-Using iRprop-
-Running in sequential mode.
-Iter. Eval. Best      Current   Min. step Max. step Bound corr. Time m:s
-0     1      0.02      0.02      0.12      0.12                   0:00.0
-1     2      0.0008    0.0008    0.06      0.06                   0:00.0
-'''.strip()
-
-log_2 = '''
-Minimising error measure
-Using iRprop-
-Running in sequential mode.
-Iter. Eval. Best      Current   Min. step Max. step Bound corr. Time m:s
-0     1      0.02      0.02      0.11      0.11                   0:00.0
-1     2      0.0002    0.0002    0.055     0.055                  0:00.0
-2     3      0.0002    0.0002    0.055     0.055                  0:00.0
-3     4      0.0002    0.00405   0.03      0.03                   0:00.0
-'''.strip()
+log_1 = '\n'.join((
+    'Minimising error measure',
+    'Using iRprop-',
+    'Running in sequential mode.',
+    'Iter. Eval. Best      Current   Min. step Max. step Bound corr. Time    ',
+    '0     1      0.02      0.02      0.12      0.12                   0:00.0',
+    '1     2      0.0008    0.0008    0.06      0.06                   0:00.0',
+))
+
+log_2 = '\n'.join((
+    'Minimising error measure',
+    'Using iRprop-',
+    'Running in sequential mode.',
+    'Iter. Eval. Best      Current   Min. step Max. step Bound corr. Time    ',
+    '0     1      0.02      0.02      0.11      0.11                   0:00.0',
+    '1     2      0.0002    0.0002    0.055     0.055                  0:00.0',
+    '2     3      0.0002    0.0002    0.055     0.055                  0:00.0',
+    '3     4      0.0002    0.00405   0.03      0.03                   0:00.0',
+))
 
 
 class TestIRPropMin(unittest.TestCase):
diff --git a/pints/tests/test_opt_nelder_mead.py b/pints/tests/test_opt_nelder_mead.py
index 8ea16949..89f85ad1 100755
--- a/pints/tests/test_opt_nelder_mead.py
+++ b/pints/tests/test_opt_nelder_mead.py
@@ -170,7 +170,7 @@ class TestNelderMead(unittest.TestCase):
             'Minimising error measure',
             'Using Nelder-Mead',
             'Running in sequential mode.',
-            'Iter. Eval. Best      Current   Time m:s',
+            'Iter. Eval. Best      Current   Time',
             '0     3      865.9531  865.9531   0:00.0',
             '1     4      832.5452  832.5452   0:00.0',
             '2     5      832.5452  832.5452   0:00.0',
diff --git a/pints/tests/test_opt_pso.py b/pints/tests/test_opt_pso.py
index 9b9795a2..29b70a44 100755
--- a/pints/tests/test_opt_pso.py
+++ b/pints/tests/test_opt_pso.py
@@ -130,7 +130,7 @@ class TestPSO(unittest.TestCase):
         self.assertEqual(
             lines[2], 'Running in parallel with 4 worker processes.')
         self.assertEqual(lines[3], 'Population size: 6')
-        self.assertEqual(lines[4], 'Iter. Eval. Best      Current   Time m:s')
+        self.assertEqual(lines[4], 'Iter. Eval. Best      Current   Time    ')
 
         pint = '[0-9]+[ ]+'
         pflt = '[0-9.-]+[ ]+'
@@ -158,7 +158,7 @@ class TestPSO(unittest.TestCase):
         self.assertEqual(
             lines[0],
             'Iter. Eval. Best      Current   f0        f1        f2        '
-            'f3        f4        f5        Time m:s'
+            'f3        f4        f5        Time    '
         )
 
         pattern = re.compile(pint * 2 + pflt * 8 + ptim)