fixing subprocess to use system buffer instead of being unbuffered

[jdmeyer3]

While testing large datasets in actions, I came across massive CPU spikes for a relatively small dataset (~8MB) being returned from the action. While investigating the issue I found two problems that were consuming the CPU. The first issue was documented in #4798. The second issue was with how the action was created. When the subprocess is created without the buffer size, it defaults to zero (unbuffered). According to the subprocess docs,

"If you experience performance issues, it is recommended that you try to enable buffering by setting bufsize to either -1 or a large enough positive value (such as 4096)." https://docs.python.org/2/library/subprocess.html.

The bufsize can be a discussion whether to use the system default or a large value. After making this change on my local machine I noticed a performance increase minus the MongoEngine issue which still persists.

[blag]

How does this impact the live execution results?

[arm4b]

+1 to @blag I'm wondering too if this change may affect the real-time live output from actions like st2 execution tail?

Performance wise, you may also benefit from disabling "live output" in your environment

st2/conf/st2.conf.sample

Lines 25 to 26 in a643ba7

	# True to store and stream action output (stdout and stderr) in real-time.
	stream_output = True

which also takes a lot of CPU cycles.

[jdmeyer3]

@blag At a -1 value for buffering, it would depend on your system. Some systems will fully buffer while others will buffer 4KB - 8KB of memory before flushing. If the buff value is hardcoded to 4096 then the live output should be able to display the information in 4K increments. This is to avoid having the CPU process the output from the execution one byte at a time and instead buffer to reduce the compute overhead. I can change it to a hardcoded buffer value instead of the system default if that works better for you.

[Kami]

Yeah, IIRC, in the past we've seen some issues with real time output hanging on some distros and that's why we used unbuffered output.

I'm fine with this change as long as we document it and make it configurable via config option in st2.conf (e.g. actionrunner.stream_output_buffer_size).

This way users who would potentially have issues can change that value in the config instead of needing to directly edit the code.

I can make that change and merge that into master.

[Kami]

I pushed the following changes:

1. Add new actionrunner.stream_output_buffer_size config option and default it to -1 per @jdmeyer3 observations. 2f96d5d

2. Only use bufsize=-1 for Python runner actions. Changing the default for all the st2common.util.green.shell.run_command() function calls would affect a lot of other code as well so it's better to keep the change small and more contained. 25ea404, 2f96d5d.

3. Add some basic tests for it. 711436f

4. Document this change in upgrade notes - Add changelog entry for changes StackStorm/st2@4803 st2docs#941.

We should still keep an eye on potential regressions on other distributions, but I think now that the value can be controlled via config option, it's safe enough to be merged into master.

If users experience issues, they can change the config option value to revert back to the old behavior.

[Kami]

@jdmeyer3^ let me know if you are OK with the changes above.

[Kami]

There were some weird / random Travis test failures.

I need to push some debugging changes (0b76bd5) which will hopefully provide us with more information and context which will allow us to troubleshoot such issues in the future.

[jdmeyer3]

@Kami Ya, those changes are fine with me.

[Kami]

Yay, all green!

Thanks again for the contribution. I will go ahead and merge it into master.

@jdmeyer3 When you get a chance, can you please test the version / changes from master and confirm it's working as expected?