Message 210186 - Python tracker

➜

This issue tracker has been migrated to GitHub, and is currently read-only.
For more information, see the GitHub FAQs in the Python's Developer Guide.

Author	vstinner
Recipients	gvanrossum, neologix, vstinner
Date	2014-02-04.09:20:39
SpamBayes Score	-1.0
Marked as misclassified	Yes
Message-id	<1391505643.05.0.800326615345.issue20505@psf.upfronthosting.co.za>
In-reply-to

Content
Here is a script to measure the accuracy of asyncio: min/max difference between the scheduled time and the real elapsed time. It's not directly related to the attached patch, but it can help if you want to implement a different option like Results on my Fedora 20 (Linux kernel 3.12) with Python compiled in debug mode. Results with the original code: --- [ asyncio accuracy ] call_later(0.0001 us): difference in [59.4839 us; 101.6307 us], [+59483938.5%, +101630708.8%] call_later(0.0005 us): difference in [59.1285 us; 129.9486 us], [+11825694.4%, +25989713.7%] call_later(0.0010 us): difference in [58.9950 us; 102.4589 us], [+5899502.5%, +10245891.9%] call_later(0.0015 us): difference in [59.0737 us; 100.6987 us], [+3938245.9%, +6713245.6%] call_later(0.0020 us): difference in [58.6790 us; 112.8620 us], [+2933950.3%, +5643097.8%] call_later(0.0030 us): difference in [58.9260 us; 118.2042 us], [+1964199.0%, +3940139.5%] call_later(0.0040 us): difference in [59.3839 us; 117.6248 us], [+1484597.0%, +2940620.9%] call_later(0.0050 us): difference in [58.9361 us; 115.3991 us], [+1178721.5%, +2307982.8%] call_later(0.1 us): difference in [61.1 us; 133.5 us], [+61131.0%, +133512.9%] call_later(0.5 us): difference in [59.0 us; 124.8 us], [+11793.8%, +24953.6%] call_later(1.0 us): difference in [57.7 us; 113.7 us], [+5770.7%, +11372.1%] call_later(1.5 us): difference in [57.2 us; 113.5 us], [+3816.0%, +7563.7%] call_later(2.0 us): difference in [56.4 us; 130.1 us], [+2822.0%, +6506.8%] call_later(3.0 us): difference in [55.1 us; 99.7 us], [+1836.5%, +3324.5%] call_later(4.0 us): difference in [53.8 us; 98.5 us], [+1345.3%, +2462.4%] call_later(5.0 us): difference in [54.6 us; 97.0 us], [+1091.2%, +1939.9%] call_later(10.0 us): difference in [76.8 us; 114.3 us], [+767.6%, +1142.5%] call_later(50.0 us): difference in [44.5 us; 1154.6 us], [+88.9%, +2309.3%] call_later(0.1 ms): difference in [1.1 ms; 1.2 ms], [+1061.3%, +1153.8%] call_later(100.0 us): difference in [1066.1 us; 1134.3 us], [+1066.1%, +1134.3%] call_later(150.0 us): difference in [1005.0 us; 1104.6 us], [+670.0%, +736.4%] call_later(200.0 us): difference in [940.3 us; 1024.9 us], [+470.2%, +512.4%] call_later(300.0 us): difference in [854.2 us; 942.4 us], [+284.7%, +314.1%] call_later(400.0 us): difference in [756.3 us; 841.4 us], [+189.1%, +210.3%] call_later(0.5 ms): difference in [0.6 ms; 0.8 ms], [+129.2%, +151.6%] call_later(500.0 us): difference in [648.7 us; 734.8 us], [+129.7%, +147.0%] call_later(1.0 ms): difference in [0.1 ms; 0.3 ms], [+14.7%, +26.0%] call_later(1.5 ms): difference in [0.7 ms; 0.8 ms], [+43.5%, +51.3%] call_later(2.0 ms): difference in [0.2 ms; 0.2 ms], [+7.7%, +10.6%] call_later(3.0 ms): difference in [0.2 ms; 0.2 ms], [+6.2%, +8.1%] call_later(4.0 ms): difference in [0.2 ms; 0.2 ms], [+4.1%, +6.0%] call_later(5.0 ms): difference in [0.2 ms; 0.3 ms], [+3.0%, +5.6%] call_later(10.0 ms): difference in [0.1 ms; 0.3 ms], [+1.3%, +2.6%] call_later(10.0 ms): difference in [0.2 ms; 0.3 ms], [+2.0%, +2.8%] call_later(15.0 ms): difference in [0.2 ms; 0.3 ms], [+1.2%, +1.7%] call_later(20.0 ms): difference in [0.2 ms; 1.9 ms], [+1.1%, +9.3%] call_later(30.0 ms): difference in [0.2 ms; 0.3 ms], [+0.7%, +1.0%] call_later(40.0 ms): difference in [0.2 ms; 0.3 ms], [+0.5%, +0.8%] call_later(50.0 ms): difference in [0.2 ms; 0.3 ms], [+0.4%, +0.5%] call_later(100.0 ms): difference in [0.3 ms; 0.4 ms], [+0.3%, +0.4%] call_later(100.000 ms): difference in [0.254 ms; 0.384 ms], [+0.3%, +0.4%] call_later(150.0 ms): difference in [0.3 ms; 0.4 ms], [+0.2%, +0.3%] call_later(200.0 ms): difference in [0.2 ms; 0.4 ms], [+0.1%, +0.2%] call_later(300.0 ms): difference in [0.5 ms; 0.5 ms], [+0.2%, +0.2%] call_later(400.0 ms): difference in [0.5 ms; 0.7 ms], [+0.1%, +0.2%] call_later(500.0 ms): difference in [0.7 ms; 0.8 ms], [+0.1%, +0.2%] call_later(500.000 ms): difference in [0.297 ms; 0.786 ms], [+0.1%, +0.2%] call_later(1000.000 ms): difference in [0.439 ms; 1.285 ms], [+0.0%, +0.1%] call_later(1500.000 ms): difference in [0.916 ms; 1.759 ms], [+0.1%, +0.1%] call_later(2000.000 ms): difference in [0.678 ms; 2.297 ms], [+0.0%, +0.1%] call_later(3000.000 ms): difference in [0.444 ms; 3.275 ms], [+0.0%, +0.1%] call_later(4000.000 ms): difference in [0.516 ms; 4.255 ms], [+0.0%, +0.1%] call_later(5000.000 ms): difference in [1.051 ms; 5.242 ms], [+0.0%, +0.1%] Global accuracy in [44.5 us; 5.2 ms] Loop granularity: 1.0 ms Selector resolution: 1.0 ms Event loop: _UnixSelectorEventLoop Selector: EpollSelector --- IMO a maximum difference of 5.2 ms with a granularity of 1 ms is very good. For a call scheduled in 1 ms, the difference is in range [0.1 ms; 0.3 ms] which is also very good. Results with remove_granularity.patch: --- [ asyncio accuracy ] call_later(0.0001 us): difference in [65.1941 us; 95.9378 us], [+65194110.0%, +95937766.7%] call_later(0.0005 us): difference in [64.9974 us; 109.2616 us], [+12999486.8%, +21852313.2%] call_later(0.0010 us): difference in [61.7960 us; 106.4841 us], [+6179597.8%, +10648409.5%] call_later(0.0015 us): difference in [61.6555 us; 106.4587 us], [+4110369.8%, +7097245.5%] call_later(0.0020 us): difference in [61.0229 us; 105.4591 us], [+3051145.6%, +5272955.3%] call_later(0.0030 us): difference in [61.7439 us; 115.1779 us], [+2058130.7%, +3839261.8%] call_later(0.0040 us): difference in [60.6982 us; 106.1491 us], [+1517455.2%, +2653727.0%] call_later(0.0050 us): difference in [61.3559 us; 105.6279 us], [+1227117.7%, +2112558.7%] call_later(0.1 us): difference in [68.4 us; 114.5 us], [+68436.0%, +114519.0%] call_later(0.5 us): difference in [63.2 us; 99.4 us], [+12644.4%, +19883.2%] call_later(1.0 us): difference in [61.6 us; 99.5 us], [+6164.7%, +9948.8%] call_later(1.5 us): difference in [60.8 us; 96.3 us], [+4055.1%, +6417.1%] call_later(2.0 us): difference in [59.9 us; 100.7 us], [+2995.2%, +5034.9%] call_later(3.0 us): difference in [58.6 us; 94.5 us], [+1952.4%, +3150.7%] call_later(4.0 us): difference in [57.3 us; 106.6 us], [+1432.8%, +2664.1%] call_later(5.0 us): difference in [61.1 us; 97.1 us], [+1221.9%, +1942.7%] call_later(10.0 us): difference in [86.5 us; 143.5 us], [+865.3%, +1434.7%] call_later(50.0 us): difference in [33.3 us; 1164.4 us], [+66.6%, +2328.8%] call_later(0.1 ms): difference in [1.1 ms; 1.2 ms], [+1055.1%, +1178.2%] call_later(100.0 us): difference in [1071.8 us; 1147.2 us], [+1071.8%, +1147.2%] call_later(150.0 us): difference in [997.9 us; 1097.1 us], [+665.3%, +731.4%] call_later(200.0 us): difference in [974.7 us; 1040.0 us], [+487.3%, +520.0%] call_later(300.0 us): difference in [868.3 us; 932.4 us], [+289.4%, +310.8%] call_later(400.0 us): difference in [770.8 us; 830.7 us], [+192.7%, +207.7%] call_later(0.5 ms): difference in [0.6 ms; 0.8 ms], [+129.2%, +151.6%] call_later(500.0 us): difference in [675.5 us; 723.7 us], [+135.1%, +144.7%] call_later(1.0 ms): difference in [0.1 ms; 0.3 ms], [+14.6%, +30.2%] call_later(1.5 ms): difference in [0.7 ms; 0.8 ms], [+43.8%, +52.0%] call_later(2.0 ms): difference in [0.1 ms; 0.2 ms], [+7.3%, +12.2%] call_later(3.0 ms): difference in [0.2 ms; 0.3 ms], [+5.8%, +9.0%] call_later(4.0 ms): difference in [0.2 ms; 0.2 ms], [+3.9%, +6.1%] call_later(5.0 ms): difference in [0.2 ms; 0.3 ms], [+3.7%, +5.6%] call_later(10.0 ms): difference in [0.2 ms; 0.3 ms], [+1.8%, +2.6%] call_later(10.0 ms): difference in [0.2 ms; 0.3 ms], [+2.1%, +2.8%] call_later(15.0 ms): difference in [0.2 ms; 0.3 ms], [+1.4%, +1.8%] call_later(20.0 ms): difference in [0.2 ms; 0.3 ms], [+1.1%, +1.5%] call_later(30.0 ms): difference in [0.2 ms; 0.3 ms], [+0.7%, +1.0%] call_later(40.0 ms): difference in [0.2 ms; 0.3 ms], [+0.6%, +0.7%] call_later(50.0 ms): difference in [0.2 ms; 0.3 ms], [+0.4%, +0.6%] call_later(100.0 ms): difference in [0.3 ms; 0.3 ms], [+0.3%, +0.3%] call_later(100.000 ms): difference in [0.269 ms; 0.325 ms], [+0.3%, +0.3%] call_later(150.0 ms): difference in [0.3 ms; 0.4 ms], [+0.2%, +0.3%] call_later(200.0 ms): difference in [0.4 ms; 0.5 ms], [+0.2%, +0.2%] call_later(300.0 ms): difference in [0.3 ms; 0.6 ms], [+0.1%, +0.2%] call_later(400.0 ms): difference in [0.5 ms; 0.7 ms], [+0.1%, +0.2%] call_later(500.0 ms): difference in [0.7 ms; 0.8 ms], [+0.1%, +0.2%] call_later(500.000 ms): difference in [0.698 ms; 0.748 ms], [+0.1%, +0.1%] call_later(1000.000 ms): difference in [1.026 ms; 1.286 ms], [+0.1%, +0.1%] call_later(1500.000 ms): difference in [0.645 ms; 1.744 ms], [+0.0%, +0.1%] call_later(2000.000 ms): difference in [1.007 ms; 2.304 ms], [+0.1%, +0.1%] call_later(3000.000 ms): difference in [1.165 ms; 3.256 ms], [+0.0%, +0.1%] call_later(4000.000 ms): difference in [0.742 ms; 4.235 ms], [+0.0%, +0.1%] call_later(5000.000 ms): difference in [1.064 ms; 5.267 ms], [+0.0%, +0.1%] Global accuracy in [33.3 us; 5.3 ms] Event loop: _UnixSelectorEventLoop Selector: EpollSelector --- No surprise, the accuracy is the same. Another approach: always adds granularity to the timeout in asyncio (and selector rounds toward zero, as in Python 3.3). It looks like the test_timeout_rounding() test still pass with this option. Results with add_granularity.patch: --- [ asyncio accuracy ] call_later(0.0001 us): difference in [1136.6910 us; 1234.2710 us], [+1136690976.7%, +1234270997.9%] call_later(0.0005 us): difference in [1134.2053 us; 1230.9015 us], [+226841068.5%, +246180307.7%] call_later(0.0010 us): difference in [1149.2229 us; 1219.4788 us], [+114922288.5%, +121947883.3%] call_later(0.0015 us): difference in [1162.8546 us; 1222.8143 us], [+77523641.3%, +81520955.4%] call_later(0.0020 us): difference in [1163.5149 us; 1217.9579 us], [+58175744.6%, +60897895.7%] call_later(0.0030 us): difference in [1179.6120 us; 1227.1221 us], [+39320401.2%, +40904068.7%] call_later(0.0040 us): difference in [1165.2680 us; 1209.9680 us], [+29131699.2%, +30249199.0%] call_later(0.0050 us): difference in [1170.0682 us; 1226.5110 us], [+23401363.4%, +24530219.5%] call_later(0.1 us): difference in [1162.8 us; 1248.8 us], [+1162765.9%, +1248821.0%] call_later(0.5 us): difference in [1154.8 us; 1247.5 us], [+230968.4%, +249492.4%] call_later(1.0 us): difference in [1146.2 us; 1231.9 us], [+114622.4%, +123185.5%] call_later(1.5 us): difference in [1125.9 us; 1220.8 us], [+75061.3%, +81385.5%] call_later(2.0 us): difference in [1121.4 us; 1211.2 us], [+56071.7%, +60558.3%] call_later(3.0 us): difference in [1138.9 us; 1228.9 us], [+37962.0%, +40962.5%] call_later(4.0 us): difference in [1146.9 us; 1227.2 us], [+28673.0%, +30680.0%] call_later(5.0 us): difference in [1149.5 us; 1247.1 us], [+22990.4%, +24942.4%] call_later(10.0 us): difference in [1174.3 us; 1231.1 us], [+11743.4%, +12311.1%] call_later(50.0 us): difference in [1112.6 us; 1187.8 us], [+2225.1%, +2375.6%] call_later(0.1 ms): difference in [1.1 ms; 1.2 ms], [+1059.0%, +1154.9%] call_later(100.0 us): difference in [1061.7 us; 1133.5 us], [+1061.7%, +1133.5%] call_later(150.0 us): difference in [1016.0 us; 1080.4 us], [+677.4%, +720.2%] call_later(200.0 us): difference in [938.1 us; 1194.4 us], [+469.0%, +597.2%] call_later(300.0 us): difference in [834.9 us; 930.1 us], [+278.3%, +310.0%] call_later(400.0 us): difference in [754.3 us; 852.6 us], [+188.6%, +213.1%] call_later(0.5 ms): difference in [0.6 ms; 0.7 ms], [+124.3%, +149.0%] call_later(500.0 us): difference in [646.8 us; 738.0 us], [+129.4%, +147.6%] call_later(1.0 ms): difference in [0.1 ms; 0.3 ms], [+11.8%, +26.1%] call_later(1.5 ms): difference in [0.6 ms; 0.8 ms], [+41.1%, +50.3%] call_later(2.0 ms): difference in [0.1 ms; 0.2 ms], [+6.2%, +10.8%] call_later(3.0 ms): difference in [0.1 ms; 0.2 ms], [+4.3%, +7.9%] call_later(4.0 ms): difference in [0.1 ms; 0.2 ms], [+3.4%, +5.7%] call_later(5.0 ms): difference in [0.2 ms; 0.4 ms], [+3.2%, +7.1%] call_later(10.0 ms): difference in [0.1 ms; 0.2 ms], [+1.4%, +2.4%] call_later(10.0 ms): difference in [0.2 ms; 0.3 ms], [+1.6%, +2.6%] call_later(15.0 ms): difference in [0.2 ms; 0.3 ms], [+1.3%, +1.7%] call_later(20.0 ms): difference in [0.2 ms; 0.3 ms], [+1.0%, +1.5%] call_later(30.0 ms): difference in [0.2 ms; 0.3 ms], [+0.8%, +0.9%] call_later(40.0 ms): difference in [0.2 ms; 0.3 ms], [+0.5%, +0.7%] call_later(50.0 ms): difference in [0.2 ms; 0.3 ms], [+0.4%, +0.5%] call_later(100.0 ms): difference in [0.2 ms; 0.3 ms], [+0.2%, +0.3%] call_later(100.000 ms): difference in [0.247 ms; 0.345 ms], [+0.2%, +0.3%] call_later(150.0 ms): difference in [0.3 ms; 0.4 ms], [+0.2%, +0.3%] call_later(200.0 ms): difference in [0.3 ms; 0.4 ms], [+0.2%, +0.2%] call_later(300.0 ms): difference in [0.2 ms; 0.5 ms], [+0.1%, +0.2%] call_later(400.0 ms): difference in [0.6 ms; 0.6 ms], [+0.1%, +0.2%] call_later(500.0 ms): difference in [0.4 ms; 0.7 ms], [+0.1%, +0.1%] call_later(500.000 ms): difference in [0.365 ms; 0.781 ms], [+0.1%, +0.2%] call_later(1000.000 ms): difference in [1.176 ms; 1.239 ms], [+0.1%, +0.1%] call_later(1500.000 ms): difference in [1.650 ms; 1.727 ms], [+0.1%, +0.1%] call_later(2000.000 ms): difference in [0.318 ms; 2.241 ms], [+0.0%, +0.1%] call_later(3000.000 ms): difference in [1.169 ms; 3.254 ms], [+0.0%, +0.1%] call_later(4000.000 ms): difference in [1.297 ms; 4.238 ms], [+0.0%, +0.1%] call_later(5000.000 ms): difference in [0.975 ms; 5.272 ms], [+0.0%, +0.1%] Global accuracy in [117.8 us; 5.3 ms] Loop granularity: 1.0 ms Selector resolution: 1.0 ms Event loop: _UnixSelectorEventLoop Selector: EpollSelector --- The accuracy is almost the same, except that the minimum accuracy (117.8 us) is bigger than the current implementation (44.5 us). But I don't know if my micro-benchmark is reliable. Note: I also tested to always add 2 * granularity to asyncio timeout, but the minimum difference increases to 1 ms (as expected) which is much worse.

