search

bodo-hugo-barwich / Process

Perl Module for Multiprocessing
Other
1 stars 2 forks source link

Perl open3() Function to create the Subprocess #1

Closed bodo-hugo-barwich closed 4 years ago

bodo-hugo-barwich commented 4 years ago

The actual Implementation of the Subprocess with the Perl fork() Function and the Backticks `` Operator forks the Main Script in order to run the Subprocess in non-blocking Mode.

Now the Perl open3() Function creates the Subprocess also in non-blocking Mode. Additionally the open3() Function does not use the Bash Interpreter to run the command. So this could improve the Performance and save System Resources. The only Draw-Back could be that Execution Time Measurement might not be that precise.

The Suggestion is to replace the fork() Logic with an open3() Logic.

bodo-hugo-barwich commented 4 years ago

At the moment the Execution Time of the Process::SubProcess::Wait() Loop is completely dependent on the _read_timeout Attribute Value since this is the TIMEOUT Parameter for the IO::Select::can_read() Function. So the measured time in the Process::SubProcess::Wait() Loop does not correspond to the actual Command Execution Time. To block until the Command execution end would would make the Library unable to read big outputs on the output pipes. Only disabling the TIMEOUT of the IO::Select::can_read() Function as by https://learn.perl.org/faq/perlfaq5.html#How-can-I-tell-whether-theres-a-character-waiting-on-a-filehandle would make the Process::SubProcess able to measure the execution time of the Command approximately. So Process::SubProcess::setCheckInterval(), Process::SubProcess::setReadTimeout() and Process::SubProcess::setProfiling() become mutually exclusive.

bodo-hugo-barwich commented 4 years ago

The Test "Execution Time = Read Timeout" in t/test_performance.t shows that IO::Select::can_read() will unblock as soon as the script finishes although the TIMEOUT was not reached yet. The Test Script t/quiet_script.pl is usually mute:

$ date +"%s.%N" ; t/quiet_script.pl 3 ; date +"%s.%N"
1599398963.757632542
1599398966.772951532

Still in the Test with a Process::SubProcess::setReadTimeout() of 2 seconds the measured time was of 3 seconds as configured in the Pause Parameter and not 4 seconds as expected:

$ ./test_performance.t
Test: 'Execution Time = Read Timeout' do ...
ok 9 - Read Timeout activated
ok 10 - Profiling enabled
script 'quiet_script.pl' Start - Time Now: '1599398837.1946' s
ok 11 - script 'quiet_script.pl': Execution correct
script 'quiet_script.pl' End - Time Now: '1599398840.21065' s
script 'quiet_script.pl' run in '3016.04914665222' ms
ok 12 - Measured Time is greater than the expected Time
Execution Time: '3.014514'
EXIT CODE: '0'
STDOUT: 'Time Execution: '3.014514' s
'
STDERR: ''

So on the Execution of a Single Child Process the Process::SubProcess::setProfiling() does not need to be disabled.

bodo-hugo-barwich commented 4 years ago

Since the Process::SubProcess::getCheckInterval() Feature is not necessary anymore it will be removed. This will especially affect the Process::SubProcess::Wait Method and also the Process::SubProcess::Group Package. But for API Consistency the check Parameter will be forwarded to the Process::SubProcess::setReadTimeout() Method.

bodo-hugo-barwich commented 4 years ago

The Execution Time of the Script t/test_script.pl is measured by the shell as of 25.9 ms:

$ date +"%s.%N" ; t/test_script.pl ; date +"%s.%N"
1600619235.063966281
Start - Time Now: '1600619235.08758' s
script 'test_script.pl' START 0 ERROR
script 'test_script.pl' START 0
script 'test_script.pl' PAUSE '0' ...
script 'test_script.pl' END 1
script 'test_script.pl' END 1 ERROR
End - Time Now: '1600619235.08779' s
script 'test_script.pl' done in '0.205039978027344' ms
script 'test_script.pl' EXIT '0'
1600619235.089883482
$ echo "scale=3; (35.089883482-35.063966281)*1000"|bc -l
25.917201000

