Performance drop with subprocesses

[cmpute]

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!

[baha2046a]

I cannot help to explain the performance difference, but if you want to use the build in event loop,
you can create a QThread and then free to start a event loop on the new thread and process your work, and update the UI via signal with Qt.QueuedConnection