Here is a script to measure the accuracy of asyncio: min/max difference between the scheduled time and the real elapsed time. It's not directly related to the attached patch, but it can help if you want to implement a different option like 

Results on my Fedora 20 (Linux kernel 3.12) with Python compiled in debug mode.

Results with the original code:
---
[ asyncio accuracy ]
call_later(0.0001 us): difference in [59.4839 us; 101.6307 us], [+59483938.5%, +101630708.8%]
call_later(0.0005 us): difference in [59.1285 us; 129.9486 us], [+11825694.4%, +25989713.7%]
call_later(0.0010 us): difference in [58.9950 us; 102.4589 us], [+5899502.5%, +10245891.9%]
call_later(0.0015 us): difference in [59.0737 us; 100.6987 us], [+3938245.9%, +6713245.6%]
call_later(0.0020 us): difference in [58.6790 us; 112.8620 us], [+2933950.3%, +5643097.8%]
call_later(0.0030 us): difference in [58.9260 us; 118.2042 us], [+1964199.0%, +3940139.5%]
call_later(0.0040 us): difference in [59.3839 us; 117.6248 us], [+1484597.0%, +2940620.9%]
call_later(0.0050 us): difference in [58.9361 us; 115.3991 us], [+1178721.5%, +2307982.8%]
call_later(0.1 us): difference in [61.1 us; 133.5 us], [+61131.0%, +133512.9%]
call_later(0.5 us): difference in [59.0 us; 124.8 us], [+11793.8%, +24953.6%]
call_later(1.0 us): difference in [57.7 us; 113.7 us], [+5770.7%, +11372.1%]
call_later(1.5 us): difference in [57.2 us; 113.5 us], [+3816.0%, +7563.7%]
call_later(2.0 us): difference in [56.4 us; 130.1 us], [+2822.0%, +6506.8%]
call_later(3.0 us): difference in [55.1 us; 99.7 us], [+1836.5%, +3324.5%]
call_later(4.0 us): difference in [53.8 us; 98.5 us], [+1345.3%, +2462.4%]
call_later(5.0 us): difference in [54.6 us; 97.0 us], [+1091.2%, +1939.9%]
call_later(10.0 us): difference in [76.8 us; 114.3 us], [+767.6%, +1142.5%]
call_later(50.0 us): difference in [44.5 us; 1154.6 us], [+88.9%, +2309.3%]
call_later(0.1 ms): difference in [1.1 ms; 1.2 ms], [+1061.3%, +1153.8%]
call_later(100.0 us): difference in [1066.1 us; 1134.3 us], [+1066.1%, +1134.3%]
call_later(150.0 us): difference in [1005.0 us; 1104.6 us], [+670.0%, +736.4%]
call_later(200.0 us): difference in [940.3 us; 1024.9 us], [+470.2%, +512.4%]
call_later(300.0 us): difference in [854.2 us; 942.4 us], [+284.7%, +314.1%]
call_later(400.0 us): difference in [756.3 us; 841.4 us], [+189.1%, +210.3%]
call_later(0.5 ms): difference in [0.6 ms; 0.8 ms], [+129.2%, +151.6%]
call_later(500.0 us): difference in [648.7 us; 734.8 us], [+129.7%, +147.0%]
call_later(1.0 ms): difference in [0.1 ms; 0.3 ms], [+14.7%, +26.0%]
call_later(1.5 ms): difference in [0.7 ms; 0.8 ms], [+43.5%, +51.3%]
call_later(2.0 ms): difference in [0.2 ms; 0.2 ms], [+7.7%, +10.6%]
call_later(3.0 ms): difference in [0.2 ms; 0.2 ms], [+6.2%, +8.1%]
call_later(4.0 ms): difference in [0.2 ms; 0.2 ms], [+4.1%, +6.0%]
call_later(5.0 ms): difference in [0.2 ms; 0.3 ms], [+3.0%, +5.6%]
call_later(10.0 ms): difference in [0.1 ms; 0.3 ms], [+1.3%, +2.6%]
call_later(10.0 ms): difference in [0.2 ms; 0.3 ms], [+2.0%, +2.8%]
call_later(15.0 ms): difference in [0.2 ms; 0.3 ms], [+1.2%, +1.7%]
call_later(20.0 ms): difference in [0.2 ms; 1.9 ms], [+1.1%, +9.3%]
call_later(30.0 ms): difference in [0.2 ms; 0.3 ms], [+0.7%, +1.0%]
call_later(40.0 ms): difference in [0.2 ms; 0.3 ms], [+0.5%, +0.8%]
call_later(50.0 ms): difference in [0.2 ms; 0.3 ms], [+0.4%, +0.5%]
call_later(100.0 ms): difference in [0.3 ms; 0.4 ms], [+0.3%, +0.4%]
call_later(100.000 ms): difference in [0.254 ms; 0.384 ms], [+0.3%, +0.4%]
call_later(150.0 ms): difference in [0.3 ms; 0.4 ms], [+0.2%, +0.3%]
call_later(200.0 ms): difference in [0.2 ms; 0.4 ms], [+0.1%, +0.2%]
call_later(300.0 ms): difference in [0.5 ms; 0.5 ms], [+0.2%, +0.2%]
call_later(400.0 ms): difference in [0.5 ms; 0.7 ms], [+0.1%, +0.2%]
call_later(500.0 ms): difference in [0.7 ms; 0.8 ms], [+0.1%, +0.2%]
call_later(500.000 ms): difference in [0.297 ms; 0.786 ms], [+0.1%, +0.2%]
call_later(1000.000 ms): difference in [0.439 ms; 1.285 ms], [+0.0%, +0.1%]
call_later(1500.000 ms): difference in [0.916 ms; 1.759 ms], [+0.1%, +0.1%]
call_later(2000.000 ms): difference in [0.678 ms; 2.297 ms], [+0.0%, +0.1%]
call_later(3000.000 ms): difference in [0.444 ms; 3.275 ms], [+0.0%, +0.1%]
call_later(4000.000 ms): difference in [0.516 ms; 4.255 ms], [+0.0%, +0.1%]
call_later(5000.000 ms): difference in [1.051 ms; 5.242 ms], [+0.0%, +0.1%]
Global accuracy in [44.5 us; 5.2 ms]

