Open
Description
Originally posted by @texascloud in #79 (comment)
Hello! I have come to you after much debugging. I don't know why, but the logic gated by this code causes
.run_pending_tasks()to occasionally take significantly longer, especially if the number of entries which are being evicted is in the range of millions, but it presents at values significantly lower than that too.if tbc >= 25_000.0 || tbc / real_cap >= 0.1If I change the
0.1to0.5, I get results like this:0215 00:20:22.976972 INFO [serial] inserting 5000000 items 0215 00:20:32.243169 INFO done after 9266ms - size: 4999936 0215 00:20:32.243266 INFO [before sync] size: 5000000 0215 00:20:39.282989 INFO [polling till empty] num_during_iter: 5000000 - removed: cycle/60001 total/60001 - elapsed_ms: 38 - items/ms: 1578 0215 00:20:43.281050 INFO [polling till empty] num_during_iter: 4939999 - removed: cycle/60002 total/120003 - elapsed_ms: 36 - items/ms: 1666 0215 00:20:44.280029 INFO [polling till empty] num_during_iter: 4879997 - removed: cycle/60002 total/180005 - elapsed_ms: 35 - items/ms: 1714 0215 00:20:47.279363 INFO [polling till empty] num_during_iter: 4819995 - removed: cycle/60002 total/240007 - elapsed_ms: 34 - items/ms: 1764 0215 00:20:50.280655 INFO [polling till empty] num_during_iter: 4759993 - removed: cycle/60002 total/300009 - elapsed_ms: 36 - items/ms: 1666 0215 00:20:52.283514 INFO [polling till empty] num_during_iter: 4699991 - removed: cycle/60002 total/360011 - elapsed_ms: 39 - items/ms: 1538 0215 00:20:55.279434 INFO [polling till empty] num_during_iter: 4639989 - removed: cycle/60002 total/420013 - elapsed_ms: 35 - items/ms: 1714 0215 00:20:57.284198 INFO [polling till empty] num_during_iter: 4579987 - removed: cycle/60002 total/480015 - elapsed_ms: 38 - items/ms: 1579 0215 00:21:00.284056 INFO [polling till empty] num_during_iter: 4519985 - removed: cycle/60002 total/540017 - elapsed_ms: 39 - items/ms: 1538 0215 00:21:03.286988 INFO [polling till empty] num_during_iter: 4459983 - removed: cycle/60002 total/600019 - elapsed_ms: 42 - items/ms: 1428 0215 00:21:05.283812 INFO [polling till empty] num_during_iter: 4399981 - removed: cycle/60002 total/660021 - elapsed_ms: 38 - items/ms: 1579 0215 00:21:08.282565 INFO [polling till empty] num_during_iter: 4339979 - removed: cycle/60002 total/720023 - elapsed_ms: 38 - items/ms: 1579 0215 00:21:10.257832 INFO [polling till empty] num_during_iter: 4279977 - removed: cycle/18143 total/738166 - elapsed_ms: 13 - items/ms: 1395 0215 00:21:12.271668 INFO [polling till empty] num_during_iter: 4261834 - removed: cycle/41859 total/780025 - elapsed_ms: 27 - items/ms: 1550 0215 00:21:13.284663 INFO [polling till empty] num_during_iter: 4219975 - removed: cycle/60002 total/840027 - elapsed_ms: 39 - items/ms: 1538 0215 00:21:16.284791 INFO [polling till empty] num_during_iter: 4159973 - removed: cycle/60002 total/900029 - elapsed_ms: 40 - items/ms: 1500 0215 00:21:18.282902 INFO [polling till empty] num_during_iter: 4099971 - removed: cycle/60002 total/960031 - elapsed_ms: 38 - items/ms: 1579 0215 00:21:21.285095 INFO [polling till empty] num_during_iter: 4039969 - removed: cycle/60002 total/1020033 - elapsed_ms: 39 - items/ms: 1538 0215 00:21:23.270587 INFO [polling till empty] num_during_iter: 3979967 - removed: cycle/37073 total/1057106 - elapsed_ms: 26 - items/ms: 1425 0215 00:21:24.259405 INFO [polling till empty] num_during_iter: 3942894 - removed: cycle/22929 total/1080035 - elapsed_ms: 15 - items/ms: 1528 0215 00:21:26.285166 INFO [polling till empty] num_during_iter: 3919965 - removed: cycle/60002 total/1140037 - elapsed_ms: 40 - items/ms: 1500 0215 00:21:29.284835 INFO [polling till empty] num_during_iter: 3859963 - removed: cycle/60002 total/1200039 - elapsed_ms: 39 - items/ms: 1538 0215 00:21:31.284801 INFO [polling till empty] num_during_iter: 3799961 - removed: cycle/60002 total/1260041 - elapsed_ms: 40 - items/ms: 1500 0215 00:21:34.284702 INFO [polling till empty] num_during_iter: 3739959 - removed: cycle/60002 total/1320043 - elapsed_ms: 40 - items/ms: 1500 0215 00:21:36.284188 INFO [polling till empty] num_during_iter: 3679957 - removed: cycle/60002 total/1380045 - elapsed_ms: 40 - items/ms: 1500 0215 00:21:39.285984 INFO [polling till empty] num_during_iter: 3619955 - removed: cycle/60002 total/1440047 - elapsed_ms: 41 - items/ms: 1463 0215 00:21:42.284987 INFO [polling till empty] num_during_iter: 3559953 - removed: cycle/60002 total/1500049 - elapsed_ms: 40 - items/ms: 1500 0215 00:21:45.286834 INFO [polling till empty] num_during_iter: 3499951 - removed: cycle/60002 total/1560051 - elapsed_ms: 41 - items/ms: 1463 inner loop longer now 55ms inner loop longer now 53ms inner loop longer now 53ms inner loop longer now 53ms inner loop longer now 58ms inner loop longer now 57ms inner loop longer now 60ms inner loop longer now 65ms inner loop longer now 59ms inner loop longer now 61ms inner loop longer now 61ms inner loop longer now 57ms inner loop longer now 60ms inner loop longer now 58ms inner loop longer now 53ms inner loop longer now 52ms inner loop longer now 51ms inner loop longer now 50ms inner loop longer now 55ms inner loop longer now 59ms inner loop longer now 59ms inner loop longer now 62ms inner loop longer now 61ms inner loop longer now 60ms inner loop longer now 57ms inner loop longer now 55ms inner loop longer now 58ms inner loop longer now 59ms inner loop longer now 55ms inner loop longer now 53ms inner loop longer now 47ms inner loop longer now 45ms inner loop longer now 47ms inner loop longer now 57ms inner loop longer now 63ms inner loop longer now 58ms inner loop longer now 52ms inner loop longer now 54ms inner loop longer now 61ms inner loop longer now 58ms inner loop longer now 56ms inner loop longer now 57ms inner loop longer now 63ms inner loop longer now 60ms inner loop longer now 64ms inner loop longer now 64ms inner loop longer now 62ms inner loop longer now 55ms inner loop longer now 59ms inner loop longer now 60ms inner loop longer now 57ms inner loop longer now 57ms inner loop longer now 58ms inner loop longer now 49ms inner loop longer now 55ms inner loop longer now 51ms inner loop longer now 49ms inner loop longer now 52ms inner loop longer now 47ms inner loop longer now 60ms inner loop longer now 57ms inner loop longer now 60ms other work in expiring entries took 3648 0215 00:21:50.899043 INFO [polling till empty] num_during_iter: 3439949 - removed: cycle/60002 total/1620053 - elapsed_ms: 3654 - items/ms: 16 inner loop longer now 58ms inner loop longer now 60ms 0215 00:21:51.149464 INFO [polling till empty] num_during_iter: 3379947 - removed: cycle/60002 total/1680055 - elapsed_ms: 250 - items/ms: 240 0215 00:21:52.343265 INFO [polling till empty] num_during_iter: 3319945 - removed: cycle/46274 total/1726329 - elapsed_ms: 98 - items/ms: 472 0215 00:21:53.277026 INFO [polling till empty] num_during_iter: 3273671 - removed: cycle/13728 total/1740057 - elapsed_ms: 32 - items/ms: 429 0215 00:21:55.373140 INFO [polling till empty] num_during_iter: 3259943 - removed: cycle/60002 total/1800059 - elapsed_ms: 128 - items/ms: 468 0215 00:21:58.378099 INFO [polling till empty] num_during_iter: 3199941 - removed: cycle/60002 total/1860061 - elapsed_ms: 133 - items/ms: 451 0215 00:22:00.374099 INFO [polling till empty] num_during_iter: 3139939 - removed: cycle/60002 total/1920063 - elapsed_ms: 129 - items/ms: 465 0215 00:22:03.373482 INFO [polling till empty] num_during_iter: 3079937 - removed: cycle/60002 total/1980065 - elapsed_ms: 129 - items/ms: 465 0215 00:22:05.311049 INFO [polling till empty] num_during_iter: 3019935 - removed: cycle/60002 total/2040067 - elapsed_ms: 66 - items/ms: 909 0215 00:22:08.307935 INFO [polling till empty] num_during_iter: 2959933 - removed: cycle/60002 total/2100069 - elapsed_ms: 63 - items/ms: 952 0215 00:22:11.283043 INFO [polling till empty] num_during_iter: 2899931 - removed: cycle/60002 total/2160071 - elapsed_ms: 38 - items/ms: 1579 0215 00:22:13.283127 INFO [polling till empty] num_during_iter: 2839929 - removed: cycle/60002 total/2220073 - elapsed_ms: 38 - items/ms: 1579 0215 00:22:16.283067 INFO [polling till empty] num_during_iter: 2779927 - removed: cycle/60002 total/2280075 - elapsed_ms: 38 - items/ms: 1579 0215 00:22:18.282396 INFO [polling till empty] num_during_iter: 2719925 - removed: cycle/60002 total/2340077 - elapsed_ms: 37 - items/ms: 1621 0215 00:22:21.282380 INFO [polling till empty] num_during_iter: 2659923 - removed: cycle/60002 total/2400079 - elapsed_ms: 38 - items/ms: 1579 0215 00:22:23.270550 INFO [polling till empty] num_during_iter: 2599921 - removed: cycle/39493 total/2439572 - elapsed_ms: 26 - items/ms: 1518 0215 00:22:25.257015 INFO [polling till empty] num_during_iter: 2560428 - removed: cycle/20509 total/2460081 - elapsed_ms: 12 - items/ms: 1709 0215 00:22:26.281062 INFO [polling till empty] num_during_iter: 2539919 - removed: cycle/60002 total/2520083 - elapsed_ms: 36 - items/ms: 1666 0215 00:22:29.286712 INFO [polling till empty] num_during_iter: 2479917 - removed: cycle/60002 total/2580085 - elapsed_ms: 42 - items/ms: 1428 0215 00:22:31.284630 INFO [polling till empty] num_during_iter: 2419915 - removed: cycle/60002 total/2640087 - elapsed_ms: 39 - items/ms: 1538 0215 00:22:34.284504 INFO [polling till empty] num_during_iter: 2359913 - removed: cycle/60002 total/2700089 - elapsed_ms: 40 - items/ms: 1500 0215 00:22:36.284147 INFO [polling till empty] num_during_iter: 2299911 - removed: cycle/60002 total/2760091 - elapsed_ms: 39 - items/ms: 1538 0215 00:22:39.285287 INFO [polling till empty] num_during_iter: 2239909 - removed: cycle/60002 total/2820093 - elapsed_ms: 40 - items/ms: 1500 0215 00:22:42.284914 INFO [polling till empty] num_during_iter: 2179907 - removed: cycle/60002 total/2880095 - elapsed_ms: 40 - items/ms: 1500 0215 00:22:44.275285 INFO [polling till empty] num_during_iter: 2119905 - removed: cycle/44856 total/2924951 - elapsed_ms: 31 - items/ms: 1446 0215 00:22:45.255715 INFO [polling till empty] num_during_iter: 2075049 - removed: cycle/15146 total/2940097 - elapsed_ms: 11 - items/ms: 1376 0215 00:22:48.293616 INFO [polling till empty] num_during_iter: 2059903 - removed: cycle/60002 total/3000099 - elapsed_ms: 49 - items/ms: 1224 0215 00:22:51.292952 INFO [polling till empty] num_during_iter: 1999901 - removed: cycle/60002 total/3060101 - elapsed_ms: 48 - items/ms: 1250 0215 00:22:54.287375 INFO [polling till empty] num_during_iter: 1939899 - removed: cycle/60002 total/3120103 - elapsed_ms: 43 - items/ms: 1395 inner loop longer now 24ms inner loop longer now 23ms inner loop longer now 22ms inner loop longer now 24ms inner loop longer now 24ms 0215 00:22:56.424655 INFO [polling till empty] num_during_iter: 1879897 - removed: cycle/60002 total/3180105 - elapsed_ms: 179 - items/ms: 335 inner loop longer now 24ms inner loop longer now 25ms inner loop longer now 23ms inner loop longer now 23ms inner loop longer now 23ms inner loop longer now 22ms inner loop longer now 23ms inner loop longer now 23ms inner loop longer now 23ms inner loop longer now 23ms inner loop longer now 23ms inner loop longer now 22ms inner loop longer now 22ms inner loop longer now 23ms inner loop longer now 22ms inner loop longer now 24ms inner loop longer now 23ms inner loop longer now 22ms inner loop longer now 22ms inner loop longer now 22ms inner loop longer now 22ms inner loop longer now 23ms inner loop longer now 22ms inner loop longer now 21ms inner loop longer now 23ms inner loop longer now 23ms inner loop longer now 23ms inner loop longer now 24ms inner loop longer now 22ms inner loop longer now 23ms inner loop longer now 23ms inner loop longer now 24ms inner loop longer now 23ms inner loop longer now 23ms inner loop longer now 23ms inner loop longer now 23ms inner loop longer now 22ms inner loop longer now 23ms inner loop longer now 23ms inner loop longer now 23ms inner loop longer now 23ms inner loop longer now 22ms inner loop longer now 22ms inner loop longer now 23ms inner loop longer now 24ms inner loop longer now 23ms inner loop longer now 23ms inner loop longer now 23ms inner loop longer now 23ms inner loop longer now 22ms inner loop longer now 22ms inner loop longer now 23ms inner loop longer now 23ms inner loop longer now 22ms inner loop longer now 23ms inner loop longer now 23ms inner loop longer now 22ms other work in expiring entries took 1461 0215 00:22:59.711709 INFO [polling till empty] num_during_iter: 1819895 - removed: cycle/60002 total/3240107 - elapsed_ms: 1467 - items/ms: 40 inner loop longer now 25ms inner loop longer now 23ms 0215 00:23:01.420114 INFO [polling till empty] num_during_iter: 1759893 - removed: cycle/60002 total/3300109 - elapsed_ms: 175 - items/ms: 342 0215 00:23:03.280751 INFO [polling till empty] num_during_iter: 1699891 - removed: cycle/16633 total/3316742 - elapsed_ms: 36 - items/ms: 462 0215 00:23:04.334370 INFO [polling till empty] num_during_iter: 1683258 - removed: cycle/43369 total/3360111 - elapsed_ms: 89 - items/ms: 487 0215 00:23:06.374591 INFO [polling till empty] num_during_iter: 1639889 - removed: cycle/60002 total/3420113 - elapsed_ms: 130 - items/ms: 461 0215 00:23:09.370134 INFO [polling till empty] num_during_iter: 1579887 - removed: cycle/60002 total/3480115 - elapsed_ms: 125 - items/ms: 480 0215 00:23:11.369464 INFO [polling till empty] num_during_iter: 1519885 - removed: cycle/60002 total/3540117 - elapsed_ms: 125 - items/ms: 480 0215 00:23:14.351265 INFO [polling till empty] num_during_iter: 1459883 - removed: cycle/60002 total/3600119 - elapsed_ms: 106 - items/ms: 566 0215 00:23:16.311857 INFO [polling till empty] num_during_iter: 1399881 - removed: cycle/60002 total/3660121 - elapsed_ms: 67 - items/ms: 895 0215 00:23:19.302834 INFO [polling till empty] num_during_iter: 1339879 - removed: cycle/60002 total/3720123 - elapsed_ms: 58 - items/ms: 1034 0215 00:23:23.287930 INFO [polling till empty] num_during_iter: 1279877 - removed: cycle/60002 total/3780125 - elapsed_ms: 43 - items/ms: 1395 0215 00:23:24.286809 INFO [polling till empty] num_during_iter: 1219875 - removed: cycle/60002 total/3840127 - elapsed_ms: 42 - items/ms: 1428 0215 00:23:27.289109 INFO [polling till empty] num_during_iter: 1159873 - removed: cycle/60002 total/3900129 - elapsed_ms: 45 - items/ms: 1333 0215 00:23:29.289941 INFO [polling till empty] num_during_iter: 1099871 - removed: cycle/60002 total/3960131 - elapsed_ms: 44 - items/ms: 1363 0215 00:23:32.289917 INFO [polling till empty] num_during_iter: 1039869 - removed: cycle/60002 total/4020133 - elapsed_ms: 45 - items/ms: 1333 0215 00:23:35.287222 INFO [polling till empty] num_during_iter: 979867 - removed: cycle/60002 total/4080135 - elapsed_ms: 42 - items/ms: 1428 0215 00:23:37.285451 INFO [polling till empty] num_during_iter: 919865 - removed: cycle/60002 total/4140137 - elapsed_ms: 40 - items/ms: 1500 0215 00:23:40.289295 INFO [polling till empty] num_during_iter: 859863 - removed: cycle/60002 total/4200139 - elapsed_ms: 45 - items/ms: 1333 0215 00:23:42.288687 INFO [polling till empty] num_during_iter: 799861 - removed: cycle/60002 total/4260141 - elapsed_ms: 44 - items/ms: 1363 0215 00:23:45.288637 INFO [polling till empty] num_during_iter: 739859 - removed: cycle/60002 total/4320143 - elapsed_ms: 44 - items/ms: 1363 0215 00:23:47.272691 INFO [polling till empty] num_during_iter: 679857 - removed: cycle/38326 total/4358469 - elapsed_ms: 28 - items/ms: 1368 0215 00:23:48.261891 INFO [polling till empty] num_during_iter: 641531 - removed: cycle/21676 total/4380145 - elapsed_ms: 17 - items/ms: 1275 0215 00:23:50.288112 INFO [polling till empty] num_during_iter: 619855 - removed: cycle/60002 total/4440147 - elapsed_ms: 43 - items/ms: 1395 0215 00:23:53.290423 INFO [polling till empty] num_during_iter: 559853 - removed: cycle/60002 total/4500149 - elapsed_ms: 44 - items/ms: 1363 0215 00:23:55.289229 INFO [polling till empty] num_during_iter: 499851 - removed: cycle/60002 total/4560151 - elapsed_ms: 44 - items/ms: 1363 0215 00:23:58.289512 INFO [polling till empty] num_during_iter: 439849 - removed: cycle/60002 total/4620153 - elapsed_ms: 45 - items/ms: 1333 0215 00:24:00.308987 INFO [polling till empty] num_during_iter: 379847 - removed: cycle/60002 total/4680155 - elapsed_ms: 64 - items/ms: 937 0215 00:24:03.289557 INFO [polling till empty] num_during_iter: 319845 - removed: cycle/60002 total/4740157 - elapsed_ms: 44 - items/ms: 1363 inner loop longer now 12ms inner loop longer now 11ms inner loop longer now 12ms inner loop longer now 12ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 12ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 12ms inner loop longer now 12ms inner loop longer now 12ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 12ms inner loop longer now 11ms inner loop longer now 12ms inner loop longer now 12ms inner loop longer now 12ms other work in expiring entries took 525 0215 00:24:07.776642 INFO [polling till empty] num_during_iter: 259843 - removed: cycle/60002 total/4800159 - elapsed_ms: 532 - items/ms: 112 inner loop longer now 13ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 12ms inner loop longer now 12ms inner loop longer now 11ms inner loop longer now 12ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms 2BDE inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms inner loop longer now 11ms other work in expiring entries took 433 0215 00:24:08.683650 INFO [polling till empty] num_during_iter: 199841 - removed: cycle/60002 total/4860161 - elapsed_ms: 439 - items/ms: 136 0215 00:24:11.370386 INFO [polling till empty] num_during_iter: 139839 - removed: cycle/60002 total/4920163 - elapsed_ms: 125 - items/ms: 480 0215 00:24:13.372136 INFO [polling till empty] num_during_iter: 79837 - removed: cycle/60002 total/4980165 - elapsed_ms: 127 - items/ms: 472 0215 00:24:16.286089 INFO [polling till empty] num_during_iter: 19835 - removed: cycle/19835 total/5000000 - elapsed_ms: 41 - items/ms: 483 0215 00:24:17.245283 INFO total time syncing cache: 10957ms 0215 00:24:17.245334 INFO longest sync time seen: 3654msResults before changing it showed this:
0215 00:28:26.697036 INFO [serial] inserting 5000000 items 0215 00:28:35.977126 INFO done after 9280ms - size: 4999936 0215 00:28:35.977219 INFO [before sync] size: 5000000 0215 00:28:43.015708 INFO [polling till empty] num_during_iter: 5000000 - removed: cycle/60001 total/60001 - elapsed_ms: 36 - items/ms: 1666 0215 00:28:47.014463 INFO [polling till empty] num_during_iter: 4939999 - removed: cycle/60002 total/120003 - elapsed_ms: 35 - items/ms: 1714 0215 00:28:48.013772 INFO [polling till empty] num_during_iter: 4879997 - removed: cycle/60002 total/180005 - elapsed_ms: 35 - items/ms: 1714 0215 75B1 00:28:51.020654 INFO [polling till empty] num_during_iter: 4819995 - removed: cycle/60002 total/240007 - elapsed_ms: 42 - items/ms: 1428 0215 00:28:52.983376 INFO [polling till empty] num_during_iter: 4759993 - removed: cycle/3224 total/243231 - elapsed_ms: 4 - items/ms: 806 0215 00:28:54.016071 INFO [polling till empty] num_during_iter: 4756769 - removed: cycle/56778 total/300009 - elapsed_ms: 37 - items/ms: 1534 0215 00:28:56.019840 INFO [polling till empty] num_during_iter: 4699991 - removed: cycle/60002 total/360011 - elapsed_ms: 41 - items/ms: 1463 0215 00:28:59.022875 INFO [polling till empty] num_during_iter: 4639989 - removed: cycle/60002 total/420013 - elapsed_ms: 44 - items/ms: 1363 0215 00:29:01.020195 INFO [polling till empty] num_during_iter: 4579987 - removed: cycle/60002 total/480015 - elapsed_ms: 41 - items/ms: 1463 0215 00:29:04.019431 INFO [polling till empty] num_during_iter: 4519985 - removed: cycle/60002 total/540017 - elapsed_ms: 40 - items/ms: 1500 0215 00:29:07.020925 INFO [polling till empty] num_during_iter: 4459983 - removed: cycle/60002 total/600019 - elapsed_ms: 42 - items/ms: 1428 0215 00:29:09.021071 INFO [polling till empty] num_during_iter: 4399981 - removed: cycle/60002 total/660021 - elapsed_ms: 42 - items/ms: 1428 0215 00:29:12.021859 INFO [polling till empty] num_during_iter: 4339979 - removed: cycle/60002 total/720023 - elapsed_ms: 43 - items/ms: 1395 0215 00:29:13.992883 INFO [polling till empty] num_during_iter: 4279977 - removed: cycle/15786 total/735809 - elapsed_ms: 14 - items/ms: 1127 0215 00:29:16.010206 INFO [polling till empty] num_during_iter: 4264191 - removed: cycle/44216 total/780025 - elapsed_ms: 31 - items/ms: 1426 inner loop longer now 51ms inner loop longer now 48ms inner loop longer now 47ms inner loop longer now 49ms inner loop longer now 47ms inner loop longer now 45ms inner loop longer now 46ms inner loop longer now 45ms inner loop longer now 45ms inner loop longer now 44ms inner loop longer now 45ms inner loop longer now 45ms inner loop longer now 46ms inner loop longer now 45ms inner loop longer now 45ms inner loop longer now 45ms inner loop longer now 46ms inner loop longer now 45ms inner loop longer now 45ms inner loop longer now 49ms inner loop longer now 46ms inner loop longer now 48ms inner loop longer now 47ms inner loop longer now 45ms inner loop longer now 49ms inner loop longer now 47ms inner loop longer now 46ms inner loop longer now 47ms inner loop longer now 47ms inner loop longer now 46ms inner loop longer now 46ms inner loop longer now 46ms inner loop longer now 47ms inner loop longer now 48ms inner loop longer now 48ms inner loop longer now 46ms inner loop longer now 46ms other work in expiring entries took 1808 0215 00:29:18.792774 INFO [polling till empty] num_during_iter: 4219975 - removed: cycle/60002 total/840027 - elapsed_ms: 1814 - items/ms: 33 inner loop longer now 56ms inner loop longer now 49ms inner loop longer now 48ms inner loop longer now 48ms inner loop longer now 46ms inner loop longer now 51ms inner loop longer now 50ms inner loop longer now 47ms inner loop longer now 49ms inner loop longer now 47ms inner loop longer now 47ms inner loop longer now 49ms inner loop longer now 48ms inner loop longer now 49ms inner loop longer now 49ms inner loop longer now 49ms inner loop longer now 49ms inner loop longer now 49ms inner loop longer now 49ms inner loop longer now 50ms inner loop longer now 52ms inner loop longer now 48ms inner loop longer now 47ms inner loop longer now 50ms inner loop longer now 54ms inner loop longer now 57ms inner loop longer now 56ms other work in expiring entries took 1512 0215 00:29:21.497398 INFO [polling till empty] num_during_iter: 4159973 - removed: cycle/60002 total/900029 - elapsed_ms: 1518 - items/ms: 39 0215 00:29:23.139800 INFO [polling till empty] num_during_iter: 4099971 - removed: cycle/60002 total/960031 - elapsed_ms: 161 - items/ms: 372 0215 00:29:25.135986 INFO [polling till empty] num_during_iter: 4039969 - removed: cycle/60002 total/1020033 - elapsed_ms: 157 - items/ms: 382 0215 00:29:26.994142 INFO [polling till empty] num_during_iter: 3979967 - removed: cycle/4632 total/1024665 - elapsed_ms: 15 - items/ms: 308 0215 00:29:28.057601 INFO [polling till empty] num_during_iter: 3975335 - removed: cycle/55370 total/1080035 - elapsed_ms: 79 - items/ms: 700 0215 00:29:31.026661 INFO [polling till empty] num_during_iter: 3919965 - removed: cycle/60002 total/1140037 - elapsed_ms: 47 - items/ms: 1276 0215 00:29:33.017612 INFO [polling till empty] num_during_iter: 3859963 - removed: cycle/60002 total/1200039 - elapsed_ms: 39 - items/ms: 1538 0215 00:29:35.018555 INFO [polling till empty] num_during_iter: 3799961 - removed: cycle/60002 total/1260041 - elapsed_ms: 39 - items/ms: 1538 0215 00:29:38.020598 INFO [polling till empty] num_during_iter: 3739959 - removed: cycle/60002 total/1320043 - elapsed_ms: 42 - items/ms: 1428 0215 00:29:40.014173 INFO [polling till empty] num_during_iter: 3679957 - removed: cycle/52531 total/1372574 - elapsed_ms: 35 - items/ms: 1500 0215 00:29:40.982811 INFO [polling till empty] num_during_iter: 3627426 - removed: cycle/7471 total/1380045 - elapsed_ms: 4 - items/ms: 1867 0215 00:29:43.017916 INFO [polling till empty] num_during_iter: 3619955 - removed: cycle/60002 total/1440047 - elapsed_ms: 39 - items/ms: 1538 0215 00:29:46.019039 INFO [polling till empty] num_during_iter: 3559953 - removed: cycle/60002 total/1500049 - elapsed_ms: 40 - items/ms: 1500 0215 00:29:49.020344 INFO [polling till empty] num_during_iter: 3499951 - removed: cycle/60002 total/1560051 - elapsed_ms: 41 - items/ms: 1463 0215 00:29:51.019268 INFO [polling till empty] num_during_iter: 3439949 - removed: cycle/60002 total/1620053 - elapsed_ms: 40 - items/ms: 1500 inner loop longer now 45ms inner loop longer now 45ms inner loop longer now 40ms inner loop longer now 41ms inner loop longer now 39ms inner loop longer now 37ms inner loop longer now 41ms inner loop longer now 38ms inner loop longer now 44ms inner loop longer now 41ms inner loop longer now 40ms inner loop longer now 37ms inner loop longer now 40ms inner loop longer now 37ms inner loop longer now 36ms inner loop longer now 38ms inner loop longer now 37ms inner loop longer now 38ms inner loop longer now 39ms inner loop longer now 38ms inner loop longer now 37ms inner loop longer now 37ms inner loop longer now 40ms inner loop longer now 37ms inner loop longer now 40ms inner loop longer now 37ms inner loop longer now 39ms inner loop longer now 39ms inner loop longer now 38ms inner loop longer now 38ms inner loop longer now 38ms inner loop longer now 39ms inner loop longer now 38ms inner loop longer now 40ms inner loop longer now 37ms inner loop longer now 38ms inner loop longer now 38ms inner loop longer now 38ms inner loop longer now 37ms inner loop longer now 37ms inner loop longer now 39ms other work in expiring entries took 1695 0215 00:29:55.679426 INFO [polling till empty] num_during_iter: 3379947 - removed: cycle/60002 total/1680055 - elapsed_ms: 1700 - items/ms: 35 inner loop longer now 44ms inner loop longer now 41ms inner loop longer now 43ms inner loop longer now 42ms inner loop longer now 42ms inner loop longer now 45ms inner loop longer now 44ms inner loop longer now 38ms inner loop longer now 40ms inner loop longer now 40ms inner loop longer now 38ms inner loop longer now 38ms inner loop longer now 40ms inner loop longer now 41ms inner loop longer now 40ms inner loop longer now 39ms inner loop longer now 39ms inner loop longer now 40ms inner loop longer now 38ms inner loop longer now 39ms inner loop longer now 38ms inner loop longer now 37ms inner loop longer now 38ms other work in expiring entries took 987 0215 00:29:56.969572 INFO [polling till empty] num_during_iter: 3319945 - removed: cycle/18277 total/1698332 - elapsed_ms: 991 - items/ms: 18 0215 00:29:57.081888 INFO [polling till empty] num_during_iter: 3301668 - removed: cycle/41725 total/1740057 - elapsed_ms: 103 - items/ms: 405 0215 00:30:00.124419 INFO [polling till empty] num_during_iter: 3259943 - removed: cycle/60002 total/1800059 - elapsed_ms: 145 - items/ms: 413 0215 00:30:02.123934 INFO [polling till empty] num_during_iter: 3199941 - removed: cycle/60002 total/1860061 - elapsed_ms: 145 - items/ms: 413 0215 00:30:04.064641 INFO [polling till empty] num_during_iter: 3139939 - removed: cycle/60002 total/1920063 - elapsed_ms: 85 - items/ms: 705 0215 00:30:07.022588 INFO [polling till empty] num_during_iter: 3079937 - removed: cycle/60002 total/1980065 - elapsed_ms: 44 - items/ms: 1363 ...<etc> 0215 00:32:20.978474 INFO total time syncing cache: 20188ms 0215 00:32:20.978507 INFO longest sync time seen: 1814msYou'll notice the batch size is locked at
60,002, that's cuz I impl'd theExpirytrait to put a max cap on number of items to be evicted on any given run of.run_pending_tasks()when invoked manually cuz I was trying to restrain these spikes in latency that affect my service.I'm happy to share the code I'm using for running this benchmark.
Would it be possible to make these settings tunable? What do they even mean? Can you think of anything that would solve my problem? I care more about the blocking nature of evictions than I do memory usage (depending on just how much more and the exact trade-off). I am doing I think ~6k inserts per second on an async Moka cache that can hold however many elements cuz I am bounding it by size in bytes of up to 8GB.
Thank you for any help
Metadata
Metadata
Assignees
Labels
No labels