The Perl Module Process::SubProcess measures the Execution Time of 24.6 ms while the Process::SubProcess::Run() Method was measured as 25.6 ms. So the Perl Module Process::SubProcess adds only an overhead of hardly 1 ms for the launch of a Child Process which is roughly the same result as was obtained measuring it with the Shell. Thus the overhead was heavily reduced in comparison with the former Version which used the Perl fork() Function which was about 5 ms

Test: 'Profiling' do ...
ok 2 - Profiling activated
script 'test_script.pl' Start - Time Now: '1600620539.13294' s
ok 3 - script 'test_script.pl': Execution correct
script 'test_script.pl' End - Time Now: '1600620539.15858' s
script 'test_script.pl' run in '25.6369113922119' ms
ok 4 - Execution Time was measured
Execution Time: '0.024603'
EXIT CODE: '0'
STDOUT: 'Start - Time Now: '1600620539.15668' s
script 'test_script.pl' START 0
script 'test_script.pl' PAUSE '0' ...
script 'test_script.pl' END 1
End - Time Now: '1600620539.15688' s
script 'test_script.pl' done in '0.194072723388672' ms
script 'test_script.pl' EXIT '0'
'
STDERR: 'script 'test_script.pl' START 0 ERROR
script 'test_script.pl' END 1 ERROR
'

And the Process::SubProcess Module is 3 ms faster than its reference the Capture::Tiny Module which 28.3 ms for the same task:

Test: 'Capture::Tiny Profiling' do ...
script 'test_script.pl' Start - Time Now: '1600623400.38676' s
script 'test_script.pl' End - Time Now: '1600623400.41507' s
script 'test_script.pl' run in '28.3050537109375' ms
EXIT CODE: '0'
STDOUT: 'Start - Time Now: '1600623400.41307' s
script 'test_script.pl' START 0
script 'test_script.pl' PAUSE '0' ...
script 'test_script.pl' END 1
End - Time Now: '1600623400.41331' s
script 'test_script.pl' done in '0.238895416259766' ms
script 'test_script.pl' EXIT '0'
'
STDERR: 'script 'test_script.pl' START 0 ERROR
script 'test_script.pl' END 1 ERROR
'
bodo-hugo-barwich commented 4 years ago

Having set TIMEOUT to "0" at IO::Select::can_read() enables the Process::SubProcess::Group::Wait() Method to measure the Child Process Execution Time correctly as seen in the "Process::SubProcess::Group Profiling" test sequence:

