ExecuteMethodDialog: Max and Avg execution times grow the more iterations you do
- Bring up the Execute D-Bus Method dialog for any method (e.g. Introspect on any object).
- Set "Method execution" to 100.
- Click Execute.
Expected result: The minimum, average, and maximum times are reasonably close.
Actual result: The maximum time is always much larger than the minimum time. Average time is somewhere in between but still suspiciously high.
The relevant code is in executemethoddialog.py:73 to :99.
If I print debugging messages when setting
method_call_time_end, it looks like this:
START 1532246758.6421 START 1532246758.6423 ... 96 STARTs START 1532246758.6506 START 1532246758.6506 END 1532246758.6527 - 1532246758.6506 = 0.0020 # Format: end - start = elapsed END 1532246758.6537 - 1532246758.6506 = 0.0030 ... 96 ENDs END 1532246758.7028 - 1532246758.6506 = 0.0522 END 1532246758.7033 - 1532246758.6506 = 0.0527
The issue here is that all the
proxy.calls are queued, so
user_data['method_call_time_start'] keeps getting overwritten; only the last one is ever used (notice that the second number on the END lines are all identical).
I tried fixing this by not reusing
user_data all the time. However, this doesn't work as expected:
START 1532247190.6325 START 1532247190.6326 ... START 1532247190.6420 START 1532247190.6421 END 1532247190.6460 - 1532247190.6325 = 0.0134 END 1532247190.6478 - 1532247190.6326 = 0.0152 ... END 1532247190.6957 - 1532247190.6420 = 0.0537 END 1532247190.6962 - 1532247190.6421 = 0.0542
The start times now correctly match sequentially, but the minimum elapsed time is much larger than normal (compared to if I set method execution to 1), and the maximum time still grows!
At this point I gave up. I think you need to somehow make sure that each method call ends before the next one starts.