Loop granularity: 1.0 ms
Selector resolution: 1.0 ms
Event loop: _UnixSelectorEventLoop
Selector: EpollSelector
---

IMO a maximum difference of 5.2 ms with a granularity of 1 ms is very good. For a call scheduled in 1 ms, the difference is in range [0.1 ms; 0.3 ms] which is also very good.

Results with  remove_granularity.patch:
---
[ asyncio accuracy ]
call_later(0.0001 us): difference in [65.1941 us; 95.9378 us], [+65194110.0%, +95937766.7%]
call_later(0.0005 us): difference in [64.9974 us; 109.2616 us], [+12999486.8%, +21852313.2%]
call_later(0.0010 us): difference in [61.7960 us; 106.4841 us], [+6179597.8%, +10648409.5%]
call_later(0.0015 us): difference in [61.6555 us; 106.4587 us], [+4110369.8%, +7097245.5%]
call_later(0.0020 us): difference in [61.0229 us; 105.4591 us], [+3051145.6%, +5272955.3%]
call_later(0.0030 us): difference in [61.7439 us; 115.1779 us], [+2058130.7%, +3839261.8%]
call_later(0.0040 us): difference in [60.6982 us; 106.1491 us], [+1517455.2%, +2653727.0%]
call_later(0.0050 us): difference in [61.3559 us; 105.6279 us], [+1227117.7%, +2112558.7%]
call_later(0.1 us): difference in [68.4 us; 114.5 us], [+68436.0%, +114519.0%]
call_later(0.5 us): difference in [63.2 us; 99.4 us], [+12644.4%, +19883.2%]
call_later(1.0 us): difference in [61.6 us; 99.5 us], [+6164.7%, +9948.8%]
call_later(1.5 us): difference in [60.8 us; 96.3 us], [+4055.1%, +6417.1%]
call_later(2.0 us): difference in [59.9 us; 100.7 us], [+2995.2%, +5034.9%]
call_later(3.0 us): difference in [58.6 us; 94.5 us], [+1952.4%, +3150.7%]
call_later(4.0 us): difference in [57.3 us; 106.6 us], [+1432.8%, +2664.1%]
call_later(5.0 us): difference in [61.1 us; 97.1 us], [+1221.9%, +1942.7%]
call_later(10.0 us): difference in [86.5 us; 143.5 us], [+865.3%, +1434.7%]
call_later(50.0 us): difference in [33.3 us; 1164.4 us], [+66.6%, +2328.8%]
call_later(0.1 ms): difference in [1.1 ms; 1.2 ms], [+1055.1%, +1178.2%]
call_later(100.0 us): difference in [1071.8 us; 1147.2 us], [+1071.8%, +1147.2%]
call_later(150.0 us): difference in [997.9 us; 1097.1 us], [+665.3%, +731.4%]
call_later(200.0 us): difference in [974.7 us; 1040.0 us], [+487.3%, +520.0%]
call_later(300.0 us): difference in [868.3 us; 932.4 us], [+289.4%, +310.8%]
call_later(400.0 us): difference in [770.8 us; 830.7 us], [+192.7%, +207.7%]
call_later(0.5 ms): difference in [0.6 ms; 0.8 ms], [+129.2%, +151.6%]
call_later(500.0 us): difference in [675.5 us; 723.7 us], [+135.1%, +144.7%]
call_later(1.0 ms): difference in [0.1 ms; 0.3 ms], [+14.6%, +30.2%]
call_later(1.5 ms): difference in [0.7 ms; 0.8 ms], [+43.8%, +52.0%]
call_later(2.0 ms): difference in [0.1 ms; 0.2 ms], [+7.3%, +12.2%]
call_later(3.0 ms): difference in [0.2 ms; 0.3 ms], [+5.8%, +9.0%]
call_later(4.0 ms): difference in [0.2 ms; 0.2 ms], [+3.9%, +6.1%]
call_later(5.0 ms): difference in [0.2 ms; 0.3 ms], [+3.7%, +5.6%]
call_later(10.0 ms): difference in [0.2 ms; 0.3 ms], [+1.8%, +2.6%]
call_later(10.0 ms): difference in [0.2 ms; 0.3 ms], [+2.1%, +2.8%]
call_later(15.0 ms): difference in [0.2 ms; 0.3 ms], [+1.4%, +1.8%]
call_later(20.0 ms): difference in [0.2 ms; 0.3 ms], [+1.1%, +1.5%]
call_later(30.0 ms): difference in [0.2 ms; 0.3 ms], [+0.7%, +1.0%]
call_later(40.0 ms): difference in [0.2 ms; 0.3 ms], [+0.6%, +0.7%]
call_later(50.0 ms): difference in [0.2 ms; 0.3 ms], [+0.4%, +0.6%]
call_later(100.0 ms): difference in [0.3 ms; 0.3 ms], [+0.3%, +0.3%]
call_later(100.000 ms): difference in [0.269 ms; 0.325 ms], [+0.3%, +0.3%]
call_later(150.0 ms): difference in [0.3 ms; 0.4 ms], [+0.2%, +0.3%]
call_later(200.0 ms): difference in [0.4 ms; 0.5 ms], [+0.2%, +0.2%]
call_later(300.0 ms): difference in [0.3 ms; 0.6 ms], [+0.1%, +0.2%]
call_later(400.0 ms): difference in [0.5 ms; 0.7 ms], [+0.1%, +0.2%]
call_later(500.0 ms): difference in [0.7 ms; 0.8 ms], [+0.1%, +0.2%]
call_later(500.000 ms): difference in [0.698 ms; 0.748 ms], [+0.1%, +0.1%]
call_later(1000.000 ms): difference in [1.026 ms; 1.286 ms], [+0.1%, +0.1%]
call_later(1500.000 ms): difference in [0.645 ms; 1.744 ms], [+0.0%, +0.1%]
call_later(2000.000 ms): difference in [1.007 ms; 2.304 ms], [+0.1%, +0.1%]
call_later(3000.000 ms): difference in [1.165 ms; 3.256 ms], [+0.0%, +0.1%]
call_later(4000.000 ms): difference in [0.742 ms; 4.235 ms], [+0.0%, +0.1%]
call_later(5000.000 ms): difference in [1.064 ms; 5.267 ms], [+0.0%, +0.1%]
Global accuracy in [33.3 us; 5.3 ms]

