Repository: autogluon/autogluon
Pull request: Tabular: Added time_limit=None warning
*Issue #, if available:*
#1096 

*Description of changes:*

- Added warning when time_limit=None and data is large.
- Hid NumExpr log statement caused by pandas.

By submitting this pull request, I confirm that you can use, modify, copy, and redistribute this contribution, under the terms of your choice.


Problem statement:
Training with `presets='best_quality'` takes too long
The following code takes ~2h on a cpu machine, which is reasonable. 

```
!kaggle competitions download california-house-prices
!unzip california-house-prices.zip

from autogluon.tabular import TabularDataset, TabularPredictor
import numpy as np 

label = 'Sold Price'
large_values = ['Lot', 'Total interior livable area', 'Tax assessed value',
                'Annual tax amount', 'Listed Price']
train_data = TabularDataset('train.csv')
for c in large_values + [label]:
    train_data[c] = np.log(train_data[c]+1)

predictor = TabularPredictor(label=label).fit(
    train_data.drop(columns=['Id']))
```

However, if enable `presets='best_quality'`, it will a significant more time. I stopped the training after about 5hours, I guess other users would do a similar thing. 

We could improve the user experience by 

1. report an estimated remaining time, not necessary to be accurate, but encourage users to wait
2. may generate a warning that "you may consider to use gpu to accelerate your training, and here is how", especially when gpus are available

Hints from issue discussion:
In general, `best_quality` will take ~20x longer than default, so if default takes 2 hours, `best_quality` will take 40 hours.

Currently it is somewhat difficult to get an estimate of total training time remaining, and this will be especially true for more diverse ensembles. I think a practical first step would be to add a log message to the user when training without specifying `time_limit` if there are many rows in the data (say >100,000) that training time may take a long time and it is recommended to specify a `time_limit`.

Commit message: removed print statement

Patch to review:
diff --git a/core/src/autogluon/core/utils/utils.py b/core/src/autogluon/core/utils/utils.py
index 21df4a0c96f1..d58f71c750e4 100644
--- a/core/src/autogluon/core/utils/utils.py
+++ b/core/src/autogluon/core/utils/utils.py
@@ -8,6 +8,7 @@
 import sys
 from typing import Callable
 from datetime import datetime
+from functools import wraps
 
 import numpy as np
 import pandas as pd
