patateqbool
commented
5 years ago Hi ! I will try this tonight at 35c3. Thanks for the report.
Closed AntonKukoba1 closed 5 years ago
patateqbool
commented
5 years ago Hi ! I will try this tonight at 35c3. Thanks for the report.
AntonKukoba1
commented
5 years ago @patateqbool any news?
patateqbool
commented
5 years ago Hey @AntonKukoba1, Indeed the upload is really very slow now. I think we broke something during the refactoring 1 month ago. I will take a closer look tonight, I will update this issue after that. Sorry for the response time and the inconvenience...
patateqbool
commented
5 years ago So after 2 hours of profiling, I didn't manage to find the exact location for the bug. Here is the beginning of the generated cprofile:
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
42/1 0.000 0.000 698.488 698.488 {built-in method builtins.exec}
1 0.000 0.000 698.488 698.488 idarling_server.py:13(<module>)
1 0.000 0.000 698.448 698.448 server.py:86(main)
1 0.000 0.000 698.447 698.447 server.py:55(start)
1 696.684 696.684 698.446 698.446 {built-in method exec_}
13844 0.174 0.000 0.921 0.000 server.py:73(timer_event)
13845 0.731 0.000 0.731 0.000 {singleShot}
4804 0.214 0.000 0.500 0.000 sockets.py:165(_notify_read)
9 0.016 0.002 0.323 0.036 sockets.py:286(event)
7 0.000 0.000 0.307 0.044 sockets.py:296(_dispatch)
7 0.000 0.000 0.307 0.044 server.py:110(recv_packet)
1 0.090 0.090 0.305 0.305 server.py:181(_handle_upload_file)
1 0.179 0.179 0.179 0.179 {method 'write' of '_io.BufferedWriter' objects}
4809 0.153 0.000 0.153 0.000 {method 'extend' of 'bytearray' objects}
4804 0.106 0.000 0.106 0.000 {method 'recv' of '_socket.socket' objects}
2 0.000 0.000 0.064 0.032 server.py:13(<module>)
50/2 0.000 0.000 0.040 0.020 <frozen importlib._bootstrap>:978(_find_and_load)
50/2 0.000 0.000 0.040 0.020 <frozen importlib._bootstrap>:948(_find_and_load_unlocked)
72/3 0.000 0.000 0.040 0.013 <frozen importlib._bootstrap>:1009(_handle_fromlist)
68/2 0.000 0.000 0.040 0.020 <frozen importlib._bootstrap>:211(_call_with_frames_removed)
4/1 0.000 0.000 0.040 0.040 {built-in method builtins.__import__}
50/2 0.000 0.000 0.040 0.020 <frozen importlib._bootstrap>:663(_load_unlocked)
36/2 0.000 0.000 0.040 0.020 <frozen importlib._bootstrap_external>:722(exec_module)I don't see any crazy tottime for the socket part... I have currently no idea what can cause this slowness. @NeatMonster any idea ?
patateqbool
commented
5 years ago Hi again. I've done better testcases and profiling, here what I have: I've simply add that in _notify_write:
def _notify_write(self):
"""Callback called when some data is ready to written on the socket."""
import time
self._remove_me2 = self._remove_me
self._remove_me = time.time()
print(self._remove_me - self._remove_me2)
...
# Trigger the upback
if (
isinstance(self._write_packet, Container)
and self._write_packet.upback
):
self._write_packet.size -= count
total = len(self._write_packet.content)
sent = max(total - self._write_packet.size, 0)
print("0x%x/0x%x" % (sent, total))The results:
0x67ff14/0x12bd8168
0.161806821823
0x68ff13/0x12bd8168
0.160951137543
0x69ff12/0x12bd8168
0.153469085693
0x6aff11/0x12bd8168
0.154184818268
0x6bff10/0x12bd8168
0.153731107712
0x6cff0f/0x12bd8168Pretty damn slow...
So I've done line by line profiling on the function _notify_write, here the results:
Total time: 0.012691 s
File: /home/patate/work/dev/idarling.re/idarling/shared/sockets.py
Function: _notify_write at line 232
Line # Hits Time Per Hit % Time Line Contents
==============================================================
232 @profile
233 def _notify_write(self, _):
234 """Callback called when some data is ready to written on the socket."""
235 1895 8538.0 4.5 67.3 if not self._check_socket():
236 return
237
238 1895 1377.0 0.7 10.9 if not self._write_buffer:
239 1895 1139.0 0.6 9.0 if not self._outgoing:
240 1890 1059.0 0.6 8.3 return # No more packets to send
241 5 15.0 3.0 0.1 self._write_packet = self._outgoing.popleft()
242
243 # Dump the packet as a line
244 5 4.0 0.8 0.0 try:
245 5 305.0 61.0 2.4 line = json.dumps(self._write_packet.build_packet())
246 5 18.0 3.6 0.1 line = line.encode("utf-8") + b"\n"
247 except Exception as e:
248 msg = "Invalid packet being sent: %s" % self._write_packet
249 self._logger.warning(msg)
250 self._logger.exception(e)
251 return
252
253 # Write the container's content
254 5 24.0 4.8 0.2 self._write_buffer.extend(bytearray(line))
255 5 11.0 2.2 0.1 if isinstance(self._write_packet, Container):
256 data = self._write_packet.content
257 self._write_buffer.extend(bytearray(data))
258 self._write_packet.size += len(line)
259
260 # Send as many bytes as possible
261 5 4.0 0.8 0.0 try:
262 5 15.0 3.0 0.1 count = min(len(self._write_buffer), ClientSocket.MAX_DATA_SIZE)
263 5 129.0 25.8 1.0 sent = self._socket.send(self._write_buffer[:count])
264 5 12.0 2.4 0.1 self._write_buffer = self._write_buffer[sent:]
265 except socket.error as e:
266 if (
267 e.errno not in (errno.EAGAIN, errno.EWOULDBLOCK)
268 and not isinstance(e, ssl.SSLWantReadError)
269 and not isinstance(e, ssl.SSLWantWriteError)
270 ):
271 self.disconnect(e)
272 return # Can't write anything
273
274 # Trigger the upback
275 if (
276 5 9.0 1.8 0.1 isinstance(self._write_packet, Container)
277 and self._write_packet.upback
278 ):
279 self._write_packet.size -= count
280 total = len(self._write_packet.content)
281 sent = max(total - self._write_packet.size, 0)
282 self._write_packet.upback(sent, total)
283
284 5 7.0 1.4 0.1 if not self._write_buffer and not self._outgoing:
285 5 25.0 5.0 0.2 self._write_notifier.setEnabled(False)67% is in _check_socket()... Here the _check_socket() profiling:
File: /home/patate/work/dev/idarling.re/idarling/shared/sockets.py
Function: _check_socket at line 137
Line # Hits Time Per Hit % Time Line Contents
==============================================================
137 @profile
138 def _check_socket(self):
139 """Check if the connection has been established yet."""
140 # Ignore if you're already connected
141 6702 16443.0 2.5 72.9 if self._connected:
142 6701 6084.0 0.9 27.0 return True
143
144 # Check if the connection was successful
145 1 4.0 4.0 0.0 ret = self._socket.getsockopt(socket.SOL_SOCKET, socket.SO_ERROR)
146 1 0.0 0.0 0.0 if ret != 0 and ret != errno.EINPROGRESS and ret != errno.EWOULDBLOCK:
147 self.disconnect(socket.error(ret, os.strerror(ret)))
148 return False
149 else:
150 # Do SSL handshake if needed
151 1 2.0 2.0 0.0 if isinstance(self._socket, ssl.SSLSocket):
152 try:
153 self._socket.do_handshake()
154 except socket.error as e:
155 if not isinstance(
156 e, ssl.SSLWantReadError
157 ) and not isinstance(e, ssl.SSLWantReadError):
158 self.disconnect(e)
159 return False
160
161 1 1.0 1.0 0.0 self._connected = True
162 1 10.0 10.0 0.0 self._logger.debug("Connected")
163 1 0.0 0.0 0.0 return TrueI'm still trying to understand the bug...
patateqbool
commented
5 years ago Ok, I finally found the bug:
begin = time.time()
self._write_buffer = self._write_buffer[sent:]
end = time.time()
print(end - begin)
Results:
0x2cff4f/0x12bd8168
0.187237024307
0.147576808929
0x2dff4e/0x12bd8168
0.158697128296
0.15110206604
0x2eff4d/0x12bd8168
0.161484003067
0.149582862854
0x2fff4c/0x12bd8168Commit f797dcd291e903ef676b6abdac581e13520cb69e should partially fixed the bug, I think there are still some possible optimizations because the end of the upload goes very fast unlike the beginning, and the download is very fast too. I'll give it a shot later during the day.
@AntonKukoba1, can you confirm the optimization?
AntonKukoba1
commented
5 years ago it's 5 minutes to upload to the integrated server. And yes it gets faster in the end.
patateqbool
commented
5 years ago Ok, it's consistent with the times I have, it had to be divided by 3. So, now the download with the integreted server is instant, but the upload is still low. By monitoring the time here, we have that:
Time during uploading (client part)
0.0311799049377
0.0283708572388
0.0324139595032
0.0308940410614
0.0369739532471
0.0320489406586
0.0315339565277
Time during downloading (server part)
[INFO] (127.0.0.1:37934) Loaded file test_test.idb
1.9073486328125e-06
7.152557373046875e-07
4.76837158203125e-07
7.152557373046875e-07
4.76837158203125e-07
7.152557373046875e-07
4.76837158203125e-07
4.76837158203125e-07
7.152557373046875e-07
4.76837158203125e-07
4.76837158203125e-07
7.152557373046875e-07
4.76837158203125e-07
4.76837158203125e-07I do not understand where this difference comes from for now.
patateqbool
commented
5 years ago Hi @AntonKukoba1,
This issue must now be fixed by the commit d8185bc7e4951c243ba4100aa5fc36bf61da286a. Can you confirm and close the issue?
Thank you for the bug report.
AntonKukoba1
commented
5 years ago Yep it became 3 times faster.
I have 300 Mb idb file and it takes 15 minutes to uploads to the server. Even if the integrated server is used. This doesn't look like a slow network connection issue. I expect it to upload in 1-2 minutes. The time of download is the same.