run time depends significantly on the amount of text printed by the command under test

[AntoniMarcinek]

Depending on settings the program which I am testing with shellspec can produce 100 lines of output to stdout, 1000 lines or 10000 lines. The run time of the program itself does not change significantly, but once it is wrapped in shellspec test it takes 9s, 20s and 300s respectively. @ko1nksm do you understand this effect? If it is not obvious to you, I will produce a demonstration.

[ko1nksm]

Are there a large number of expectations (the)? The line/word subject/modifier parses the output sequentially from the beginning each time it is used, so it may be extremely slow depending on the number of lines. I'm sure there is room for improvement, but I didn't originally assume for that many lines. because unit tests usually use a small amount of data to test.

If it is not obvious to you, I will produce a demonstration.

Detailed data (e.g., number of seconds) is not necessary, but a simple sample code here would be appreciate to make it easier to understand.

[AntoniMarcinek]

I prepared a test repo: https://gitlab.com/amarcine/test-long-output
To perform the check just execute the run.sh script that will time different conditions for shellspec.

I made my checks on bash 5.0.3 if that might be significant. My results were:

long_no_check_spec.sh

real	6m40,312s
user	6m25,875s
sys	0m14,187s
-------------
long_present_spec.sh

real	1m42,737s
user	1m33,582s
sys	0m9,070s
-------------
short_no_check_spec.sh

real	0m0,398s
user	0m0,343s
sys	0m0,027s
-------------
short_present_spec.sh

real	0m0,338s
user	0m0,271s
sys	0m0,039s
-------------

I am not only surprised by the fact that the run time depends so much on the amount of text printed, but also that making no checks gives much longer run time - 4 times in my case.

I understand that shellspec doesn't expect commands producing lots of output, but its behaviour without checks is rather strange. I could accept that doing many complicated checks on large text output could increase the run time, but as you see from the test cases there are essentially no checks.

[ko1nksm]

Thank you for the test repository.

Regardless of whether you want to check the output or not, it will take some time because the output contents are loaded into memory. However, it is strange that it takes longer not to check. I suspected the file cache and reversed the execution order, but it didn't seem to change. Also, I changed to dash instead of bash, but it will take longer not to check. This needs to be investigated.

The output is read line by line by the shell with the read command. Therefore, the number of lines has a larger impact than the file size. Using cat command to load may be faster, but it is an external command, so it will be slower for small data. This is to be expected, since I value performance with small data, but still, taking a few minutes for only 600kb is a bit long.

By change to read output content when checking, It can improve the speed when not checked. However, in general we would check the output. I don't think it's very effective in a realistic test, but in your case, do you often not check the output?

[ko1nksm]

If the output is not checked, a warning will be displayed along with the output contents. Since all the output contents are included in the report protocol, I can assume that this is causing the slowdown.