Test: 'Process::SubProcess::Group Profiling' do ...
ok 8 - Profiling activated
ok 9 - Profiling activated
ok 10 - Profiling activated
ok 11 - scripts (count: '3'): added correctly
Process Group Execution Start - Time Now: '1601118305.01331' s
ok 12 - Process Group Execution: Execution correct
Process Group Execution End - Time Now: '1601118314.06227' s
Process Group Execution finished in '9048.95806312561' ms
ok 13 - Process No. '0': Listed correctly
Process (7069) 'test-script:3s':
ok 14 - Execution Time was measured
Read Timeout: '0'
Execution Time: '3.034142'
EXIT CODE: '0'
STDOUT: 'Start - Time Now: '1601118305.04656' s
script 'test_script.pl' START 0
script 'test_script.pl' PAUSE '3' ...
script 'test_script.pl' END 1
End - Time Now: '1601118308.0468' s
script 'test_script.pl' done in '3000.24509429932' ms
script 'test_script.pl' EXIT '0'
'
STDERR: 'script 'test_script.pl' START 0 ERROR
script 'test_script.pl' END 1 ERROR
'
ok 15 - Process No. '1': Listed correctly
Process (7070) 'test-script:5s':
ok 16 - Execution Time was measured
Read Timeout: '0'
Execution Time: '5.032457'
EXIT CODE: '0'
STDOUT: 'Start - Time Now: '1601118305.04752' s
script 'test_script.pl' START 0
script 'test_script.pl' PAUSE '5' ...
script 'test_script.pl' END 1
End - Time Now: '1601118310.04774' s
script 'test_script.pl' done in '5000.21600723267' ms
script 'test_script.pl' EXIT '0'
'
STDERR: 'script 'test_script.pl' START 0 ERROR
script 'test_script.pl' END 1 ERROR
'
ok 17 - Process No. '2': Listed correctly
Process (7071) 'test-script:9s':
ok 18 - Execution Time was measured
Read Timeout: '0'
Execution Time: '9.043087'
EXIT CODE: '0'
STDOUT: 'Start - Time Now: '1601118305.06028' s
script 'test_script.pl' START 0
script 'test_script.pl' PAUSE '9' ...
script 'test_script.pl' END 1
End - Time Now: '1601118314.06051' s
script 'test_script.pl' done in '9000.23007392883' ms
script 'test_script.pl' EXIT '0'
'
STDERR: 'script 'test_script.pl' START 0 ERROR
script 'test_script.pl' END 1 ERROR
'

Executing the same Child Process Set with Process::SubProcess::Group::setCheckInterval(6) shows that the Process::SubProcess::setReadTimeout() is set to "2" proportionally to achieve an allover Check Sequence Cycle Execution time of 6 seconds. This results in pending Zombie Child Processes until the Check Sequence Cycle is completed and the Execution Time is measured in multiple of Process::SubProcess::getReadTimeout() or Process::SubProcess::Group::getCheckInterval() because the Check Sequence Cycle will not reap them until the Cycle is completed. This is demonstrated in the "Process::SubProcess::Group Profiling Quiet" Test Sequence:

Test: 'Process::SubProcess::Group Profiling Quiet' do ...
ok 19 - Profiling activated
ok 20 - Profiling activated
ok 21 - Profiling activated
ok 22 - scripts (count: '3'): added correctly
ok 23 - Read Timeout activated
Process Group Execution Start - Time Now: '1601118314.06572' s
ok 24 - Process Group Execution: Execution correct
Process Group Execution End - Time Now: '1601118323.08969' s
Process Group Execution finished in '9023.97489547729' ms
ok 25 - Process No. '0': Listed correctly
Process (7072) 'quiet-script:3s' finished with [0]:
ok 26 - Execution Time was measured
Read Timeout: '2'
Execution Time: '6.019002'
ERROR CODE: '0'
EXIT CODE: '0'
STDOUT: ''
STDERR: ''
ok 27 - Process No. '1': Listed correctly
Process (7073) 'quiet-script:5s' finished with [0]:
ok 28 - Execution Time was measured
Read Timeout: '2'
Execution Time: '6.016740'
ERROR CODE: '0'
EXIT CODE: '0'
STDOUT: ''
STDERR: ''
ok 29 - Process No. '2': Listed correctly
Process (7074) 'quiet-script:9s' finished with [0]:
ok 30 - Execution Time was measured
Read Timeout: '2'
Execution Time: '9.017560'
ERROR CODE: '0'
EXIT CODE: '0'
STDOUT: ''
STDERR: ''

Further more the Process::SubProcess::Group::setTimeout() also is affected by the Process::SubProcess::Group::setCheckInterval() since it becomes a multiple of Process::SubProcess::getReadTimeout(). Even having introduced the Execution Timeout check in the Process::SubProcess::Group::Check() Method to stop checking if the Execution Timeout is reached the Check Sequence Cycle cannot reach this point before the Process::SubProcess::getReadTimeout() is fulfilled. This is observed in the "Process::SubProcess::Group Execution Timeout" Test Sequence:

