4

I've just spent a while debugging some particularly slow code and have been completely thrown off by the MATLAB profiler. This looks to me like a massive bug, so I was wondering if anyone could cast any light on to what is going on here.

Here is some code that will cause the problem:

function profiler_test

  %%% Create 20 files with random data

  count = 20;

  for i = 1 : count
    x = rand(3);
    save(sprintf('temp_file_%06d', i), 'x'); 
  end

  %%% Load them in a for loop

  xs = cell(1, count);

  tic;
  for i = 1 : count
    x = load(sprintf('temp_file_%06d', i), 'x');
    xs{i} = x.x;
  end
  toc

  %%% Load them in a for loop, but writing a small log file on the way

  tic;
  for i = 1 : count
    x = load(sprintf('temp_file_%06d', i), 'x');
    xs{i} = x.x;

    file = fopen(sprintf('temp_logfile_%d', i), 'w');
    fprintf(file, 'Success\n');
    fclose(file);
  end
  toc


end

The first for loop takes 0.239739 seconds, the second takes 4.411179.

Now, I should make it clear that I am aware of the sloppy idea I had, shown in the second for loop example, of creating a log file for each result - it was because I was running on a cluster where I couldn't see the output, I wanted a cheap indication of the function's progress, and this turned out to be the bottleneck. I'm fine with that.

My problem however is that I've spent a day trying to optimise the wrong line, because the MATLAB profiler says this:

         1   24   tic; 
         1   25   for i = 1 : count 
4.41    20   26     x = load(sprintf('temp_file_%06d', i), 'x'); 
        20   27     xs{i} = x.x; 
             28     
        20   29     file = fopen(sprintf('temp_logfile_%d', i), 'w'); 
        20   30     fprintf(file, 'Success\n'); 
        20   31     fclose(file); 
        20   32   end 
         1   33   toc

It's placed the entire time taken to execute the final three lines on the line for load. In my actual program, the load was not so close to the other bit so it didn't occur to me until I decided to distrust the profiler. My question is: what is going on here? Why has this happened and should I be watching out for any more bizarre behaviour like this?

I'm using MATLAB 2011a. Many thanks.

EDIT: I seem to be causing some confusion, apologies. Here is the situation:

  • The two for loops shown above are identical, except that the second one has three lines at the bottom which write to a temporary file each iteration.
  • The second loop takes substantially longer to run: the conclusion is that those last three lines are to blame for the speed increase. When they are removed, the code is fast again.
  • However, the profiler does not attribute any of the time for the second loop to those final three statements. Instead, it tells me that my load function call - exactly the same call as the first loop, which was faster - is now taking 4 seconds instead of 0.2. So either the presence of the last three lines causes the load to be slow (I had disregarded this; is that even a possibility?), OR the MATLAB profiler is incorrectly reporting that load is taking 4 seconds when it is clearly not.

Either way it seems to me that something very strange is happening.

EDIT: Seem to have answered it myself, see below. Changed the title as it was misleading

Shai
  • 111,146
  • 38
  • 238
  • 371
devrobf
  • 6,973
  • 2
  • 32
  • 46
  • Are you saying that `load` doesn't take `4.41 s` and that Matlab displays it wrong? You wrote that the second `for` loop in the first code snippet also takes `4.41 s`; the loop just loads the data. – Dedek Mraz Mar 13 '13 at 13:59
  • Yes, that's exactly what I'm saying. Sorry if I didn't make it clear enough: the two loops are identical apart from the logging in the second loop, but the large time increase is incorrectly attributed to the `load` call. – devrobf Mar 13 '13 at 14:23
  • I guess I was confused about which is the second of the three loops in your code. I guess you don't count the first loop – Dedek Mraz Mar 13 '13 at 14:37
  • Also true, my fault again! In any case, I seem to have resolved it - see below. – devrobf Mar 13 '13 at 14:54

3 Answers3

3

I do not see any evidence of a bug in your post.

You mention that the entire loop takes about 4.111 and the profiler shows that line 26 takes about 4.11.

This means that all other lines together take less than 0.01 and therefore each line takes a rounded amount of zero seconds.

My guess is that zeroes are just not printed and that you interpreted this as the other lines not being timed.

I may be missing something but so far the output provided by MATLAB seems to be consistent.

Dennis Jaheruddin
  • 21,208
  • 8
  • 66
  • 122
  • Sorry, I don't think I've been clear enough; I'll add an edit to my question! – devrobf Mar 13 '13 at 14:24
  • @jazzbassrob Please measure the time on each line before drawing the conclusion that the time increase after adding lines is actually happening in those lines. Perhaps they just slow your load down because of less optimization or something alike. – Dennis Jaheruddin Mar 13 '13 at 14:39
  • Yes, I'll accept I automatically assumed that the extra time was happening on those those rather than the `load` actually slowing down, but my question still remains: why? What sort of optimization would cause this? – devrobf Mar 13 '13 at 14:44
  • I think I've answered it myself, but thanks - you got me thinking on the right track! – devrobf Mar 13 '13 at 14:55
3

Actually, I think I've solved it. I was wrong to jump to the conclusion that the additional processing time was occurring on the new lines, so my question is now a little misleading - the profiler is correct. However, I still didn't understand why writing to a temporary file would cause load to slow down. I had a thought, which was to try this:

file = fopen(sprintf('../temp_logfile_%d', i), 'w');

That is, write to a file in the parent directory instead of the current working directory. This removed the problem, and was very fast. The reason, I am guessing, is that the current directory is in my MATLAB search path, as are a bunch of other directories. I presume that every time MATLAB uses a function which looks though the whole search path, as load does, it checks to see if any directories have been modified, and if so re-parses the whole lot to see what files are available. Writing a new file to the working directory certainly would have caused this. This may have been worse in my case since I also have a whole tree of subdirectories in the working directory which are part of the search path.

Anyway, thanks to those who had a look and sorry that the answer turned out to be something quite different from the question. Be aware when using functions which rely on the entire search path!

devrobf
  • 6,973
  • 2
  • 32
  • 46
1

I get the following report generated by the profiler of MATLAB 2012b, I dont see a bug. enter image description here enter image description here enter image description here

Abhishek Thakur
  • 16,337
  • 15
  • 66
  • 97
  • That's very interesting; mine certainly does not look like that, for one thing the second loop took 4 seconds! I do have 2012a available so I'll try on that for comparison – devrobf Mar 13 '13 at 14:37
  • Instead of CPU or version, could be an I/O config difference, maybe due to jazzbassrob running on a cluster with non-local storage attached, or a network drive? Abhishek's numbers look like what you'd expect from a local disk where everything's happening in the disk cache; jazzbassrob's numbers, even the faster 0.239, are pretty slow for local disk, closer to uncached I/O. – Andrew Janke Mar 18 '13 at 04:36