4

I'm trying to understand why I'm getting very different profiling/timing numbers when using numpy.loadtxt within a function and stand-alone.

Setup of data to read/profile

  • 1 file with 26 columns and 1000 rows, each item in file is random floating point number
  • File is space separated
  • 1st line in file is a space separated header with 26 column names
  • See below for code on how this data was generated

Profiling numpy.loadtxt alone

Assume I have a file called 'test.out' with the above properties:

>>> f = open('test.out', 'r');f.readline()
'a b c d e f g h i j k l m n o p q r s t u v w x y z\n'
>>> %timeit -n 1 np.loadtxt(f, unpack=True)
1 loops, best of 3: 30 us per loop

Profiling numpy.loadtxt inside of a function

Now I want to profile numpy.loadtxt inside of a function (using line_profiler) and %lrpun magic in ipython:

>>> %lprun -f file_to_numpy_ordered_dict file_to_numpy_ordered_dict('test.out')
Timer unit: 1e-06 s

Function: file_to_numpy_ordered_dict at line 88
Total time: 0.085642 s

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    88                                           def file_to_numpy_ordered_dict(filename):
    89                                               """
    90                                               Read a space-separated-value file as a dict of columns, keyed by
    91                                               column header where each column (dict value) is a numpy array.
    92                                               """
    93                                           
    94         1          430    430.0      0.5      with open(filename, 'r') as file_obj:
    95         1          363    363.0      0.4          headers = file_obj.readline().split()
    96                                           
    97                                                   # unpack=True b/c want data organized as column based arrays, not rows
    98         1        84634  84634.0     98.8          arrs = np.loadtxt(file_obj, unpack=True)
    99                                           
   100         1           66     66.0      0.1      ret_dict = collections.OrderedDict()
   101        27           34      1.3      0.0      for ii, colname in enumerate(headers):
   102        26          114      4.4      0.1          ret_dict[colname] = arrs[ii]
   103                                           
   104         1            1      1.0      0.0      return ret_dict

Why?

Why does calling numpy.loadtxt by itself only take 30us and calling it inside this function take roughly .085 seconds? I feel like there is something obvious I'm missing here, but it looks like the function is being called exactly the same in each scenario with the same arguments, etc.

Is this some weird difference because I'm using %timeit and %lprun? Maybe this data cannot be compared for some reason?

Details of random data creation

  • File data was generated with the following code: def generate_test_data(column_names, row_count, filename): """ Generate file of random test data of size (row_count, len(column_names))

    column_names - List of column name strings to use as header row
    row_count - Number of rows of data to generate
    filename - Name of file to write test data to
    """
    
    col_count = len(column_names)
    rand_arr = np.random.rand(row_count, col_count)
    header_line = ' '.join(column_names)
    np.savetxt(filename, rand_arr, delimiter=' ', fmt='%1.5f',
                  header=header_line, comments='')
    
4
  • 1
    Actually, I think this is an issue with the arguments I'm passing to %timeit. I was mistaken in assuming that -n 1 would call the function only once, but -n is for executing n times in a loop. So, I need the additional argument -r 1 to repeat the loop only once. Otherwise, %timeit is returning the best of 3 calls, which means 2 of the 3 calls don't have to read any data since the file is read on the first call. So, the fastest iteration is obviously one where numpy.loadtxt reads no data.
    – durden2.0
    Mar 8, 2013 at 15:22
  • The real timings with %timeit should be: 32.4 ms per loop which makes a lot more sense.
    – durden2.0
    Mar 8, 2013 at 15:23
  • So, seems like this question was sort of answered by me, as I expected, missing something obvious. Should I close this or post the comments as an answer? What's the standard for this sort of thing?
    – durden2.0
    Mar 8, 2013 at 15:30
  • Just add your solution as an answer (there's even a badge for it!). Mar 8, 2013 at 16:00

1 Answer 1

3

Just for reference the 'answer' to this question is related to how I was doing my profiling, not in the actual calls to numpy.loadtxt being slower or faster within a function.

  1. Be careful of the arguments to %timeit:

    -n: execute the given statement times in a loop. If this value is not given, a fitting value is chosen.

    -r: repeat the loop iteration times and take the best result. Default: 3

Notice that I was specifying -n 1 to force %timeit to only run the numpy.loadtxt code 1 time. However, -n 1 is not sufficient for this. You must also specify -r 1 to force the evaluation of the code to only happen exactly once.

So, my call to %timeit was effectively evaluating the call to numpy.loadtxt 3 times. The first call would actually read all of the file and take the majority of the total runtime. The next two calls would have no data to read because the file handle passed to numpy.loadtxt didn't have anymore data to read. Thus, two out of three calls didn't have any real work to do and took almost no time at all.

  1. Be careful what the time reported from %timeit means.

Notice what the call to %timeit reports as part of it's output, 1 loops, best of 3: 30 us per loop. Since two of my three calls effectively did no work one of these two calls would be the best of 3.

So by comparing my original call to %timeit and %lprun I was effectively comparing the time numpy.loadtxt takes to look at an empty/finished file handle and the time numpy.loadtxt takes to truly open and read a full 208k of data.

The real timings, when using correct arguments to %timeit make much more sense:

>>> f = open('test.out', 'r');f.readline()
'a b c d e f g h i j k l m n o p q r s t u v w x y z\n'
>>> %timeit -n 1 -r 1 np.loadtxt(f, unpack=True)
1 loops, best of 1: 31.1 ms per loop


Function: file_to_numpy_ordered_dict at line 88
Total time: 0.083706 s

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    88                                           def file_to_numpy_ordered_dict(filename):
    89                                               """
    90                                               Read a space-separated-value file as a dict of columns, keyed by
    91                                               column header where each column (dict value) is a numpy array.
    92                                               """
    93                                           
    94         1          583    583.0      0.7      with open(filename, 'r') as file_obj:
    95         1          313    313.0      0.4          headers = file_obj.readline().split()
    96                                           
    97                                                   # unpack=True b/c want data organized as column based arrays, not rows
    98         1        82417  82417.0     98.5          arrs = np.loadtxt(file_obj, unpack=True)
    99                                           
   100         1          226    226.0      0.3      ret_dict = collections.OrderedDict()
   101        27           35      1.3      0.0      for ii, colname in enumerate(headers):
   102        26          131      5.0      0.2          ret_dict[colname] = arrs[ii]
   103                                           
   104         1            1      1.0      0.0      return ret_dict

31ms vs 83 ms makes a bit more sense. These numbers are close enough that I'm assuming the differences are simply because I'm only running this relatively fast operation one time. To effectively compare these it would be best to take an average of a bunch of runs.

1
  • Great explanation, and a well-written question by the way! Mar 8, 2013 at 17:16

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.