libraries: BuiltIn: _accepts_embedded_arguments: do not recommend on …

[totu]

…failure

We are not using this runner for anything here, so let's not gather recommendations on failure.

This is a pretty big performance hit for no apparent benefit.

We have to introduce recommend_on_failure variable to _ExecutionContext's get_runner(), but we can keep the default behaviour the same.

This might be fix for #4659 I found this for very similar performance issue. This came in 5.1b2 when the decoration for run_keyword() in BuiltIn was changed.

[pekkaklarck]

Could you clarify the problem you have and how this PR helps with that? If there are performance enhancements, do you have concrete numbers?

[totu]

We have a lot of proprietary protocols implemented in Python which are then dynamically imported in Robot Framework. We are mainly calling into these libraries with the Run Keyword keyword from BuiltIn library ala:

Run Keyword ${lib}.Send Message payload=${payload}

We have been running Robot Framework 4.1.2 for long while and now decided it was time to upgrade, but I noticed that these Run Keyword calls were taking 40-100ms to find the library after which the actual function only takes ~5ms to execute.

From my experiments the actual change was made in 5.1b2 where the decorator for run_keyword() function was change from resolve=1 to 0. Changing this back also got the Run Keyword to execute in ball park of 1-5ms depending on test case. Most of the time was spent in running/namespace.py function _raise_no_keyword_found() specifically in line 283 where we are finding the recommended similar keyword, which at the end of the day we are discarding the in the _accept_embedded_arguments().

An example test timings compared with release 6.1.1, 6.1.1 with the decorator changed back to 1, and my changes

Version          Test Run Time    Run Keyword Run Time
6.1              35sec            40-100ms
6.1-resolve=1    19.1sec          7ms    
6.1-my-change    19.4sec          7ms       

In all cases 5ms of that time is spec in our Python library.

[pekkaklarck]

I was able to easily reproduce the performance regression with the following example. It runs in ~1.4s on my machine with the latest code and in ~0.7s with RF 5.0. I also tested that if I disable recommendations altogether, the execution time drops to ~0.8s. Still slower than with RF 5.0 but much closer!

*** Variables ***
${KW}     No Operation

*** Test Cases ***
Example
    FOR    ${i}    IN RANGE    1000
        Run Keyword    ${KW}
    END

You are most likely right that this is the root cause for the performance regression reported in #4659. I had already earlier analyzed that the problem was caused by a fix for #1595 that we didn't want to revert. I thought that slowness was caused only by needing to look for the keyword twice, and in a comment wrote that fixing isn't easy. It seems I was wrong and slowness was mostly caused by finding recommendations that were never even used for anything. Great that you found the real root cause!

The fix looks good and I'll merge this shortly. I'll also add #4659 to RF 7.0 scope and close it.

PS: You may want to consider using library search order instead of using Run Keyword. Depending on your usage, it will likely help cleaning up your tests and will also be faster without the extra overhead by Run Keyword. See the aforementioned comment for more details.