Performance drop with subprocesses #43
Description
I have an application that will call several codecs as subprocesses to decode audio files in parallel, using asyncio.create_subprocess_exec. The subprocesses will stream the decoded binary through pipes. I want to integrate it with a Qt GUI, so I want to transfer to qasync. However when I'm testing the code, I found serious performance drop. It's tricky to write some minimal example for reproducing, but I can post the profiling result with yappi package:
Using built-in event loop:
name ncall tsub ttot tavg
C:\Users\cmput\.conda\envs\qt\lib\asyncio\streams.py:493 StreamReader._wait_for_data 8835 23.96956 23.98725 0.002715
d:\github\fluss\fluss\codecs.py:105 flac.encode_async 1 5.168207 5.216069 5.216069
C:\Users\cmput\.conda\envs\qt\lib\asyncio\base_subprocess.py:226 _WindowsSubprocessTransport._wait 6 5.168127 5.168131 0.861355
d:\github\fluss\fluss\utils.py:51 merge_tracks 1 4.479253 10.00827 10.00827
C:\Users\cmput\.conda\envs\qt\lib\asyncio\streams.py:643 StreamReader.read 8775/5 1.147379 20.03824 0.002284
C:\Users\cmput\.conda\envs\qt\lib\asyncio\base_events.py:1784 ProactorEventLoop._run_once 5445 0.385968 10.02511 0.001841
d:\github\fluss\fluss\codecs.py:134 flac.decode_async 5 0.292958 20.39943 4.079885
..s\cmput\.conda\envs\qt\lib\asyncio\proactor_events.py:271 _ProactorReadPipeTransport._loop_reading 17651 0.076452 1.798698 0.000102
C:\Users\cmput\.conda\envs\qt\lib\asyncio\windows_events.py:719 IocpProactor._register 17636 0.075778 0.398914 0.000023
C:\Users\cmput\.conda\envs\qt\lib\asyncio\windows_events.py:440 IocpProactor.recv 17643 0.075101 1.408057 0.000080
C:\Users\cmput\.conda\envs\qt\lib\asyncio\base_events.py:738 ProactorEventLoop._call_soon 44264 0.070941 0.163611 0.000004
C:\Users\cmput\.conda\envs\qt\lib\asyncio\events.py:32 Handle.__init__ 44264 0.067399 0.083677 0.000002
C:\Users\cmput\.conda\envs\qt\lib\asyncio\base_events.py:709 ProactorEventLoop.call_soon 44264 0.062985 0.240528 0.000005
C:\Users\cmput\.conda\envs\qt\lib\asyncio\windows_events.py:766 IocpProactor._poll 5446 0.058976 5.251805 0.000964
C:\Users\cmput\.conda\envs\qt\lib\asyncio\events.py:79 Handle._run 44263 0.054110 4.360696 0.000099
C:\Users\cmput\.conda\envs\qt\lib\asyncio\windows_events.py:49 _OverlappedFuture.__init__ 17636 0.043227 0.048583 0.000003
C:\Users\cmput\.conda\envs\qt\lib\asyncio\streams.py:471 StreamReader.feed_data 17629 0.042104 0.507448 0.000029
..mput\.conda\envs\qt\lib\asyncio\windows_events.py:381 ProactorEventLoop._make_subprocess_transport 6 0.040638 0.067062 0.011177
C:\Users\cmput\.conda\envs\qt\lib\_weakrefset.py:70 WeakSet.__contains__ 35292 0.028496 0.028496 0.000001
..\cmput\.conda\envs\qt\lib\asyncio\proactor_events.py:246 _ProactorReadPipeTransport._data_received 17640 0.027922 0.189725 0.000011
C:\Users\cmput\.conda\envs\qt\lib\asyncio\base_subprocess.py:194 _WindowsSubprocessTransport._call 17653 0.024575 0.123610 0.000007
...
Using QEventLoop:
name ncall tsub ttot tavg
C:\Users\cmput\.conda\envs\qt\lib\asyncio\streams.py:493 StreamReader._wait_for_data 8550 1250.373 1250.401 0.146246
d:\github\fluss\fluss\utils.py:51 merge_tracks 1 269.2083 274.9219 274.9219
C:\Users\cmput\.conda\envs\qt\lib\site-packages\qasync\_windows.py:78 _IocpProactor.recv 17074 203.4781 206.8020 0.012112
d:\github\fluss\fluss\codecs.py:105 flac.encode_async 1 5.295270 5.399147 5.399147
C:\Users\cmput\.conda\envs\qt\lib\asyncio\base_subprocess.py:226 _WindowsSubprocessTransport._wait 6 5.290173 5.290175 0.881696
C:\Users\cmput\.conda\envs\qt\lib\reprlib.py:137 Repr.repr_instance 128261.. 2.876891 19.59483 0.000153
..s\cmput\.conda\envs\qt\lib\asyncio\windows_events.py:381 QIOCPEventLoop._make_subprocess_transport 6 2.349893 2.445466 0.407578
C:\Users\cmput\.conda\envs\qt\lib\logging\__init__.py:284 LogRecord.__init__ 171485 1.782854 6.013292 0.000035
C:\Users\cmput\.conda\envs\qt\lib\asyncio\base_events.py:1522 QIOCPEventLoop.connect_read_pipe 11 1.746174 1.754524 0.159502
C:\Users\cmput\.conda\envs\qt\lib\logging\__init__.py:431 PercentStyle._format 171485 1.375643 1.375643 0.000008
C:\Users\cmput\.conda\envs\qt\lib\logging\__init__.py:1069 FileHandler.emit 171485 1.347615 15.69609 0.000092
C:\Users\cmput\.conda\envs\qt\lib\asyncio\streams.py:643 StreamReader.read 8492/5 1.327644 1246.508 0.146786
C:\Users\cmput\.conda\envs\qt\lib\ntpath.py:180 split 171485 1.003509 2.075590 0.000012
C:\Users\cmput\.conda\envs\qt\lib\site-packages\qasync\__init__.py:254 _SimpleTimer.timerEvent 42838 0.849470 270.1640 0.006307
d:\github\fluss\fluss\codecs.py:134 flac.decode_async 5 0.765147 1249.679 249.9358
C:\Users\cmput\.conda\envs\qt\lib\logging\__init__.py:1174 FileHandler.emit 171485 0.721638 16.41773 0.000096
C:\Users\cmput\.conda\envs\qt\lib\site-packages\qasync\__init__.py:423 QIOCPEventLoop.call_later 42838 0.701538 40.70495 0.000950
C:\Users\cmput\.conda\envs\qt\lib\logging\__init__.py:1502 Logger.findCaller 171485 0.647646 1.488996 0.000009
C:\Users\cmput\.conda\envs\qt\lib\ntpath.py:124 splitdrive 171524 0.611331 0.765882 0.000004
C:\Users\cmput\.conda\envs\qt\lib\logging\__init__.py:651 Formatter.format 171485 0.597927 4.994302 0.000029
C:\Users\cmput\.conda\envs\qt\lib\logging\__init__.py:1553 Logger._log 171485 0.510051 26.41886 0.000154
C:\Users\cmput\.conda\envs\qt\lib\logging\__init__.py:1058 FileHandler.flush 171485 0.498120 3.152054 0.000018
C:\Users\cmput\.conda\envs\qt\lib\genericpath.py:121 _splitext 171485 0.483204 0.796615 0.000005
C:\Users\cmput\.conda\envs\qt\lib\logging\__init__.py:1412 Logger.debug 171475 0.468869 27.05055 0.000158
C:\Users\cmput\.conda\envs\qt\lib\logging\__init__.py:1633 Logger.callHandlers 171485 0.445889 17.77421 0.000104
C:\Users\cmput\.conda\envs\qt\lib\asyncio\base_futures.py:44 _future_repr_info 111125 0.437028 16.97227 0.000153
C:\Users\cmput\.conda\envs\qt\lib\logging\__init__.py:937 FileHandler.handle 171485 0.433702 17.32832 0.000101
C:\Users\cmput\.conda\envs\qt\lib\asyncio\proactor_events.py:72 _ProactorReadPipeTransport.__repr__ 51288 0.390298 9.458899 0.000184
C:\Users\cmput\.conda\envs\qt\lib\ntpath.py:44 normcase 171485 0.353953 0.576882 0.000003
C:\Users\cmput\.conda\envs\qt\lib\ntpath.py:203 splitext 171485 0.333395 1.208162 0.000007
C:\Users\cmput\.conda\envs\qt\lib\reprlib.py:54 Repr.repr1 145378.. 0.307255 19.97495 0.000137
C:\Users\cmput\.conda\envs\qt\lib\logging\__init__.py:894 FileHandler.acquire 342970 0.305694 0.437972 0.000001
C:\Users\cmput\.conda\envs\qt\lib\logging\__init__.py:901 FileHandler.release 342970 0.298793 0.387364 0.000001
C:\Users\cmput\.conda\envs\qt\lib\logging\__init__.py:1579 Logger.handle 171485 0.277690 18.14146 0.000106
C:\Users\cmput\.conda\envs\qt\lib\logging\__init__.py:584 Formatter.formatTime 171485 0.268153 2.199540 0.000013
C:\Users\cmput\.conda\envs\qt\lib\logging\__init__.py:1538 Logger.makeRecord 171485 0.265055 6.278347 0.000037
C:\Users\cmput\.conda\envs\qt\lib\asyncio\format_helpers.py:10 _get_function_source 77295 0.258311 0.730289 0.000009
C:\Users\cmput\.conda\envs\qt\lib\site-packages\qasync\__init__.py:247 _SimpleTimer.add_callback 42838 0.235378 5.289468 0.000123
C:\Users\cmput\.conda\envs\qt\lib\asyncio\format_helpers.py:44 _format_callback 77295/.. 0.218848 9.054200 0.000117
C:\Users\cmput\.conda\envs\qt\lib\inspect.py:171 _has_code_flag 42838 0.191478 0.367154 0.000009
C:\Users\cmput\.conda\envs\qt\lib\logging\__init__.py:914 FileHandler.format 171485 0.189866 5.184168 0.000030
C:\Users\cmput\.conda\envs\qt\lib\asyncio\streams.py:416 StreamReader.__repr__ 34059 0.189435 5.676302 0.000167
C:\Users\cmput\.conda\envs\qt\lib\asyncio\windows_events.py:55 _OverlappedFuture._repr_info 85295 0.187839 16.61061 0.000195
C:\Users\cmput\.conda\envs\qt\lib\inspect.py:493 unwrap 77295 0.186258 0.356166 0.000005
C:\Users\cmput\.conda\envs\qt\lib\ntpath.py:214 basename 171485 0.182038 2.257628 0.000013
C:\Users\cmput\.conda\envs\qt\lib\asyncio\windows_events.py:440 _IocpProactor.recv 17074 0.167361 3.323878 0.000195
C:\Users\cmput\.conda\envs\qt\lib\asyncio\format_helpers.py:30 _format_args_and_kwargs 77295/.. 0.164086 8.677641 0.000112
C:\Users\cmput\.conda\envs\qt\lib\logging\__init__.py:1677 Logger.isEnabledFor 171485 0.163885 0.163901 0.000001
C:\Users\cmput\.conda\envs\qt\lib\logging\__init__.py:423 PercentStyle.usesTime 171485 0.159722 0.251497 0.000001
C:\Users\cmput\.conda\envs\qt\lib\logging\__init__.py:792 Logger.filter 342970 0.158075 0.158075 0.000000
C:\Users\cmput\.conda\envs\qt\lib\reprlib.py:51 Repr.repr 145344.. 0.156664 20.10566 0.000138
C:\Users\cmput\.conda\envs\qt\lib\logging\__init__.py:635 Formatter.formatMessage 171485 0.153240 1.676804 0.000010
C:\Users\cmput\.conda\envs\qt\lib\logging\__init__.py:119 getLevelName 171485 0.150181 0.201649 0.000001
C:\Users\cmput\.conda\envs\qt\lib\asyncio\windows_events.py:719 _IocpProactor._register 17064 0.148931 0.750285 0.000044
C:\Users\cmput\.conda\envs\qt\lib\logging\__init__.py:434 PercentStyle.format 171485 0.147920 1.523564 0.000009
C:\Users\cmput\.conda\envs\qt\lib\threading.py:1306 current_thread 171485 0.146324 0.181226 0.000001
C:\Users\cmput\.conda\envs\qt\lib\site-packages\qasync\__init__.py:444 QIOCPEventLoop._add_callback 42838 0.143038 5.432506 0.000127
...
Could anyone help with the performance difference? What's best practice to call subprocess with qasync? Will it be different if I run my program on Linux?
Thanks in advance!