Add debug logging to odo.

[groutr]

This was something that I added to an old fork I had of odo. I found it useful for understanding the route of transformations in odo and it also helped me understand an issue that I was having at the time.

Is logging like this something that is desirable for odo? The log will record the route that odo took transforming from source to destination.

In [1]: import odo

In [2]: import logging

In [3]: import pandas as pd

In [4]: logging.basicConfig(level=logging.DEBUG)

In [5]: a = list(range(10))

In [6]: odo.odo(a, pd.DataFrame)
DEBUG:odo.core:[list -> ndarray] list_to_numpy ({'dshape': dshape("10 * int64")})
DEBUG:odo.core:[ndarray -> DataFrame] numpy_to_dataframe ({'dshape': dshape("10 * int64")})
Out[6]: 
   0
0  0
1  1
2  2
3  3
4  4
5  5
6  6
7  7
8  8
9  9

[llllllllll]

Thanks for posting this PR!

I think this could help with debugging in some cases but I am worried about the overhead when idle. Can you post some profiling data to see how much time is spent in dropped log lines?

[llllllllll]

why are you explicitly logging registering a handler for this?

[groutr]

I think I misunderstood initially what NullHandler was for. It's not needed here and I will remove it.

[llllllllll]

do we really need a log warning and a warning.warn?

[groutr]

I don't know if both are desired. The difference between warning.warn and log.warning is explained on this page https://docs.python.org/2/howto/logging.html. In short, warning.warn is intended for libraries where application code should be modified to accomodate a change in the library.

[llllllllll]

in general you should let logging libraries handle string formatting, this ensuers that no formatting happens unless the log message is being handled. logging uses % formatting so you can pass the values to format in as positionals after the message format.

[groutr]

Since the path is known before the loop, an alternative approach would be to log the path before traversing it. Though as far as performance goes, my initial impression is the calls to various conversion functions would far outweigh the overhead from calls to the log.

[groutr]

I've done some simple (very simple) benchmarking/profiling. Yes, logging does add some overhead. If we are logging below the log level, each log call results in three function calls. getEffectiveLevel is probably the most expensive call (has a while loop that traverses the current logger and all its parents), the other two seem to be relatively cheap. I don't think any of odo's paths even approach 100 hops in length.

I think my alternative solution will sidestep much of this overhead. Logging should be fine if we avoid calling it in the loop. Thoughts?

import logging
log = logging.getLogger(__name__)
loops = 100
def withlogging():
    y = 0
    for x in range(loops):
        log.debug("This is a debug message %s", x)
        y += 1

def outlogging():
    y = 0
    log.debug("This is a debug message %s", loops)
    for x in range(loops):
        y += 1

def withoutlogging():
    y = 0
    for x in range(loops):
        y+= 1

(no configuring of logging level)
>>> %timeit withlogging()
10000 loops, best of 3: 109 µs per loop
>>> %timeit withoutlogging()
100000 loops, best of 3: 4.52 µs per loop
>>> %timeit outlogging()
100000 loops, best of 3: 5.84 µs per loop
>>> %prun withlogging()
        304 function calls in 0.000 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 withlog.py:5(wlogging)
      100    0.000    0.000    0.000    0.000 __init__.py:1515(isEnabledFor)
      100    0.000    0.000    0.000    0.000 __init__.py:1501(getEffectiveLevel)
      100    0.000    0.000    0.000    0.000 __init__.py:1257(debug)
        1    0.000    0.000    0.000    0.000 {built-in method builtins.exec}
        1    0.000    0.000    0.000    0.000 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
>>> %prun withoutlogging()
         4 function calls in 0.000 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 {built-in method builtins.exec}
        1    0.000    0.000    0.000    0.000 withlog.py:12(wologging)
        1    0.000    0.000    0.000    0.000 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
>>> %prun outlogging()
        7 function calls in 0.000 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 withlog.py:17(outlogging)
        1    0.000    0.000    0.000    0.000 {built-in method builtins.exec}
        1    0.000    0.000    0.000    0.000 __init__.py:1257(debug)
        1    0.000    0.000    0.000    0.000 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 __init__.py:1515(isEnabledFor)
        1    0.000    0.000    0.000    0.000 __init__.py:1501(getEffectiveLevel)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

[groutr]

I left the log.debug call in the for loop for now.
Variations on my system seem to have a more visible effect than the log.debug calls.

With logging, but no configuration (best of 7 runs) list -> DataFrame with 1 element.
0.0003306s
Without logging (commented out) (best of 7 runs) tuple -> DataFrame with 1 element.
0.0003268s

I tried to use a path that I was easy to benchmark and reasonable fast (not spend a whole lot of time with data structures. The path was 4 hops.
tuple -> list -> ndarray -> pd.DataFrame

EDIT: Updated timings

[llllllllll]

These changes look good, could you rebase? After the ci runs on the rebase I will merge.

[groutr]

I'll rebase hopefully this weekend.