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_start
and 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.call
s 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.