Adding logging in a couple places in urbanchoice.

urbansim/urbanchoice/interaction.py

@@ -4,6 +4,7 @@
 Used for location choice models.
 
 """
+import logging
 import random
 import sys
 import time
@@ -15,7 +16,8 @@
 import nl
 import pmat
 
-GPU = 0
+logger = logging.getLogger(__name__)
+GPU = False
 
 
 def enable_gpu():
@@ -38,6 +40,10 @@ def add_fnames(fnames, est_params):
 # and simulation.
 def mnl_interaction_dataset(choosers, alternatives, SAMPLE_SIZE,
                             chosenalts=None):
+    logger.debug((
+        'start: compute MNL interaction dataset with {} choosers, '
+        '{} alternatives, and sample_size={}'
+        ).format(len(choosers), len(alternatives), SAMPLE_SIZE))
     # filter choosers and their current choices if they point to
     # something that isn't in the alternatives table
     if chosenalts is not None:
@@ -47,10 +53,10 @@ def mnl_interaction_dataset(choosers, alternatives, SAMPLE_SIZE,
         except:
             removing = None
         if removing:
-            print (
+            logger.info((
                 "Removing {} choice situations because chosen "
                 "alt doesn't exist"
-            ).format(removing)
+            ).format(removing))
             choosers = choosers[isin]
             chosenalts = chosenalts[isin]
 
@@ -100,6 +106,7 @@ def mnl_interaction_dataset(choosers, alternatives, SAMPLE_SIZE,
     chosen = np.zeros((numchoosers, SAMPLE_SIZE))
     chosen[:, 0] = 1
 
+    logger.debug('finish: compute MNL interaction dataset')
     return sample, alts_sample, chosen
 
 

urbansim/urbanchoice/mnl.py

@@ -4,13 +4,19 @@
 ``urbansim.models.lcm``.
 
 """
+import logging
+
 import numpy as np
 import pandas as pd
 import scipy.optimize
 
 import pmat
 from pmat import PMAT
 
+from ..utils.logutil import log_start_finish
+
+logger = logging.getLogger(__name__)
+
 # right now MNL can only estimate location choice models, where every equation
 # is the same
 # it might be better to use stats models for a non-location choice problem
@@ -20,6 +26,7 @@
 
 
 def mnl_probs(data, beta, numalts):
+    logging.debug('start: calculate MNL probabilities')
     clamp = data.typ == 'numpy'
     utilities = beta.multiply(data)
     if numalts == 0:
@@ -39,6 +46,7 @@ def mnl_probs(data, beta, numalts):
     if clamp:
         probs.clamptomin(1e-300)
 
+    logging.debug('finish: calculate MNL probabilities')
     return probs
 
 
@@ -55,6 +63,7 @@ def get_standard_error(hessian):
 
 def mnl_loglik(beta, data, chosen, numalts, weights=None, lcgrad=False,
                stderr=0):
+    logger.debug('start: calculate MNL log-likelihood')
     numvars = beta.size
     numobs = data.size() / numvars / numalts
 
@@ -103,10 +112,14 @@ def mnl_loglik(beta, data, chosen, numalts, weights=None, lcgrad=False,
         loglik = loglik.get_mat()[0, 0]
         gradarr = np.reshape(gradarr.get_mat(), (1, gradarr.size()))[0]
 
+    logger.debug('finish: calculate MNL log-likelihood')
     return -1 * loglik, -1 * gradarr
 
 
 def mnl_simulate(data, coeff, numalts, GPU=False, returnprobs=False):
+    logger.debug(
+        'start: MNL simulation with len(data)={} and numalts={}'.format(
+            len(data), numalts))
     atype = 'numpy' if not GPU else 'cuda'
 
     data = np.transpose(data)
@@ -127,6 +140,7 @@ def mnl_simulate(data, coeff, numalts, GPU=False, returnprobs=False):
     r = pmat.random(probs.size() / numalts)
     choices = probs.subtract(r, inplace=True).firstpositive(axis=0)
 
+    logger.debug('finish: MNL simulation')
     return choices.get_mat()
 
 
@@ -156,6 +170,9 @@ def mnl_estimate(data, chosen, numalts, GPU=False, coeffrange=(-3, 3),
         'T-Score'.
 
     """
+    logger.debug(
+        'start: MNL fit with len(data)={} and numalts={}'.format(
+            len(data), numalts))
     atype = 'numpy' if not GPU else 'cuda'
 
     numvars = data.shape[1]
@@ -175,15 +192,16 @@ def mnl_estimate(data, chosen, numalts, GPU=False, coeffrange=(-3, 3),
         beta = np.zeros(numvars)
     bounds = np.array([coeffrange for i in range(numvars)])
 
-    args = (data, chosen, numalts, weights, lcgrad)
-    bfgs_result = scipy.optimize.fmin_l_bfgs_b(mnl_loglik,
-                                               beta,
-                                               args=args,
-                                               fprime=None,
-                                               factr=1e5,
-                                               approx_grad=False,
-                                               bounds=bounds
-                                               )
+    with log_start_finish('scipy optimization for MNL fit', logger):
+        args = (data, chosen, numalts, weights, lcgrad)
+        bfgs_result = scipy.optimize.fmin_l_bfgs_b(mnl_loglik,
+                                                   beta,
+                                                   args=args,
+                                                   fprime=None,
+                                                   factr=1e5,
+                                                   approx_grad=False,
+                                                   bounds=bounds
+                                                   )
     beta = bfgs_result[0]
     stderr = mnl_loglik(
         beta, data, chosen, numalts, weights, stderr=1, lcgrad=lcgrad)
@@ -203,4 +221,5 @@ def mnl_estimate(data, chosen, numalts, GPU=False, coeffrange=(-3, 3),
         'Std. Error': stderr,
         'T-Score': beta / stderr})
 
+    logger.debug('finish: MNL fit')
     return log_likelihood, fit_parameters