Slow parsing of Socrates source files

[hiker]

One source file from Socrates is parsed extremely slow. I aborted fparser2 after 15 minutes, my Fab build (which I believe was only parsing this file) was busy for over 30 minutes without a result.

The file in question is:
https://github.com/MetOffice/socrates/blob/main/src/odepack/opkda1.f
A bit over 10k lines of Fortran 77 :( The same directory has a file opkdmain.f, which is over 16k lines, and it got parsed in around 140 seconds.

[hiker]

I've narrowed it down to 300 lines, which take around 400 seconds, one subroutine is causing this (other subroutines will have similar issues, since the overall parse time is >30 minutes, but this one is the most obvious one).
FWIW, some other ~500 line section of this file parse in 0.3 seconds.

[hiker]

It seems to be related to loops using a label, e.g.:

      DO 530 I = 1,N
 530    SAVF(I) = ACOR(I) - YH(I,LMAX)

Not entirely sure if there is a certain type (nested, or single). After starting to replace these loops, parsing time is down from 400 seconds to 25 seconds now. Replacing a single loop seems to reduce parsing time by around 2 seconds 🫨

[arporter]

Wow. I'm a bit puzzled why we haven't seen this before though. Is Socrates being built as part of lfric_atm - we build this in our ITs but perhaps Fab does more source code parsing?

[hiker]

We don't see this problem in LFRic, since the odepack directory is not checked out in the build ;)

Below an interesting graph: I map the number of old-style loop (with labels) vs the time it takes to parse around 310 lines of code. I just replaces all labelled loops with normal do / enddo ones, so no real code change.

The line in green (which is hard to see, since its nearly identical) is 2**(x-15) - exponential (admittedly, if you look close it's only good for 15 or more old-style loops, I would actually expect it to be more a square, but found it harder to manually match a square function).

I have a profile, and while nothing obvious jumped out (though admittedly I am neither that familiar with fparser's internal, nor with python profiling), the fact that I see 153,245,554 calls to next and get_item seems to indicate that somehow fparser is parsing too often (trial and error for matching something?Match has over 7 million calls as well).

If no one here has an immediate idea (though suggestions are always welcome ;) ), I am happy to dig in a bit deeper. Also, we now have the hopefully simple solution of just updating one or two files in Socrates by using a small script to replace loops (though ... I can't use fparser ;) )

[hiker]

Ah, I think I understand what the problem is. A loop like DO 645 I = 1,N has two different rules: it could either be a nonblock-do-construct:

     DO 645 I = 1,N
 645    Y(I) = YH(I,1)

or a block-do-construct:

     DO 645 I = 1,N
        Y(I) = YH(I,1)
 645 ENDDO

Fparser is strictly following the grammar:

R825 do-construct is block-do-construct
                  or nonblock-do-construct

Which means it first uses block-do-construct and searches for 645 enddo ... and it happy parses till the end of the subroutine(!!)

When it can't find the labeled enddo, it undoes all it has parsed (pushing it all back into the reader's fifo queue etc), and then trying (successfully) to parse it as a nonblock-do-construct.

Given that the subroutine has 24 loops, here what I think is causing the slowdown:

1. fparser reads the loop 1 (as blocking), and while searching for the enddo finds loop 2 --> pushed on stack
2. while trying to parser loop 2 (as blocking), it finds loop 3 -> pushed on stack
   Rinse and repeat:
   Once it has reached the last loop 24, it (quickly) is detected as nonblock. So, fparser goes back to loop 23. Even though loop24 is now parsed, it still can't find the enddo for loop 23. So, it then tries to parse loop 23 as nonblock, and succeeds. So, after some backtracking, loop 1 is then confirmed NOT to be a blocked, so it is parsed as non-block.

Then fparser reaches loop 2. And even though it has previously been parsed as non-blocking, fparser follows the rule order and starts again with a blocking loop ... and hits all 23 loops it has already parsed previously again. Yes, the parsing is cached, but that only means (I think) that each loop is faster detected to be a labeled-block (from cache), but it still starts testing for blocked first, testing the remaining 22 loops again, ...

I am getting a headache :) But that's at least a O(n^2) algorithm with n sequential loops (parsing the first loop as blocking, parsing all following n-1 loops, before backtracking and then parsing the first loop as non-blocking, which is something like n-1 + n-2 + ... + 1 = O(n^2)

That's not easy to fix imho :( We could somehow add a test for non-blocking loops while parsing for blocking loops, but that sounds seriously messy (not to mention that messing with the grammar in this way is not something I am keen on doing).

Unless you have a better idea, I am happy to declare this won't-fix (though I would be interested in testing with treesitter), and just fix the source code.

[hiker]

Actually, ... still having an headache ;) But I think O(n^2) is wrong.

The amount of work (as in: how many do loop statements are parsed) if we have n loops is f(n) =1 + f(n-1) + 1 + f(n-1)

1. We first try the nth loop as blocking: 1
2. Then we try to parse the next n-1 loops: f(n-1)
3. Then we parse the nth loop as non-blocking (successful): 1
4. Then we need to parse the next n-1 loops, which is f(n-1)

