Add _measure_time time function

src/pymongo_migrate/mongo_migrate.py

@@ -1,5 +1,6 @@
 import datetime
 import logging
+import time
 from dataclasses import asdict, dataclass
 from pathlib import Path
 from typing import Iterator, Optional
@@ -32,6 +33,29 @@ def _deserialize(data, cls):
     return cls(**data)
 
 
+class MeasureTime:
+    def __init__(self):
+        self.start = None
+        self.stop = None
+
+    @staticmethod
+    def time() -> float:
+        return time.time()
+
+    @property
+    def elapsed(self) -> Optional[float]:
+        if self.start is None:
+            return None
+        return (self.stop or self.time()) - self.start
+
+    def __enter__(self):
+        self.start = self.time()
+        return self
+
+    def __exit__(self, exc_type, exc_val, exc_tb):
+        self.stop = self.time()
+
+
 @dataclass
 class MongoMigrate:
     client: pymongo.MongoClient
@@ -103,7 +127,7 @@ def migrate(self, migration_name: Optional[str] = None):
             self.logger.debug("Migration target already applied, assuming downgrade")
             self.downgrade(migration_name)
         else:
-            self.logger.debug("Migration target already applied, assuming upgrade")
+            self.logger.debug("Migration target not applied, assuming upgrade")
             self.upgrade(migration_name)
 
     def upgrade(self, migration_name: Optional[str] = None):
@@ -123,7 +147,9 @@ def upgrade(self, migration_name: Optional[str] = None):
                 )
                 continue
             self.logger.info("Running upgrade migration %r", migration.name)
-            migration.upgrade(self.db)
+            with MeasureTime() as mt:
+                migration.upgrade(self.db)
+                self.logger.info(f"Execution time of {migration.name}: {mt.elapsed()}s")
             migration_state.applied = dt()
             self.set_state(migration_state)
             if migration.name == migration_name:
@@ -148,7 +174,9 @@ def downgrade(self, migration_name: Optional[str]):
                 )
                 continue
             self.logger.info("Running downgrade migration %r", migration.name)
-            migration.downgrade(self.db)
+            with MeasureTime() as mt:
+                migration.downgrade(self.db)
+                self.logger.info(f"Execution time of {migration.name}: {mt.elapsed()}s")
             migration_state.applied = None
             self.set_state(migration_state)