Make refreshing our list of relays less expensive
Created by: pastly
This file is from measuring a relay but having to stop and refresh our list of relays in the network first (in the code here). expensive.txt
Excerpt:
Thu Jun 21 21:05:40 2018 profile/thread-BeTheChange-1529607940.6844442.dat
8115121 function calls (8101347 primitive calls) in 172.868 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 172.869 172.869 /home/pastly/src/simple-bw-scanner/sbws/core/scanner.py:169(measure_relay)
2 0.000 0.000 126.375 63.187 /home/pastly/src/simple-bw-scanner/sbws/lib/relaylist.py:129(relays)
2 0.329 0.165 126.375 63.187 /home/pastly/src/simple-bw-scanner/sbws/lib/relaylist.py:174(_refresh)
2 0.000 0.000 126.045 63.023 /home/pastly/src/simple-bw-scanner/sbws/lib/relaylist.py:167(_init_relays)
2 0.282 0.141 126.045 63.022 /home/pastly/src/simple-bw-scanner/sbws/lib/relaylist.py:170(<listcomp>)
25599/12735 0.147 0.000 119.294 0.009 /home/pastly/src/simple-bw-scanner/stem/stem/control.py:473(wrapped)
12726 0.190 0.000 118.305 0.009 /home/pastly/src/simple-bw-scanner/sbws/lib/relaylist.py:16(__init__)
12726 0.239 0.000 117.829 0.009 /home/pastly/src/simple-bw-scanner/stem/stem/control.py:1785(get_server_descriptor)
12732 1.094 0.000 108.271 0.009 /home/pastly/src/simple-bw-scanner/stem/stem/control.py:1117(get_info)
12738 74.675 0.006 102.640 0.008 /home/pastly/src/simple-bw-scanner/stem/stem/control.py:585(msg)
1 0.000 0.000 85.842 85.842 /home/pastly/src/simple-bw-scanner/sbws/lib/circuitbuilder.py:152(build_circuit)
1 0.000 0.000 84.876 84.876 /home/pastly/src/simple-bw-scanner/sbws/lib/circuitbuilder.py:135(_random_sample_relays)
1 0.000 0.000 84.798 84.798 /home/pastly/src/simple-bw-scanner/sbws/lib/circuitbuilder.py:50(relays)
18 0.001 0.000 43.931 2.441 /home/pastly/src/simple-bw-scanner/sbws/core/scanner.py:32(timed_recv_from_server)
18 0.000 0.000 43.929 2.440 /home/pastly/src/simple-bw-scanner/sbws/util/requests.py:16(get)
501 43.867 0.088 43.867 0.088 {method 'read' of '_ssl._SSLSocket' objects}This file is from measuring a relay but not needing to stop and do that. cheap.txt
Excerpt:
Thu Jun 21 21:08:17 2018 profile/thread-quietquark1-1529608097.691879.dat
135824 function calls (134906 primitive calls) in 53.757 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 53.757 53.757 /home/pastly/src/simple-bw-scanner/sbws/core/scanner.py:169(measure_relay)
444 46.699 0.105 46.699 0.105 {method 'read' of '_ssl._SSLSocket' objects}
18 0.001 0.000 46.116 2.562 /home/pastly/src/simple-bw-scanner/sbws/core/scanner.py:32(timed_recv_from_server)
18 0.000 0.000 46.114 2.562 /home/pastly/src/simple-bw-scanner/sbws/util/requests.py:16(get)
1 0.000 0.000 38.882 38.882 /home/pastly/src/simple-bw-scanner/sbws/core/scanner.py:100(measure_bandwidth_to_server)
170 0.002 0.000 31.658 0.186 {method 'join' of 'bytes' objects}
360 0.005 0.000 31.607 0.088 {method 'readinto' of '_io.BufferedReader' objects}
208 0.001 0.000 15.113 0.073 {method 'readline' of '_io.BufferedReader' objects}
1 0.000 0.000 7.242 7.242 /home/pastly/src/simple-bw-scanner/sbws/core/scanner.py:76(measure_rtt_to_server)
1 0.000 0.000 4.444 4.444 /home/pastly/src/simple-bw-scanner/sbws/lib/destination.py:107(is_usable)
1 1.692 1.692 4.443 4.443 /home/pastly/src/simple-bw-scanner/sbws/lib/destination.py:31(connect_to_destination_over_circuit)
1 0.000 0.000 3.105 3.105 /home/pastly/src/simple-bw-scanner/sbws/lib/circuitbuilder.py:152(build_circuit)
120 3.058 0.025 3.058 0.025 {method 'acquire' of '_thread.lock' objects}
1 0.000 0.000 3.053 3.053 /home/pastly/src/simple-bw-scanner/sbws/lib/circuitbuilder.py:78(_build_circuit_impl)
1 0.000 0.000 3.053 3.053 /home/pastly/src/simple-bw-scanner/stem/stem/control.py:3420(new_circuit)
1 0.000 0.000 3.053 3.053 /home/pastly/src/simple-bw-scanner/stem/stem/control.py:3442(extend_circuit)
4 0.000 0.000 3.046 0.761 /home/pastly/src/simple-bw-scanner/stem/stem/control.py:4040(_get_with_timeout)
1 0.000 0.000 2.748 2.748 /home/pastly/src/simple-bw-scanner/sbws/util/requests.py:20(head)
1 1.260 1.260 1.260 1.260 {method 'do_handshake' of '_ssl._SSLSocket' objects}
5 0.000 0.000 0.649 0.130 {method 'read' of '_io._RawIOBase' objects}
5 0.649 0.130 0.649 0.130 {method 'recv_into' of '_socket.socket' objects}If I'm not mistaken, measurement threads will dogpile on refreshing the list of relays, casing the process to take longer.
Consider:
- t=0 Thread 1 goes to get the list of relays in the network. The RelayList realizes it needs to refresh its list of relays. Assume this will take about 20 seconds, if allowed to max out the CPU
- t=3 Thread 2 similarly wants the list of relays in the network. The RelayList doesn't realize it is currently refreshing, and so Thread 2 starts doing the work to refresh as well. Now that two threads are doing this refreshing, what would normally take 20 seconds will take ~40 seconds.
- t=4-39 CPU is hardcore pegged at 100% ...
- t=40 They both finish refreshing and get back to more productive work
So what do I think needs to happen?
I think a check (maybe a lock? event?) on whether or not there is already a check in progress. If so, we should either (1) also wait for the refresh to finish and then grab the fresh results, or (2) immediately take the existing results that are a little out of date.
I like (1) better because it sounds cleaner, but I'm a little worried that having a bunch of worker threads block might hurt how quickly we can produce measurements. At least they won't be blocking for as long since only one thread will be doing the refresh work, so if I tackle this I will try (1) first. I run with 6 measurement threads and watched them slowly die and do their fair share of pegging the CPU, so I suspect this refreshing takes about 1/3rd - 1/6th the amount of time if only one thread is doing it.
(Friendly reminder that in Python a multithreaded program is still bound to the performance of a single CPU. There's multiprocessing to get around that, be we aren't using that. And I don't think that's a good solution at this time.)