Test: 'Process::SubProcess::Group Execution Timeout' do ...
ok 31 - Profiling activated
ok 32 - Profiling activated
ok 33 - Profiling activated
ok 34 - scripts (count: '3'): added correctly
ok 35 - Check Interval activated
ok 36 - Execution Timeout activated
Process Group Execution Start - Time Now: '1601118323.09578' s
ok 37 - Process Group Execution: Execution failed as expected
Process Group Execution End - Time Now: '1601118331.1405' s
Process Group Execution finished in '8044.72088813782' ms
Process Group ERROR CODE: '4'
ok 38 - Process Group Execution: ERROR CODE is correct
Process Group STDOUT: '2020-09-26 12:05:23 : Sub Process No. '0' - 'test-script:3s': Launching ...
2020-09-26 12:05:23 : Sub Process No. '0' - 'test-script:3s': Launch OK - PID (7075)
2020-09-26 12:05:23 : Sub Process No. '1' - 'test-script:5s': Launching ...
2020-09-26 12:05:23 : Sub Process No. '1' - 'test-script:5s': Launch OK - PID (7076)
2020-09-26 12:05:23 : Sub Process No. '2' - 'test-script:13s': Launching ...
2020-09-26 12:05:23 : Sub Process No. '2' - 'test-script:13s': Launch OK - PID (7077)
2020-09-26 12:05:29 : Sub Process (7075) 'test-script:3s': finished with [0]
2020-09-26 12:05:29 : Sub Process (7076) 'test-script:5s': finished with [0]
'
Process Group STDERR: 'Sub Processes 'Count: 1': Execution timed out!
Execution Time '8 / 7'
Processes will be terminated.
Sub Processes: Processes terminating ...
'
ok 39 - Process No. '0': Listed correctly
Process (7075) 'test-script:3s' finished with [0]:
ERROR CODE: '0'
EXIT CODE: '0'
ok 40 - Execution Time was measured
Read Timeout: '2'
Execution Time: '6.039233'
STDOUT: 'Start - Time Now: '1601118323.12841' s
script 'test_script.pl' START 0
script 'test_script.pl' PAUSE '3' ...
script 'test_script.pl' END 1
End - Time Now: '1601118326.12876' s
script 'test_script.pl' done in '3000.35691261292' ms
script 'test_script.pl' EXIT '0'
'
STDERR: 'script 'test_script.pl' START 0 ERROR
script 'test_script.pl' END 1 ERROR
'
ok 41 - Process No. '1': Listed correctly
Process (7076) 'test-script:5s' finished with [0]:
ERROR CODE: '0'
EXIT CODE: '0'
ok 42 - Execution Time was measured
Read Timeout: '2'
Execution Time: '6.036622'
STDOUT: 'Start - Time Now: '1601118323.12448' s
script 'test_script.pl' START 0
script 'test_script.pl' PAUSE '5' ...
script 'test_script.pl' END 1
End - Time Now: '1601118328.12473' s
script 'test_script.pl' done in '5000.25105476379' ms
script 'test_script.pl' EXIT '0'
'
STDERR: 'script 'test_script.pl' START 0 ERROR
script 'test_script.pl' END 1 ERROR
'
ok 43 - Process No. '2': Listed correctly
Process (7077) 'test-script:13s' finished with [4]:
ERROR CODE: '4'
EXIT CODE: '-1'
ok 44 - Execution Time not measured as expected
Read Timeout: '2'
Execution Time: '-1'
STDOUT: ''
STDERR: 'script 'test_script.pl' START 0 ERROR
Sub Process (7077) 'test-script:13s': Process terminating ...
'
ok 45 - '1' Process timed out as expected
Process Group Execution Timeout - Count: '1'
domibay-hugo commented 4 years ago

On BareMetal Systems the Process::SubProcess::Run() Method runs faster than the Capture::Tiny::capture() Function:

