closing 209 : added info message for computation time (#222)

* added info message for computation time

* fixed lint issues

Co-authored-by: ragrawal <ragrawal@varomoney.com>

Author: ragrawal

README.rst

@@ -441,10 +441,26 @@ can be easily serialized.
            [1.60943791],
            [1.38629436]])
 
+Changing Logging level
+***********************************
+
+You can change log level to info to print time take to fit/transform features. Setting it to higher level will stop printing elapsed time.
+Below example shows how to change logging level.
+
+
+    >>> import logging
+    >>> logging.getLogger('sklearn_pandas').setLevel(logging.INFO)
 
 
 Changelog
 ---------
+
+2.0.3 (2020-11-06)
+******************
+
+* Added elapsed time information for each feature
+
+
 2.0.2 (2020-10-01)
 ******************
 

sklearn_pandas/__init__.py

@@ -1,4 +1,7 @@
-__version__ = '2.0.2'
+__version__ = '2.0.3'
+
+import logging
+logger = logging.getLogger(__name__)
 
 from .dataframe_mapper import DataFrameMapper  # NOQA
 from .features_generator import gen_features  # NOQA

sklearn_pandas/dataframe_mapper.py

@@ -1,12 +1,14 @@
 import contextlib
 
+from datetime import datetime
 import pandas as pd
 import numpy as np
 from scipy import sparse
 from sklearn.base import BaseEstimator, TransformerMixin
 
 from .cross_validation import DataWrapper
 from .pipeline import make_transformer_pipeline, _call_fit, TransformerPipeline
+from . import logger
 
 string_types = text_type = str
 
@@ -31,6 +33,10 @@ def _build_feature(columns, transformers, options={}):
     return (columns, _build_transformer(transformers), options)
 
 
+def _elapsed_secs(t1):
+    return (datetime.now()-t1).total_seconds()
+
+
 def _get_feature_names(estimator):
     """
     Attempt to extract feature names based on a given estimator
@@ -107,7 +113,6 @@ def __init__(self, features, default=False, sparse=False, df_out=False,
         self.input_df = input_df
         self.drop_cols = [] if drop_cols is None else drop_cols
         self.transformed_names_ = []
-
         if (df_out and (sparse or default)):
             raise ValueError("Can not use df_out with sparse or default")
 
@@ -208,13 +213,16 @@ def fit(self, X, y=None):
 
         """
         self._build()
+
         for columns, transformers, options in self.built_features:
+            t1 = datetime.now()
             input_df = options.get('input_df', self.input_df)
 
             if transformers is not None:
                 with add_column_names_to_exception(columns):
                     Xt = self._get_col_subset(X, columns, input_df)
                     _call_fit(transformers.fit, Xt, y)
+            logger.info(f"[FIT] {columns}: {_elapsed_secs(t1)} secs")
 
         # handle features not explicitly selected
         if self.built_default:  # not False and not None
@@ -304,14 +312,24 @@ def _transform(self, X, y=None, do_fit=False):
             # strings; we don't care because pandas
             # will handle either.
             Xt = self._get_col_subset(X, columns, input_df)
+
             if transformers is not None:
                 with add_column_names_to_exception(columns):
                     if do_fit and hasattr(transformers, 'fit_transform'):
+                        t1 = datetime.now()
                         Xt = _call_fit(transformers.fit_transform, Xt, y)
+                        logger.info(f"[FIT_TRANSFORM] {columns}: {_elapsed_secs(t1)} secs")  # NOQA
                     else:
                         if do_fit:
+                            t1 = datetime.now()
                             _call_fit(transformers.fit, Xt, y)
+                            logger.info(
+                                f"[FIT] {columns}: {_elapsed_secs(t1)} secs")
+
+                        t1 = datetime.now()
                         Xt = transformers.transform(Xt)
+                        logger.info(f"[TRANSFORM] {columns}: {_elapsed_secs(t1)} secs")  # NOQA
+
             extracted.append(_handle_feature(Xt))
 
             alias = options.get('alias')
@@ -339,6 +357,7 @@ def _transform(self, X, y=None, do_fit=False):
                 # if not applying a default transformer,
                 # keep column names unmodified
                 self.transformed_names_ += unsel_cols
+
             extracted.append(_handle_feature(Xt))
 
         # combine the feature outputs into one array.

tests/test_dataframe_mapper.py

@@ -152,6 +152,20 @@ def test_transformed_names_binarizer(complex_dataframe):
     assert mapper.transformed_names_ == ['target_a', 'target_b', 'target_c']
 
 
+def test_logging(caplog, complex_dataframe):
+    """
+    Get transformed names of features in `transformed_names` attribute
+    for a transformation that multiplies the number of columns
+    """
+    import logging
+    logger = logging.getLogger('sklearn_pandas')
+    logger.setLevel(logging.INFO)
+    df = complex_dataframe
+    mapper = DataFrameMapper([('target', LabelBinarizer())])
+    mapper.fit_transform(df)
+    assert '[FIT_TRANSFORM] target:' in caplog.text
+
+
 def test_transformed_names_binarizer_unicode():
     df = pd.DataFrame({'target': [u'ñ', u'á', u'é']})
     mapper = DataFrameMapper([('target', LabelBinarizer())])