Huge performance loss in R2011b with cell based indexing and reassignment of struct field

Hi,

In R2011b when you re-assign a field of a struct and index using a cell expansion (indexes{:}), Matlab behaves as if accel is off. It also appears that Matlab is touching all of the pages of the underlying data and this is especially apparent when the underlying data is memory mapped.

It seems like the copy on write mechanism is incorrectly being activated and the data is being copied before the field is reassigned, as if I am attempting to mutate something that already has a reference (see test #7). I have attached a working example and results on R2011a and R2011b (specific versions included in output).

Is this a known problem? I was unable to find any reference to this.

Please note that the performance on R2011a is clean for all tests (including accel off) but R2011b clearly underperforms.

Note: Run the test a few times to produce the below results. In general, the results will be right in terms of what I am trying to demonstrate but the JIT will need to get warmed up to get consistent results (Thanks Jan Simon).

R2011a (expected performance):

----ACCEL ON---- (7.12.0.635 (R2011a) - GLNXA64)
  ----Iteration 1----
    #1: 0.000020
    #2: 0.000027
    #3: 0.000018
    #4: 0.000012
    #5: 0.000087
    #6: 0.000015
    #7: 0.032089

----ACCEL OFF---- (7.12.0.635 (R2011a) - GLNXA64)
  ----Iteration 1----
    #1: 0.000021
    #2: 0.000015
    #3: 0.000015
    #4: 0.000008
    #5: 0.000084
    #6: 0.000016
    #7: 0.032500

R2011b (underperformance on #5 & #6 and with accel off).

----ACCEL ON---- (7.13.0.564 (R2011b) - GLNXA64)
  ----Iteration 1----
    #1: 0.000027
    #2: 0.000038
    #3: 0.000029
    #4: 0.000019
    #5: 0.037336
    #6: 0.037215
    #7: 0.034041

----ACCEL OFF---- (7.13.0.564 (R2011b) - GLNXA64)
  ----Iteration 1----
    #1: 0.036203
    #2: 0.036536
    #3: 0.036511
    #4: 0.035887
    #5: 0.036641
    #6: 0.036468
    #7: 0.032923

Test code:

function slowtest()
    z.data = randn(10, 1e6);
    fprintf('\n----ACCEL ON---- (%s - %s)\n', version(), computer());
    feature('accel', 'on');
    slowtest_index(z);

      fprintf('\n----ACCEL OFF---- (%s - %s)\n', version(), computer());
      feature('accel', 'off');
      slowtest_index(z);
  end

function slowtest_index(input)    
    for i=1:1
        idxs = {[1]};

          fprintf('\t----Iteration %d----\n', i);
          t=tic();
          a = input;
          a.data = a.data([1]);
          fprintf('\t\t#1: %f\n', toc(t));

          t=tic();
          a = input;
          d = a.data(idxs{:});
          a.data = d;
          fprintf('\t\t#2: %f\n', toc(t));

          t=tic();
          a = input;
          d = a.data(idxs{1});
          a.data = d;
          fprintf('\t\t#3: %f\n', toc(t));

          t=tic();
          a = input;
          a.data = 1;
          fprintf('\t\t#4: %f\n', toc(t));

          t=tic();
          a = input;
          a.data = subsref(a.data, substruct('()', idxs));
          fprintf('\t\t#5: %f\n', toc(t));

          t=tic();
          a = input;
          a.data = a.data(idxs{:});
          fprintf('\t\t#6: %f\n', toc(t));

          t=tic();
          a = input;
          a.data(1) = a.data(2);
          fprintf('\t\t#7: %f\n', toc(t));
      end
      fprintf('\n');
  end

[Jan]

Is the table correct?

R2011a (expected performance):

----ACCEL ON---- (7.12.0.635 (R2011a) - GLNXA64)

#1: 0.000264

----ACCEL OFF---- (7.12.0.635 (R2011a) - GLNXA64)

#1: 0.000022

Why is the function much faster with disabled acceleration?

[Nathan]

Good catch. I think I had a bad interaction with the JIT when I ran the tests for those outputs. I just re-ran them and they are more consistent. I will update the above results. Can someone else with R2011a or b confirm the results?

[Nathan]

Definitely the JIT getting warmed up. I originally had a test that did two iterations but trimmed it back to keep this post a little smaller with the results. First pass gives us the 264us and second pass gives us the 22us.

[Daniel Shub]

Have you tried it without "5", the one with subsref. I wonder if MATLAB is doing some sort of garbage collection after the call. I don't have MATLAB access right now to check.

[Nathan]

Daniel: I have. To demonstrate this problem, I started with the basic case (#6) and included the other cases to demonstrate the inconsistency. Removing #5 (reconfirmed just a second ago) has no change in the results. Note that I am only asking for a single double at any given time so garbage should be minimal. To further this case, running *only* #6 with 100 iterations produces the same results.

[Nathan]

One other thought...note that the times in #5 and #6 are consistent with #7 which intentionally triggers the copy on write (COW) behavior. #7 should be making a copy of the underlying input.data in order to detach itself from that reference and then mutating the first element. I believe that the time observed is the memory copy. Cases #5 and #6 should not be triggering COW behavior but I am speculating that they are in R2011b.

Answer 1

[Nathan]

From Mathworks support staff:

"I looked into the issue and consulted with the concerned development team about it. This is a bug in the latest release MATLAB 7.13 R2011b. The development team have taken a note of this and will further look into it. They will investigate the bug and look to fix it in a future release of the product."

Answer 2

[Jan]

Matlab 2011b, Win7, Core2Duo:

 ----ACCEL ON---- (7.13.0.564 (R2011b) - PCWIN64)
  ----Iteration 1----
    #1: 0.000029
    #2: 0.000033
    #3: 0.000021
    #4: 0.000012
    #5: 0.076800
    #6: 0.083983
    #7: 0.069058

 ----ACCEL OFF---- (7.13.0.564 (R2011b) - PCWIN64)
  ----Iteration 1----
    #1: 0.083822
    #2: 0.086834
    #3: 0.077840
    #4: 0.077228
    #5: 0.077171
    #6: 0.081455
    #7: 0.073255

[Nathan]

Looks consistent with my results.