Event loop: _UnixSelectorEventLoop
Selector: EpollSelector
---

No surprise, the accuracy is the same.

Another approach: always adds granularity to the timeout in asyncio (and selector rounds toward zero, as in Python 3.3). It looks like the test_timeout_rounding() test still pass with this option. Results with add_granularity.patch:
---
[ asyncio accuracy ]
call_later(0.0001 us): difference in [1136.6910 us; 1234.2710 us], [+1136690976.7%, +1234270997.9%]
call_later(0.0005 us): difference in [1134.2053 us; 1230.9015 us], [+226841068.5%, +246180307.7%]
call_later(0.0010 us): difference in [1149.2229 us; 1219.4788 us], [+114922288.5%, +121947883.3%]
call_later(0.0015 us): difference in [1162.8546 us; 1222.8143 us], [+77523641.3%, +81520955.4%]
call_later(0.0020 us): difference in [1163.5149 us; 1217.9579 us], [+58175744.6%, +60897895.7%]
call_later(0.0030 us): difference in [1179.6120 us; 1227.1221 us], [+39320401.2%, +40904068.7%]
call_later(0.0040 us): difference in [1165.2680 us; 1209.9680 us], [+29131699.2%, +30249199.0%]
call_later(0.0050 us): difference in [1170.0682 us; 1226.5110 us], [+23401363.4%, +24530219.5%]
call_later(0.1 us): difference in [1162.8 us; 1248.8 us], [+1162765.9%, +1248821.0%]
call_later(0.5 us): difference in [1154.8 us; 1247.5 us], [+230968.4%, +249492.4%]
call_later(1.0 us): difference in [1146.2 us; 1231.9 us], [+114622.4%, +123185.5%]
call_later(1.5 us): difference in [1125.9 us; 1220.8 us], [+75061.3%, +81385.5%]
call_later(2.0 us): difference in [1121.4 us; 1211.2 us], [+56071.7%, +60558.3%]
call_later(3.0 us): difference in [1138.9 us; 1228.9 us], [+37962.0%, +40962.5%]
call_later(4.0 us): difference in [1146.9 us; 1227.2 us], [+28673.0%, +30680.0%]
call_later(5.0 us): difference in [1149.5 us; 1247.1 us], [+22990.4%, +24942.4%]
call_later(10.0 us): difference in [1174.3 us; 1231.1 us], [+11743.4%, +12311.1%]
call_later(50.0 us): difference in [1112.6 us; 1187.8 us], [+2225.1%, +2375.6%]
call_later(0.1 ms): difference in [1.1 ms; 1.2 ms], [+1059.0%, +1154.9%]
call_later(100.0 us): difference in [1061.7 us; 1133.5 us], [+1061.7%, +1133.5%]
call_later(150.0 us): difference in [1016.0 us; 1080.4 us], [+677.4%, +720.2%]
call_later(200.0 us): difference in [938.1 us; 1194.4 us], [+469.0%, +597.2%]
call_later(300.0 us): difference in [834.9 us; 930.1 us], [+278.3%, +310.0%]
call_later(400.0 us): difference in [754.3 us; 852.6 us], [+188.6%, +213.1%]
call_later(0.5 ms): difference in [0.6 ms; 0.7 ms], [+124.3%, +149.0%]
call_later(500.0 us): difference in [646.8 us; 738.0 us], [+129.4%, +147.6%]
call_later(1.0 ms): difference in [0.1 ms; 0.3 ms], [+11.8%, +26.1%]
call_later(1.5 ms): difference in [0.6 ms; 0.8 ms], [+41.1%, +50.3%]
call_later(2.0 ms): difference in [0.1 ms; 0.2 ms], [+6.2%, +10.8%]
call_later(3.0 ms): difference in [0.1 ms; 0.2 ms], [+4.3%, +7.9%]
call_later(4.0 ms): difference in [0.1 ms; 0.2 ms], [+3.4%, +5.7%]
call_later(5.0 ms): difference in [0.2 ms; 0.4 ms], [+3.2%, +7.1%]
call_later(10.0 ms): difference in [0.1 ms; 0.2 ms], [+1.4%, +2.4%]
call_later(10.0 ms): difference in [0.2 ms; 0.3 ms], [+1.6%, +2.6%]
call_later(15.0 ms): difference in [0.2 ms; 0.3 ms], [+1.3%, +1.7%]
call_later(20.0 ms): difference in [0.2 ms; 0.3 ms], [+1.0%, +1.5%]
call_later(30.0 ms): difference in [0.2 ms; 0.3 ms], [+0.8%, +0.9%]
call_later(40.0 ms): difference in [0.2 ms; 0.3 ms], [+0.5%, +0.7%]
call_later(50.0 ms): difference in [0.2 ms; 0.3 ms], [+0.4%, +0.5%]
call_later(100.0 ms): difference in [0.2 ms; 0.3 ms], [+0.2%, +0.3%]
call_later(100.000 ms): difference in [0.247 ms; 0.345 ms], [+0.2%, +0.3%]
call_later(150.0 ms): difference in [0.3 ms; 0.4 ms], [+0.2%, +0.3%]
call_later(200.0 ms): difference in [0.3 ms; 0.4 ms], [+0.2%, +0.2%]
call_later(300.0 ms): difference in [0.2 ms; 0.5 ms], [+0.1%, +0.2%]
call_later(400.0 ms): difference in [0.6 ms; 0.6 ms], [+0.1%, +0.2%]
call_later(500.0 ms): difference in [0.4 ms; 0.7 ms], [+0.1%, +0.1%]
call_later(500.000 ms): difference in [0.365 ms; 0.781 ms], [+0.1%, +0.2%]
call_later(1000.000 ms): difference in [1.176 ms; 1.239 ms], [+0.1%, +0.1%]
call_later(1500.000 ms): difference in [1.650 ms; 1.727 ms], [+0.1%, +0.1%]
call_later(2000.000 ms): difference in [0.318 ms; 2.241 ms], [+0.0%, +0.1%]
call_later(3000.000 ms): difference in [1.169 ms; 3.254 ms], [+0.0%, +0.1%]
call_later(4000.000 ms): difference in [1.297 ms; 4.238 ms], [+0.0%, +0.1%]
call_later(5000.000 ms): difference in [0.975 ms; 5.272 ms], [+0.0%, +0.1%]
Global accuracy in [117.8 us; 5.3 ms]

Loop granularity: 1.0 ms
Selector resolution: 1.0 ms
Event loop: _UnixSelectorEventLoop
Selector: EpollSelector
---

The accuracy is almost the same, except that the minimum accuracy (117.8 us) is bigger than the current implementation (44.5 us). But I don't know if my micro-benchmark is reliable.

Note: I also tested to always add 2 * granularity to asyncio timeout, but the minimum difference increases to 1 ms (as expected) which is much worse.

History
Date	User	Action	Args
2014-02-04 09:20:43	vstinner	set	recipients: + vstinner, gvanrossum, neologix
2014-02-04 09:20:43	vstinner	set	messageid: <1391505643.05.0.800326615345.issue20505@psf.upfronthosting.co.za>
2014-02-04 09:20:43	vstinner	link	issue20505 messages
2014-02-04 09:20:40	vstinner	create