MATLAB Execution Time Increasing despite preallocation

Here is my code. The intent is I have a Wireshark capture saved to a particularly formatted text file. The MATLAB code is supposed to go through the Packets, dissect them for different protocols, and then make tables based on those protocols. I currently have this programmed for ETHERNET/IP/UDP/MODBUS. In this case, it creates a column in MBTable each time it encounters a new register value, and each time it comes across a change to that register value, it updates the value in that line of the table. The first column of MBTable is time, the registers start with the second column.

MBTable is preallocated to over 100,000 Rows (nol is very large), 10 columns before this code is executed. The actual data from a file I'm pulling into the table gets to about 10,000 rows and 4 columns and the code execution is so slow I have to stop it. The tic/toc value is calculated every 1000 rows and continues to increase exponentially with every iteration. It is a large loop, but I can't see where anything is growing in such a way that it would cause it to run slower with each iteration.

All variables get initialized up top (left out to lessen amount of code. eth, eth.ip, eth.ip.udp, and eth.ip.udp.modbus are all of type struct as is eth.header and eth.ip.header. WSID is a file ID from a .txt file opened earlier in the program.

      MBTable = zeros(nol,10);
      tval = tic;
      while not(feof(WSID))
          packline = packline + 1;
          fl = fl + 1;

          %Get the next line from the file
          MBLine = fgetl(WSID);
          %Make sure line is not blank or short
          if length(MBLine) >= 3
              %Split the line into 1. Line no, 2. Data, 3. ASCII
              %MBAll = strsplit(MBLine,' ');
              %First line of new packet, if headers included
              if strcmp(MBLine(1:3),'No.')
                  newpack = true;
                  newtime = false;
                  newdata = false;
                  stoppack = false;
                  packline = 1;
              end
              %If packet has headers, 2nd line contains timestamp
              if newpack
                  Ordered = false;
                  if packline == 2;
                      newtime = true;
                      %MBstrs = strsplit(MBAll{2},' ');
                      packno = int32(str2double(MBLine(1:8)));
                      t = str2double(MBLine(9:20));

                      et = t - lastt;
                      if lastt > 0 && et > 0
                          L = L + 1;
                          MBTable(L,1) = t;
                      end
                      %newpack = false;
                  end
                  if packline > 3              
                          dataline = int16(str2double(MBLine(1:4)));
                          packdata = strcat(packdata,MBLine(7:53));
                  end
              end

          else
              %if t >= st

              if packline > 3
                  stoppack = true;
                  newpack = false;
              end
              if stoppack
                  invalid = false;
                  %eth = struct;

                  eth.pack = packdata(~isspace(packdata));
                  eth.length = length(eth.pack);

                  %Dissect the packet data
                  eth.stbyte = 1;
                  eth.ebyte = eth.length;
                  eth.header.stbyte = 1;
                  eth.header.ebyte = 28;
                  %Ethernet Packet Data
                  eth.header.pack = eth.pack(eth.stbyte:eth.stbyte+27);
                  eth.header.dest = eth.header.pack(eth.header.stbyte:eth.header.stbyte + 11);
                  eth.header.src = eth.header.pack(eth.header.stbyte + 12:eth.header.stbyte + 23);
                  eth.typecode = eth.header.pack(eth.header.stbyte + 24:eth.header.ebyte);

                  if strcmp(eth.typecode,'0800')

                      eth.type = 'IP';
                      %eth.ip = struct;
                      %IP Packet Data
                      eth.ip.stbyte = eth.header.ebyte + 1;
                      eth.ip.ver = eth.pack(eth.ip.stbyte);
                      %IP Header length
                      eth.ip.header.length = 4*int8(str2double(eth.pack(eth.ip.stbyte+1)));
                      eth.ip.header.ebyte = eth.ip.stbyte + eth.ip.header.length - 1;
                      %Differentiated Services Field
                      eth.ip.DSF = eth.pack(eth.ip.stbyte + 2:eth.ip.stbyte + 3);
                      %Total IP Packet Length
                      eth.ip.length = hex2dec(eth.pack(eth.ip.stbyte+4:eth.ip.stbyte+7));
                      eth.ip.ebyte = eth.ip.stbyte + max(eth.ip.length,46) - 1;
                      eth.ip.pack = eth.pack(eth.ip.stbyte:eth.ip.ebyte);
                      eth.ip.ID = eth.pack(eth.ip.stbyte+8:eth.ip.stbyte+11);
                      eth.ip.flags = eth.pack(eth.ip.stbyte+12:eth.ip.stbyte+13);
                      eth.ip.fragoff = eth.pack(eth.ip.stbyte+14:eth.ip.stbyte+15);
                      %Time to Live
                      eth.ip.ttl = hex2dec(eth.pack(eth.ip.stbyte+16:eth.ip.stbyte+17));
                      eth.ip.typecode = eth.pack(eth.ip.stbyte+18:eth.ip.stbyte+19);
                      eth.ip.checksum = eth.pack(eth.ip.stbyte+20:eth.ip.stbyte+23);

                      %eth.ip.src = eth.pack(eth.ip.stbyte+24:eth.ip.stbyte+31);

                      eth.ip.src = ...
                          [num2str(hex2dec(eth.pack(eth.ip.stbyte+24:eth.ip.stbyte+25))),'.', ...
                          num2str(hex2dec(eth.pack(eth.ip.stbyte+26:eth.ip.stbyte+27))),'.', ...
                          num2str(hex2dec(eth.pack(eth.ip.stbyte+28:eth.ip.stbyte+29))),'.', ...
                          num2str(hex2dec(eth.pack(eth.ip.stbyte+30:eth.ip.stbyte+31)))];

                      eth.ip.dest = ...
                          [num2str(hex2dec(eth.pack(eth.ip.stbyte+32:eth.ip.stbyte+33))),'.', ...
                          num2str(hex2dec(eth.pack(eth.ip.stbyte+34:eth.ip.stbyte+35))),'.', ...
                          num2str(hex2dec(eth.pack(eth.ip.stbyte+36:eth.ip.stbyte+37))),'.', ...
                          num2str(hex2dec(eth.pack(eth.ip.stbyte+38:eth.ip.stbyte+39)))];

                      if strcmp(eth.ip.typecode,'11')
                          eth.ip.type = 'UDP';

                          eth.ip.udp.stbyte = eth.ip.stbyte + 40;
                          eth.ip.udp.src = hex2dec(eth.pack(eth.ip.udp.stbyte:eth.ip.udp.stbyte + 3));
                          eth.ip.udp.dest = hex2dec(eth.pack(eth.ip.udp.stbyte+4:eth.ip.udp.stbyte+7));
                          eth.ip.udp.length = hex2dec(eth.pack(eth.ip.udp.stbyte+8:eth.ip.udp.stbyte+11));
                          eth.ip.udp.checksum = eth.pack(eth.ip.udp.stbyte+12:eth.ip.udp.stbyte+15);
                          eth.ip.udp.protoID = eth.pack(eth.ip.udp.stbyte+20:eth.ip.udp.stbyte+23);

                          if strcmp(eth.ip.udp.protoID,'0000')
                             eth.ip.udp.proto = 'MODBUS';

                             %eth.ip.udp.modbus = struct;
                             eth.ip.udp.modbus.stbyte = eth.ip.udp.stbyte+16;
                             eth.ip.udp.modbus.transID = eth.pack(eth.ip.udp.modbus.stbyte:eth.ip.udp.modbus.stbyte+3);
                             eth.ip.udp.modbus.protoID = eth.ip.udp.protoID;
                             eth.ip.udp.modbus.length = int16(str2double(eth.pack(eth.ip.udp.modbus.stbyte + 8:eth.ip.udp.modbus.stbyte + 11)));
                             eth.ip.udp.modbus.UID = eth.pack(eth.ip.udp.modbus.stbyte + 12:eth.ip.udp.modbus.stbyte + 13);
                             eth.ip.udp.modbus.func = hex2dec(eth.pack(eth.ip.udp.modbus.stbyte + 14:eth.ip.udp.modbus.stbyte+15));
                             eth.ip.udp.modbus.register = eth.pack(eth.ip.udp.modbus.stbyte + 16: eth.ip.udp.modbus.stbyte+19);
                             %Number of words to a register, or the number of registers
                             eth.ip.udp.modbus.words = hex2dec(eth.pack(eth.ip.udp.modbus.stbyte+20:eth.ip.udp.modbus.stbyte+23));
                             eth.ip.udp.modbus.bytes = hex2dec(eth.pack(eth.ip.udp.modbus.stbyte+24:eth.ip.udp.modbus.stbyte+25));
                             eth.ip.udp.modbus.data = eth.pack(eth.ip.udp.modbus.stbyte + 26:eth.ip.udp.modbus.stbyte + 26 + 2*eth.ip.udp.modbus.bytes - 1);

                             %If func 16 or 23, loop through data/registers and add to table
                             if eth.ip.udp.modbus.func == 16 || eth.ip.udp.modbus.func == 23
                                 stp = eth.ip.udp.modbus.bytes*2/eth.ip.udp.modbus.words;
                                 for n = 1:stp:eth.ip.udp.modbus.bytes*2;
                                    %Check for existence of register as a key?
                                    if ~isKey(MBMap,eth.ip.udp.modbus.register)
                                      MBCol = MBCol + 1;
                                      MBMap(eth.ip.udp.modbus.register) = MBCol; 
                                    end
                                    MBTable(L,MBCol) = hex2dec(eth.ip.udp.modbus.data(n:n+stp-1));
                                    eth.ip.udp.modbus.register = dec2hex(hex2dec(eth.ip.udp.modbus.register)+1);
                                 end
                                 lastt = t;
                             end

                             %If func 4, make sure it is the response, then put
                             %data into table for register column

                          elseif false

                              %need code to handle serial to UDP conversion box

                          else
                              invalid = true;
                          end

                      else
                          invalid = true;
                      end

                  else
                      invalid = true;
                  end

                  if ~invalid

                  end
              end
              %end
          end
         %Display Progress
         if int64(fl/1000)*1000 == fl
             for x = 1:length(mess);
                 fprintf('\b');
             end
             %fprintf('Lines parsed: %i',fl);
              mess = sprintf('Lines parsed: %i / %i',fl,nol);
              fprintf('%s',mess);
             %Check execution time - getting slower:
             %%{
             ext = toc(tval);
              mess = sprintf('\nExecution Time: %f\n',ext);
              fprintf('%s',mess);
             %%}
         end
      end
      ext = toc - exst;

Update: I updated my code above to remove the overloaded operators (disp and lt were replaced with mess and lastt)

Was asked to use the profiler, so I limited to 2000 lines in the table (added && L >=2000 to the while loop) to limit the execution time, and here are the top results from the profiler:

Wireshark_Parser_v0p7_fulleth    1  57.110 s9.714 s
Strcat            9187  29.271 s  13.598 s
Blanks            9187  15.673 s  15.673 s
Uigetfile          1  12.226 s  0.009 s
uitools\private\uigetputfile_helper    1  12.212 s  0.031 s
FileChooser.FileChooser>FileChooser.show  1  12.085 s  0.006s
...er>FileChooser.showPeerAndBlockMATLAB  1  12.056 s0.001s
...nChooser>FileOpenChooser.doShowDialog  1  12.049 s12.049 s
hex2dec          44924  2.944 s  2.702 s
num2str          16336  1.139 s  0.550 s
str2double          17356  1.025 s  1.025 s
int2str            16336  0.589 s  0.589 s
fgetl            17356  0.488 s  0.488 s
dec2hex          6126  0.304 s  0.304 s
fliplr            44924  0.242 s0.242 s

It appears to be strcat calls that are doing it. I only explicitly call strcat on one line. Are some of the other string manipulations I'm doing calling strcat indirectly? Each loop should be calling strcat the same number of times though, so I still don't understand why it takes longer and longer the more it runs...

also, hex2dec is called a lot, but is not really affecting the time.

But anyway, are there any other methods I can use the combine the strings?

[dpb]

I don't see where there's anything that's array dependent that zero initialization would matter? Perhaps it's because there's so much code and don't know what it's doing I'm just overlooking it, but, don't see the portion you think is the problem.

Seems like a lot of gyrations from/to hex/dec/back again -- surely this could be streamlined significantly??? I'd take a stab but don't have a clue what inputs/outputs expected are.

Could you shorten this to just a small subset that still shows a growing time to execute and then supply some data so folks could have a chance to look at it? Likely more probable to get some useful suggestions.

And, of course, in a performance case like this, first "profile, profile, profile" to see where the bottleneck(s) really are instead of trying to guess.

[Geoff Hayes]

Alan - are you able to attach the data file, or at least a subset of the data?

[Alan]

The Only array is MBTable, and as I stated it was preallocated to a much larger array than it actually creates. I posted all this code because this is as far as I have narrowed it down. I will try the profiler, as suggested and post the results.

[Alan]

I posted profile results to the question above. I'm not sure what to do still.

[Philip Borghesani]

If you are using strcat something (packdata) is not being preallocated does it continue to grow?...

Take a look at the time used by each line of code in your main function that will let you know if you are directly calling strcat using the time.

Given that strcat and blanks are called the same number of times and this code does not call blanks something else is going on here.

[dpb]

dataline = int16(str2double(MBLine(1:4)));
packdata = strcat(packdata,MBLine(7:53));

strcat is likely doing a reallocation behind the scenes -- this is so much code and without any data or any idea of what it's really doing as noted before it's a lot to expect someone else to just look at it and tell you what to do differently.

At a minimum as Alan suggests, attach a data file.

I'd again suggest to provide a short section of an input file and a description and an example of what the expected output would be from that input and any details that aren't obvious of getting from input to output.

IOW, let someone else have the information needed to solve the problem in their way rather than expecting them to debug and optimize your code in the dark.

Answer 1

[Alan]

Here is the issue:

The string (an char array in MATLAB) packdata was being resized and reallocated over and over again. That's what was slowing down this code. I did the following steps:

1. I eliminated the redundant variable packdata and now only use eth.pack.

2. I preallocated eth.pack and a couple "helper variables" of known lengths by running blanks ONCE for each before the loop ever starts

    eth.pack = blanks(604);
    thisline = blanks(47);
    smline = blanks(32);

(Note: 604 is the maximum possible size of packdata based on headers + MODBUS protocol)

3. Then I created a pointer variable to point to the location of the last char written to packdata.

    pptr = 1;

    ...

    dataline = int16(str2double(MBLine(1:4)));

    thisline = MBLine(7:53); %Always 47 characters

    smline = [thisline(~isspace(thisline)),blanks(32-sum(~isspace(thisline)))]; %Always 32 Characters

    eth.pack(pptr:pptr+31) = smline;

    pptr = pptr + 32;

The above was inside the 'if packline > 3' block in place of the 'packdata =' statement, then at the end of the 'if stoppack' block was the reset statement:

    pptr = 1; %Reset Pointer

FYI, not surprisingly this brought out other flaws in my code which I've mostly fixed but still need to finish. Not a big issue now as this loop executes lightning fast with these changes. Thanks to Philip and dpb for helping point me in the right direction.

I kept thinking my huge table, MBTable was the issue... but it had nothing to do with it.