That is (slightly more than) exponential I believe?

[arporter]

Could we change the order that fparser attempts to do its matching once we've hit one case of a nonblock-do-construct? (On the principle that once one has been found, it's quite likely that there will be others...)

[hiker]

I tried, it failed one test ... and I have NO idea why that happens. Test in question:

      do 12
        do 13
          a = 1
 13   continue
 12   continue

And that version does also NOT parse the reproducer. Again, no idea why - if it would hang, ok - but not match??? I'll have a look later.

[hiker]

I think the reason for the failure of

      do 12
        do 13
          a = 1
 13   continue
 12   continue

is actually an existing bug in fparser. When changing the order:

class Do_Construct(Base):  # pylint: disable=invalid-name
    """
    R825::

        <do-construct> = <block-do-construct>
                         | <nonblock-do-construct>

    """

    #subclass_names = ["Block_Do_Construct", "Nonblock_Do_Construct"]
    subclass_names = [ "Nonblock_Do_Construct", "Block_Do_Construct"]

then utils.py, line 482 searches across all subclasses:

            for subcls in Base.subclasses.get(cls.__name__, []):
                if subcls in parent_cls:  # avoid recursion 2.
                    continue
                try:
                    obj = subcls(string, parent_cls=parent_cls)

which in case of the reversed order contains the do statements in the order:

32 = {type} <class 'fparser.two.Fortran2003.Action_Term_Do_Construct'>
33 = {type} <class 'fparser.two.Fortran2003.Outer_Shared_Do_Construct'>
34 = {type} <class 'fparser.two.Fortran2003.Block_Label_Do_Construct'>
35 = {type} <class 'fparser.two.Fortran2003.Block_Nonlabel_Do_Construct'>

The original order has (as expected) the two block versions first:

32 = {type} <class 'fparser.two.Fortran2003.Block_Label_Do_Construct'>
33 = {type} <class 'fparser.two.Fortran2003.Block_Nonlabel_Do_Construct'>
34 = {type} <class 'fparser.two.Fortran2003.Action_Term_Do_Construct'>
35 = {type} <class 'fparser.two.Fortran2003.Outer_Shared_Do_Construct'>

In theory that shouldn't matter. It will affect the speed, since the parsing of the two non-block constructs (action_term/outer_shared) will be slower (it will parse till the end of the file to detect that no matching label exist ... while the label exists, it's in continue statements, which are not accepted as end statements in non-blocking). But, the outer_shared_construct contains:

            if obj is None:  # todo: restore reader
                return

And indeed, if I debug this code, the parser is trying to match the inner loop (which it can't as non-blocking) and reaches the end of the file, and gives up (so far correct). But then the outer_shared_construct doesn't restore the reader. Which means when it finally tries to parse the inner loop as Block_Label_Do_Construct next, the reader is empty.

I think the following patch fixes this issue:

     def match(reader):
         content = []
         for cls in [Label_Do_Stmt, Do_Body, Shared_Term_Do_Construct]:
-            obj = cls(reader)
+            try:
+                obj = cls(reader)
+            except NoMatchError:
+                obj = None
             if obj is None:  # todo: restore reader
+                for obj in reversed(content):
+                    obj.restore_reader(reader)
+
                 return
             content.append(obj)
         return (content,)

Note that I need the try, since in at least one case the cls(reader) raises an exception instead of returning None.

Also,the Inner_Shared_Construct seems to have the same bug.

The additional problem: as far as I can see, this will have the same exponential scaling for blocked loops with a label (since it will first try to match each loop as non-blocked loop, ignoring the labeled end-do statements). But tbh, I think labeled blocked loops are rarer than non-blocked loops(???). Though ... we didn't notice the exponential scaling before either, it needs at least a few loops (let's say ... 17) for the runtime to become more than 10 seconds (on my laptop).

I will do some further tests, esp. performance (and correctness) impact of current fparser, switching the order, or early-abort for non-blocked loops (original approach).

[hiker]

Interestingly, switching the order of the classes (and fixing the outer_shared_construct) does NOT fix the slow parsing in the original file (I aborted after ~120 seconds. My original patch allows successful parsing of the file in under 7 seconds, and it's a 10k line files)

[hiker]

More precise: it does parse my reproducer in ~1.4 seconds (from 400 seconds with fparser master). My patch parses the same file in around 0.6 seconds. The full (10k) file is not parsed in 120 seconds with this change, but it takes 7 seconds for my patch.

Without debugging (which would take some effort tbh), I believe this might be caused by loops using continue:

        DO 440 I = I1,NQNYH
 440      YH1(I) = YH1(I) - YH1(I+NYH)
 445    CONTINUE

The continue statement makes it a blocked one with label, which will now trigger the same exponential behaviour (I didn't think of 10 continue and 10 enddo being the same blocked grammar rule). My reproducer has only 3 continue loops, but the actual file has 240 - so likely the exponential behaviour hits us again in some other subroutine.

So, I think in order to fix this we need to get my original patch in.