$ cat /etc/centos-release
CentOS Linux release 7.6.1810 (Core)
$ t/test_performance.t
Test: 'Capture::Tiny Profiling' do ...
script 'test_script.pl' Start - Time Now: '1601376444.86369' s
script 'test_script.pl' End - Time Now: '1601376444.88312' s
script 'test_script.pl' run in '19.4289684295654' ms
EXIT CODE: '0'
STDOUT: 'Start - Time Now: '1601376444.88187' s
script 'test_script.pl' START 0
script 'test_script.pl' PAUSE '0' ...
script 'test_script.pl' END 1
End - Time Now: '1601376444.882' s
script 'test_script.pl' done in '0.133037567138672' ms
script 'test_script.pl' EXIT '0'
'
STDERR: 'script 'test_script.pl' START 0 ERROR
script 'test_script.pl' END 1 ERROR
'

Test: 'Profiling' do ...
ok 11 - Profiling activated
script 'test_script.pl' Start - Time Now: '1601376444.88359' s
ok 12 - script 'test_script.pl': Execution correct
script 'test_script.pl' End - Time Now: '1601376444.90018' s
script 'test_script.pl' run in '16.5910720825195' ms
ok 13 - Execution Time was measured
Execution Time: '0.016168'
EXIT CODE: '0'
STDOUT: 'Start - Time Now: '1601376444.89925' s
script 'test_script.pl' START 0
script 'test_script.pl' PAUSE '0' ...
script 'test_script.pl' END 1
End - Time Now: '1601376444.89935' s
script 'test_script.pl' done in '0.0998973846435547' ms
script 'test_script.pl' EXIT '0'
'
STDERR: 'script 'test_script.pl' START 0 ERROR
script 'test_script.pl' END 1 ERROR
'

But on the GitHub Workflow Docker Container the Capture::Tiny::capture() function is fater:

Current runner version: '2.273.4'
Operating System
  Ubuntu
  18.04.5
  LTS
Virtual Environment
  Environment: ubuntu-18.04
  Version: 20200920.1
  Included Software: https://github.com/actions/virtual-environments/blob/ubuntu18/20200920.1/images/linux/Ubuntu1804-README.md
Run t/test_performance.t
  t/test_performance.t
  shell: /bin/bash -e {0}
Test: 'Capture::Tiny Profiling' do ...
script 'test_script.pl' Start - Time Now: '1601371365.19542' s
script 'test_script.pl' End - Time Now: '1601371365.20896' s
script 'test_script.pl' run in '13.5388374328613' ms
EXIT CODE: '0'
STDOUT: 'Start - Time Now: '1601371365.20801' s
script 'test_script.pl' START 0
script 'test_script.pl' PAUSE '0' ...
script 'test_script.pl' END 1
End - Time Now: '1601371365.20816' s
script 'test_script.pl' done in '0.153064727783203' ms
script 'test_script.pl' EXIT '0'
'
STDERR: 'script 'test_script.pl' START 0 ERROR
script 'test_script.pl' END 1 ERROR
'

Test: 'Profiling' do ...
ok 11 - Profiling activated
script 'test_script.pl' Start - Time Now: '1601371365.20939' s
ok 12 - script 'test_script.pl': Execution correct
script 'test_script.pl' End - Time Now: '1601371365.22413' s
script 'test_script.pl' run in '14.739990234375' ms
ok 13 - Execution Time was measured
Execution Time: '0.014338'
EXIT CODE: '0'
STDOUT: 'Start - Time Now: '1601371365.22324' s
script 'test_script.pl' START 0
script 'test_script.pl' PAUSE '0' ...
script 'test_script.pl' END 1
End - Time Now: '1601371365.22339' s
script 'test_script.pl' done in '0.149011611938477' ms
script 'test_script.pl' EXIT '0'
'
STDERR: 'script 'test_script.pl' START 0 ERROR
script 'test_script.pl' END 1 ERROR
'