We need to to add the ability to suppress warnings (#122), or to improve the warning content and reporting protocol.

[AntoniMarcinek]

My usual use case - integration tests

In my case I would most often not check the output. I use it for integration tests of a program and associated library which processes high energy physics data. So the program makes some calculations, the results of which are streamed in binary or ASCII files, but never to the stdout. The output is used there only to see which steps were passed, what DB entries were used etc. So as more or less verbose progress and debug messages. The output is most useful to understand when something fails either getting the answer in the output itself or comparing the output from a successful and failed runs. Therefore I need the output stored along with test results - hence the improvements I asked earlier regarding the JUnit xml - but usually I do not assert the output content.

My understanding of the reasons for slowness and possible solutions

OK, so if I understand correctly the reason why shellspec is slow with many lines of the output is because it first redirects the output to a file and then reads from this file line by line using read instead of everything at once. This reading happens in 2 cases:

1. when asserting the output only some lines are read (faster)
2. when not asserting all are read to report the warning (slower)

Ultimate solution - change of the way how output is loaded

Both cases could be made faster for large output moving from read to cat, but this screws up unit tests which tend to operate on a tiny output. I propose to add an option that will switch between the 2 methods on user request with read being the default.

Btw how do you manage the choice of tools depending on their availability or requests - do you make a choice when the tool is used or in some initialization phase of shellspec to set once and use many times? It is probably a stupid question, so sorry, but for an object oriented software I would expect initialization phase to compose the behaviour, while for procedure oriented software, as I understand shellspec is due to shell not having OOP features, the choice is not so natural.

Partial solution - speeding up when no assertions are done

Irrespective of cat vs read, case 2. could be made faster by simply refraining from printing warnings. I think #122 should definitely be implemented independently from my above proposal.

But I do have a question - what happens for the JUnit report? - supposing the warnings are gone but I still want the full output in JUnit xml, will this again use read and be slow?

[ko1nksm]

I will make improvements due to performance issues and shells cannot handle binary data, but ShellSpec is a unit testing framework. I don't deny that you can use it for integration testing, but it is not a high priority and there will be other omissions to consider. If there are conflicting requirements, use as a unit testing will be given priority.

The performance problem of this issue will be solved by not reading unnecessary output. To this end, I plan to make the following improvements.

• Read output only if it is referenced.
• Do not include contents of output on warning in reporting protocol.

OK, so if I understand correctly the reason why shellspec is slow with many lines of the output is because it first redirects the output to a file and then reads from this file line by line using read instead of everything at once. This reading happens in 2 cases:

The read is also slow, but more than that, the amount of reporting protocol used to communicate with the specfile results and the reporter is the main cause. I knew from the beginning that the reporting protocol was slow, so the mistake is including the entire output in the warning.

Ultimate solution - change of the way how output is loaded

Changing read to cat is an improvement for large data reads, but the read is unnecessary if you don't need to refer to it in the first place. In your case, you don't check the output, so reading is unnecessary, and changing read to cat won't improve the situation. For that reason, the ability to switch between cat and read is not planned to be implemented (for now).

And, I think if the data is large, we will want to compare it with the correct file. I mean, #138. (I'm sorry I've been putting off this PR. I haven't considered it enough yet.)

For small data, cat may have performance degradation due to fork, but We can use read -r -d "" or readarray, which are available in some shells, to improve the read speed without degrading performance. I plan to improve performance using these commands.

Also, if you really want to use cat, most of the internal shellspec functions can be redefined in spec_helper.sh.

shellspec_readfile() {
  eval "$1=\$(cat \"\$2\"; echo _); $1=\${$1%_}"
}

Btw how do you manage the choice of tools depending on their availability or requests - do you make a choice when the tool is used or in some initialization phase of shellspec to set once and use many times?

I don't understand the meaning of the question. I think it is common for any command to change its behavior with configuration files, options, environment variables, etc. It also doesn't even matter if it is object-oriented or not.

I think #122 should definitely be implemented independently from my above proposal.
Yes, it is another issue.

But I do have a question - what happens for the JUnit report? - supposing the warnings are gone but I still want the full output in JUnit xml, will this again use read and be slow?

In the case of the JUnit formatter, the contents of the stdout and stderr are not included in the reporting protocol, so they are not directly related to this issue. However, it may already be slow for another reason. This will be addressed in another issue.

[ko1nksm]

@AntoniMarcinek If you have ideas about integration testing, please post them here (#187).

[AntoniMarcinek]

Thanks for all the explanations!

Sure, it is clear that ShellSpec prioritizes unit testing.

The 2 improvements you mention look very reasonable.

While comparing large output to file is useful in itself, using string matchers is also useful. In my use case there is a lot of text printed from other parts of the system than the specific subject of my test. So while I would check file equality for some specific files produced by the executable, I wouldn't really do it on stdout/err.

If you would improve performance using read -r -d "" or readarray, great. But I guess for my case most of the improvement will actually come from the 2 bullets you wrote.

Thanks for the tip with overriding functions in the helper. Looks like this pretty much removes any need for an option to choose between cat and read.

Please forget the question "how do you manage the choice of tools...".

In the test project one can switch off the junit in .shellspec. It has some effect, but looks like the main part of the problem lies in the reporting protocol. As I wrote in #184 I am not happy at all about that issue. I would be glad if you didn't change that part or at least put it behind an option.

Regarding the integration tests discussion, should I repeat what is already in the issue we iterated several times for the sake of completeness/clarity or you want me to post any new ideas I have?

[ko1nksm]

The number of warning lines has been reduced and the output is not read when it is not needed. I believe these fixes (#188) resolved the direct problem of this Issue.

Regarding the integration tests discussion, should I repeat what is already in the issue we iterated several times for the sake of completeness/clarity or you want me to post any new ideas I have?

If you have something else you want to write.

[AntoniMarcinek]

Thank you! Indeed it seems to fix the problem.

I will iterate on the integration tests discussion some time later.