@@ -735,6 +736,22 @@ def _get_safe_fi_batch_count(X, num_features, X_transformed=None, max_memory_rat
     return feature_batch_count
 
 
+def suspend_logging(func):
+    """hides any logs within the called func that are below warnings"""
+    @wraps(func)
+    def inner(*args, **kwargs):
+        root_logger = logging.getLogger()
+        previous_log_level = root_logger.getEffectiveLevel()
+        try:
+            root_logger.setLevel(max(30, previous_log_level))
+            return func(*args, **kwargs)
+        finally:
+            root_logger.setLevel(previous_log_level)
+    return inner
+
+
+# suspect_logging to hide the Pandas log of NumExpr initialization
+@suspend_logging
 def get_approximate_df_mem_usage(df: DataFrame, sample_ratio=0.2):
     if sample_ratio >= 1:
         return df.memory_usage(deep=True)
@@ -753,6 +770,7 @@ def get_approximate_df_mem_usage(df: DataFrame, sample_ratio=0.2):
                 sample_ratio_cat = num_categories_sample / num_categories
                 memory_usage[column] = df[column].cat.codes.dtype.itemsize * num_rows + df[column].cat.categories[:num_categories_sample].memory_usage(deep=True) / sample_ratio_cat
         if columns_inexact:
+            # this line causes NumExpr log, suspend_logging is used to hide the log.
             memory_usage_inexact = df[columns_inexact].head(num_rows_sample).memory_usage(deep=True)[columns_inexact] / sample_ratio
             memory_usage = memory_usage_inexact.combine_first(memory_usage)
         return memory_usage
diff --git a/tabular/src/autogluon/tabular/predictor/predictor.py b/tabular/src/autogluon/tabular/predictor/predictor.py
index cfd17b7d10ce..59a523b81a04 100644
--- a/tabular/src/autogluon/tabular/predictor/predictor.py
+++ b/tabular/src/autogluon/tabular/predictor/predictor.py
@@ -18,7 +18,7 @@
 from autogluon.core.utils import get_pred_from_proba_df, set_logger_verbosity
 from autogluon.core.utils.loaders import load_pkl
 from autogluon.core.utils.savers import save_pkl
-from autogluon.core.utils.utils import setup_outputdir, default_holdout_frac
+from autogluon.core.utils.utils import setup_outputdir, default_holdout_frac, get_approximate_df_mem_usage
 from autogluon.core.utils.decorators import apply_presets
 
 from ..configs.hyperparameter_configs import get_hyperparameter_config
@@ -690,6 +690,13 @@ def fit(self,
                 ag_args_ensemble = {}
             ag_args_ensemble['save_bag_folds'] = kwargs['_save_bag_folds']
 
+        if time_limit is None:
+            mb_mem_usage_train_data = get_approximate_df_mem_usage(train_data, sample_ratio=0.2).sum() / 1e6
+            num_rows_train = len(train_data)
+            if mb_mem_usage_train_data >= 50 or num_rows_train >= 100000:
+                logger.log(20, f'Warning: Training may take a very long time because `time_limit` was not specified and `train_data` is large ({num_rows_train} samples, {round(mb_mem_usage_train_data, 2)} MB).')
+                logger.log(20, f'\tConsider setting `time_limit` to ensure training finishes within an expected duration or experiment with a small portion of `train_data` to identify an ideal `hyperparameters` configuration.')
+
         core_kwargs = {'ag_args': ag_args, 'ag_args_ensemble': ag_args_ensemble, 'ag_args_fit': ag_args_fit, 'excluded_model_types': excluded_model_types}
         self._learner.fit(X=train_data, X_val=tuning_data, X_unlabeled=unlabeled_data,
                           holdout_frac=holdout_frac, num_bag_folds=num_bag_folds, num_bag_sets=num_bag_sets, num_stack_levels=num_stack_levels,
diff --git a/tabular/src/autogluon/tabular/trainer/abstract_trainer.py b/tabular/src/autogluon/tabular/trainer/abstract_trainer.py
index 22a2c3b5d6cb..941b2699a9d0 100644
--- a/tabular/src/autogluon/tabular/trainer/abstract_trainer.py
+++ b/tabular/src/autogluon/tabular/trainer/abstract_trainer.py
@@ -174,12 +174,11 @@ def get_max_level(self, stack_name: str = None, models: List[str] = None) -> int
         else:
             return -1
 
-    # TODO: Rename method for v0.1
-    def get_models(self, hyperparameters: dict, **kwargs) -> Tuple[List[AbstractModel], dict]:
+    def construct_model_templates(self, hyperparameters: dict, **kwargs) -> Tuple[List[AbstractModel], dict]:
         """Constructs a list of unfit models based on the hyperparameters dict."""
         raise NotImplementedError
 
-    def get_models_distillation(self, hyperparameters: dict, **kwargs) -> Tuple[List[AbstractModel], dict]:
+    def construct_model_templates_distillation(self, hyperparameters: dict, **kwargs) -> Tuple[List[AbstractModel], dict]:
         """Constructs a list of unfit models based on the hyperparameters dict for softclass distillation."""
         raise NotImplementedError
 
@@ -233,6 +232,7 @@ def train_multi_levels(self, X, y, hyperparameters: dict, X_val=None, y_val=None
         if relative_stack:
             if level_start != 1:
                 raise AssertionError(f'level_start must be 1 when `relative_stack=True`. (level_start = {level_start})')
+            level_add = 0
             if base_model_names:
                 max_base_model_level = self.get_max_level(models=base_model_names)
                 level_start = max_base_model_level + 1
@@ -251,6 +251,8 @@ def train_multi_levels(self, X, y, hyperparameters: dict, X_val=None, y_val=None
         aux_kwargs = {} if aux_kwargs is None else aux_kwargs.copy()
 
         model_names_fit = []
+        if level_start != level_end:
+            logger.log(20, f'AutoGluon will fit {level_end - level_start + 1} stack levels (L{level_start} to L{level_end}) ...')
         for level in range(level_start, level_end + 1):
             core_kwargs_level = core_kwargs.copy()
             aux_kwargs_level = aux_kwargs.copy()
@@ -314,7 +316,7 @@ def stack_new_level_core(self, X, y, models: Union[List[AbstractModel], dict], X
         The data provided in this method should not contain stack features, as they will be automatically generated if necessary.
         """
         if get_models_func is None:
-            get_models_func = self.get_models
+            get_models_func = self.construct_model_templates
         if base_model_names is None:
             base_model_names = []
         if not self.bagged_mode and level != 1:
@@ -359,6 +361,7 @@ def stack_new_level_core(self, X, y, models: Union[List[AbstractModel], dict], X
                     for model_name in model_args_fit if 'hyperparameter_tune_kwargs' in model_args_fit[model_name]
                 }
                 kwargs['hyperparameter_tune_kwargs'] = hyperparameter_tune_kwargs
+        logger.log(20, f'Fitting {len(models)} L{level} models ...')
         X_init = self.get_inputs_to_stacker(X, base_models=base_model_names, fit=True)
         if X_val is not None:
             X_val = self.get_inputs_to_stacker(X_val, base_models=base_model_names, fit=False)
@@ -832,7 +835,7 @@ def unpersist_models(self, model_names='all') -> list:
 
     def generate_weighted_ensemble(self, X, y, level, base_model_names, k_fold=0, n_repeats=1, stack_name=None, hyperparameters=None, time_limit=None, name_suffix: str = None, save_bag_folds=None, check_if_best=True, child_hyperparameters=None, get_models_func=None) -> List[str]:
         if get_models_func is None:
-            get_models_func = self.get_models
+            get_models_func = self.construct_model_templates
         if len(base_model_names) == 0:
             logger.log(20, 'No base models to train on, skipping weighted ensemble...')
             return []
@@ -910,6 +913,7 @@ def _train_and_save(self, X, y, model: AbstractModel, X_val=None, y_val=None, st
         time_limit = model_fit_kwargs.get('time_limit', None)
         model_names_trained = []
         try:
+            fit_log_message = f'Fitting model: {model.name} ...'
             if time_limit is not None:
                 if time_limit <= 0:
                     logger.log(15, f'Skipping {model.name} due to lack of time remaining.')
@@ -918,9 +922,8 @@ def _train_and_save(self, X, y, model: AbstractModel, X_val=None, y_val=None, st
                     time_left_total = self._time_limit - (fit_start_time - self._time_train_start)
                 else:
                     time_left_total = time_limit
-                logger.log(20, f'Fitting model: {model.name} ... Training model for up to {round(time_limit, 2)}s of the {round(time_left_total, 2)}s of remaining time.')
-            else:
-                logger.log(20, f'Fitting model: {model.name} ...')
+                fit_log_message += f' Training model for up to {round(time_limit, 2)}s of the {round(time_left_total, 2)}s of remaining time.'
+            logger.log(20, fit_log_message)
             model = self._train_single(X, y, model, X_val, y_val, **model_fit_kwargs)
             fit_end_time = time.time()
             if self.weight_evaluation:
@@ -1995,10 +1998,10 @@ def distill(self, X=None, y=None, X_val=None, y_val=None, X_unlabeled=None,
 
         core_kwargs = {
             'stack_name': self.distill_stackname,
-            'get_models_func': self.get_models_distillation,
+            'get_models_func': self.construct_model_templates_distillation,
         }
         aux_kwargs = {
-            'get_models_func': self.get_models_distillation,
+            'get_models_func': self.construct_model_templates_distillation,
             'check_if_best': False,
         }
 
diff --git a/tabular/src/autogluon/tabular/trainer/auto_trainer.py b/tabular/src/autogluon/tabular/trainer/auto_trainer.py
index e0dcf2e8ad8e..1dd70f7d88e6 100644
--- a/tabular/src/autogluon/tabular/trainer/auto_trainer.py
+++ b/tabular/src/autogluon/tabular/trainer/auto_trainer.py
@@ -14,7 +14,7 @@
 
 # This Trainer handles model training details
 class AutoTrainer(AbstractTrainer):
-    def get_models(self, hyperparameters, **kwargs):
+    def construct_model_templates(self, hyperparameters, **kwargs):
         path = kwargs.pop('path', self.path)
         problem_type = kwargs.pop('problem_type', self.problem_type)
         eval_metric = kwargs.pop('eval_metric', self.eval_metric)
@@ -53,7 +53,7 @@ def fit(self, X, y, hyperparameters, X_val=None, y_val=None, X_unlabeled=None, f
                                        feature_prune=feature_prune,
                                        num_stack_levels=num_stack_levels, time_limit=time_limit, core_kwargs=core_kwargs)
 
-    def get_models_distillation(self, hyperparameters, **kwargs):
+    def construct_model_templates_distillation(self, hyperparameters, **kwargs):
         path = kwargs.pop('path', self.path)
         problem_type = kwargs.pop('problem_type', self.problem_type)
         eval_metric = kwargs.pop('eval_metric', self.eval_metric)


Code review comments:
diff_hunk: @@ -690,6 +690,13 @@ def fit(self,
                 ag_args_ensemble = {}
             ag_args_ensemble['save_bag_folds'] = kwargs['_save_bag_folds']
 
+        if time_limit is None:
+            mb_mem_usage_train_data = get_approximate_df_mem_usage(train_data, sample_ratio=0.2).sum() / 1e6
+            num_rows_train = len(train_data)
+            if mb_mem_usage_train_data >= 50 or num_rows_train >= 100000:
+                logger.log(20, f'Warning: Training may take a very long time because `time_limit` was not specified and `train_data` is large ({num_rows_train} samples, {round(mb_mem_usage_train_data, 2)} MB).')
+                logger.log(20, f'\tConsider setting `time_limit` to ensure training finishes within an expected duration or experiment with a small portion of `train_data` to identify an ideal `hyperparameters` configuration.')
path: tabular/src/autogluon/tabular/predictor/predictor.py
text: @user1:
might also mention `presets` in addition to  `hyperparameters`

@author:
added

diff_hunk: @@ -735,6 +736,22 @@ def _get_safe_fi_batch_count(X, num_features, X_transformed=None, max_memory_rat
     return feature_batch_count
 
 
+def suspend_logging(func):
+    """hides any logs within the called func that are below warnings"""
+    @wraps(func)
+    def inner(*args, **kwargs):
+        root_logger = logging.getLogger()
+        previous_log_level = root_logger.getEffectiveLevel()
+        try:
+            root_logger.setLevel(max(30, previous_log_level))
+            return func(*args, **kwargs)
+        finally:
+            root_logger.setLevel(previous_log_level)
+    return inner
+
+
+# suspect_logging to hide the Pandas log of NumExpr initialization
path: core/src/autogluon/core/utils/utils.py
text: @user1:
suspend not suspect

@author:
fixed