Fix ImportError after refactoring (PY-21487)
[idea/community.git] / python / helpers / pydev / pydevd_concurrency_analyser / pydevd_concurrency_logger.py
1 from pydevd_concurrency_analyser.pydevd_thread_wrappers import ObjectWrapper, wrap_attr
2
3 import pydevd_file_utils
4 from _pydevd_bundle import pydevd_xml
5 from _pydev_bundle._pydev_filesystem_encoding import getfilesystemencoding
6 from _pydevd_bundle.pydevd_constants import dict_contains, get_thread_id, IS_PY3K
7
8 file_system_encoding = getfilesystemencoding()
9
10 try:
11     from urllib import quote
12 except:
13     from urllib.parse import quote  # @UnresolvedImport
14
15 from _pydev_imps._pydev_saved_modules import threading
16 threadingCurrentThread = threading.currentThread
17
18
19 DONT_TRACE_THREADING = ['threading.py', 'pydevd.py']
20 INNER_METHODS = ['_stop']
21 INNER_FILES = ['threading.py']
22 THREAD_METHODS = ['start', '_stop', 'join']
23 LOCK_METHODS = ['__init__', 'acquire', 'release', '__enter__', '__exit__']
24 QUEUE_METHODS = ['put', 'get']
25
26 from _pydevd_bundle.pydevd_comm import GlobalDebuggerHolder, NetCommand
27 import traceback
28
29 import time
30 # return time since epoch in milliseconds
31 cur_time = lambda: int(round(time.time() * 1000000))
32
33
34 try:
35     import asyncio  # @UnresolvedImport
36 except:
37     pass
38
39
40 def get_text_list_for_frame(frame):
41     # partial copy-paste from make_thread_suspend_str
42     curFrame = frame
43     cmdTextList = []
44     try:
45         while curFrame:
46             #print cmdText
47             myId = str(id(curFrame))
48             #print "id is ", myId
49
50             if curFrame.f_code is None:
51                 break #Iron Python sometimes does not have it!
52
53             myName = curFrame.f_code.co_name #method name (if in method) or ? if global
54             if myName is None:
55                 break #Iron Python sometimes does not have it!
56
57             #print "name is ", myName
58
59             filename = pydevd_file_utils.get_abs_path_real_path_and_base_from_frame(curFrame)[1]
60
61             myFile = pydevd_file_utils.norm_file_to_client(filename)
62             if file_system_encoding.lower() != "utf-8" and hasattr(myFile, "decode"):
63                 # myFile is a byte string encoded using the file system encoding
64                 # convert it to utf8
65                 myFile = myFile.decode(file_system_encoding).encode("utf-8")
66
67             #print "file is ", myFile
68             #myFile = inspect.getsourcefile(curFrame) or inspect.getfile(frame)
69
70             myLine = str(curFrame.f_lineno)
71             #print "line is ", myLine
72
73             #the variables are all gotten 'on-demand'
74             #variables = pydevd_xml.frame_vars_to_xml(curFrame.f_locals)
75
76             variables = ''
77             cmdTextList.append('<frame id="%s" name="%s" ' % (myId , pydevd_xml.make_valid_xml_value(myName)))
78             cmdTextList.append('file="%s" line="%s">' % (quote(myFile, '/>_= \t'), myLine))
79             cmdTextList.append(variables)
80             cmdTextList.append("</frame>")
81             curFrame = curFrame.f_back
82     except :
83         traceback.print_exc()
84
85     return cmdTextList
86
87
88 def send_message(event_class, time, name, thread_id, type, event, file, line, frame, lock_id=0, parent=None):
89     dbg = GlobalDebuggerHolder.global_dbg
90     cmdTextList = ['<xml>']
91
92     cmdTextList.append('<' + event_class)
93     cmdTextList.append(' time="%s"' % pydevd_xml.make_valid_xml_value(str(time)))
94     cmdTextList.append(' name="%s"' % pydevd_xml.make_valid_xml_value(name))
95     cmdTextList.append(' thread_id="%s"' % pydevd_xml.make_valid_xml_value(thread_id))
96     cmdTextList.append(' type="%s"' % pydevd_xml.make_valid_xml_value(type))
97     if type == "lock":
98         cmdTextList.append(' lock_id="%s"' % pydevd_xml.make_valid_xml_value(str(lock_id)))
99     if parent is not None:
100         cmdTextList.append(' parent="%s"' % pydevd_xml.make_valid_xml_value(parent))
101     cmdTextList.append(' event="%s"' % pydevd_xml.make_valid_xml_value(event))
102     cmdTextList.append(' file="%s"' % pydevd_xml.make_valid_xml_value(file))
103     cmdTextList.append(' line="%s"' % pydevd_xml.make_valid_xml_value(str(line)))
104     cmdTextList.append('></' + event_class + '>')
105
106     cmdTextList += get_text_list_for_frame(frame)
107     cmdTextList.append('</xml>')
108
109     text = ''.join(cmdTextList)
110     if dbg.writer is not None:
111         dbg.writer.add_command(NetCommand(145, 0, text))
112
113
114 def log_new_thread(global_debugger):
115     t = threadingCurrentThread()
116     event_time = cur_time() - global_debugger.thread_analyser.start_time
117     send_message("threading_event", event_time, t.getName(), get_thread_id(t), "thread",
118              "start", "code_name", 0, None, parent=get_thread_id(t))
119
120
121 class ThreadingLogger:
122     def __init__(self):
123         self.start_time = cur_time()
124
125     def set_start_time(self, time):
126         self.start_time = time
127
128     def log_event(self, frame):
129         write_log = False
130         self_obj = None
131         if dict_contains(frame.f_locals, "self"):
132             self_obj = frame.f_locals["self"]
133             if isinstance(self_obj, threading.Thread) or self_obj.__class__ == ObjectWrapper:
134                 write_log = True
135         if hasattr(frame, "f_back") and frame.f_back is not None:
136             back = frame.f_back
137             if hasattr(back, "f_back") and back.f_back is not None:
138                 back = back.f_back
139                 if dict_contains(back.f_locals, "self"):
140                     if isinstance(back.f_locals["self"], threading.Thread):
141                         write_log = True
142         try:
143             if write_log:
144                 t = threadingCurrentThread()
145                 back = frame.f_back
146                 if not back:
147                     return
148                 _, name, back_base = pydevd_file_utils.get_abs_path_real_path_and_base_from_frame(back)
149                 event_time = cur_time() - self.start_time
150                 method_name = frame.f_code.co_name
151
152                 if isinstance(self_obj, threading.Thread):
153                     if not hasattr(self_obj, "_pydev_run_patched"):
154                         wrap_attr(self_obj, "run")
155                     if (method_name in THREAD_METHODS) and (back_base not in DONT_TRACE_THREADING or \
156                             (method_name in INNER_METHODS and back_base in INNER_FILES)):
157                         thread_id = get_thread_id(self_obj)
158                         name = self_obj.getName()
159                         real_method = frame.f_code.co_name
160                         parent = None
161                         if real_method == "_stop":
162                             if back_base in INNER_FILES and \
163                                             back.f_code.co_name == "_wait_for_tstate_lock":
164                                 back = back.f_back.f_back
165                             real_method = "stop"
166                             if hasattr(self_obj, "_pydev_join_called"):
167                                 parent = get_thread_id(t)
168                         elif real_method == "join":
169                             # join called in the current thread, not in self object
170                             if not self_obj.is_alive():
171                                 return
172                             thread_id = get_thread_id(t)
173                             name = t.getName()
174                             setattr(self_obj, "_pydev_join_called", True)
175
176                         if real_method == "start":
177                             parent = get_thread_id(t)
178                         send_message("threading_event", event_time, name, thread_id, "thread",
179                         real_method, back.f_code.co_filename, back.f_lineno, back, parent=parent)
180                         # print(event_time, self_obj.getName(), thread_id, "thread",
181                         #       real_method, back.f_code.co_filename, back.f_lineno)
182
183                 if method_name == "pydev_after_run_call":
184                     if hasattr(frame, "f_back") and frame.f_back is not None:
185                         back = frame.f_back
186                         if hasattr(back, "f_back") and back.f_back is not None:
187                             back = back.f_back
188                         if dict_contains(back.f_locals, "self"):
189                             if isinstance(back.f_locals["self"], threading.Thread):
190                                 my_self_obj = frame.f_back.f_back.f_locals["self"]
191                                 my_back = frame.f_back.f_back
192                                 my_thread_id = get_thread_id(my_self_obj)
193                                 send_massage = True
194                                 if IS_PY3K and hasattr(my_self_obj, "_pydev_join_called"):
195                                     send_massage = False
196                                     # we can't detect stop after join in Python 2 yet
197                                 if send_massage:
198                                     send_message("threading_event", event_time, "Thread", my_thread_id, "thread",
199                                                  "stop", my_back.f_code.co_filename, my_back.f_lineno, my_back, parent=None)
200
201                 if self_obj.__class__ == ObjectWrapper:
202                     if back_base in DONT_TRACE_THREADING:
203                         # do not trace methods called from threading
204                         return
205                     back_back_base = pydevd_file_utils.get_abs_path_real_path_and_base_from_frame(back.f_back)[-1]
206                     back = back.f_back
207                     if back_back_base in DONT_TRACE_THREADING:
208                         # back_back_base is the file, where the method was called froms
209                         return
210                     if method_name == "__init__":
211                         send_message("threading_event", event_time, t.getName(), get_thread_id(t), "lock",
212                                      method_name, back.f_code.co_filename, back.f_lineno, back, lock_id=str(id(frame.f_locals["self"])))
213                     if dict_contains(frame.f_locals, "attr") and \
214                             (frame.f_locals["attr"] in LOCK_METHODS or
215                             frame.f_locals["attr"] in QUEUE_METHODS):
216                         real_method = frame.f_locals["attr"]
217                         if method_name == "call_begin":
218                             real_method += "_begin"
219                         elif method_name == "call_end":
220                             real_method += "_end"
221                         else:
222                             return
223                         if real_method == "release_end":
224                             # do not log release end. Maybe use it later
225                             return
226                         send_message("threading_event", event_time, t.getName(), get_thread_id(t), "lock",
227                         real_method, back.f_code.co_filename, back.f_lineno, back, lock_id=str(id(self_obj)))
228
229                         if real_method in ("put_end", "get_end"):
230                             # fake release for queue, cause we don't call it directly
231                             send_message("threading_event", event_time, t.getName(), get_thread_id(t), "lock",
232                                          "release", back.f_code.co_filename, back.f_lineno, back, lock_id=str(id(self_obj)))
233                         # print(event_time, t.getName(), get_thread_id(t), "lock",
234                         #       real_method, back.f_code.co_filename, back.f_lineno)
235
236
237         except Exception:
238             traceback.print_exc()
239
240
241 class NameManager:
242     def __init__(self, name_prefix):
243         self.tasks = {}
244         self.last = 0
245         self.prefix = name_prefix
246
247     def get(self, id):
248         if id not in self.tasks:
249             self.last += 1
250             self.tasks[id] = self.prefix + "-" + str(self.last)
251         return self.tasks[id]
252
253
254 class AsyncioLogger:
255     def __init__(self):
256         self.task_mgr = NameManager("Task")
257         self.coro_mgr = NameManager("Coro")
258         self.start_time = cur_time()
259
260     def get_task_id(self, frame):
261         while frame is not None:
262             if dict_contains(frame.f_locals, "self"):
263                 self_obj = frame.f_locals["self"]
264                 if isinstance(self_obj,  asyncio.Task):
265                     method_name = frame.f_code.co_name
266                     if method_name == "_step":
267                         return id(self_obj)
268             frame = frame.f_back
269         return None
270
271     def log_event(self, frame):
272         event_time = cur_time() - self.start_time
273
274         # Debug loop iterations
275         # if isinstance(self_obj, asyncio.base_events.BaseEventLoop):
276         #     if method_name == "_run_once":
277         #         print("Loop iteration")
278
279         if not hasattr(frame, "f_back") or frame.f_back is None:
280             return
281         back = frame.f_back
282
283         if dict_contains(frame.f_locals, "self"):
284             self_obj = frame.f_locals["self"]
285             if isinstance(self_obj, asyncio.Task):
286                 method_name = frame.f_code.co_name
287                 if method_name == "set_result":
288                     task_id = id(self_obj)
289                     task_name = self.task_mgr.get(str(task_id))
290                     send_message("asyncio_event", event_time, task_name, task_name, "thread", "stop", frame.f_code.co_filename,
291                                  frame.f_lineno, frame)
292
293                 method_name = back.f_code.co_name
294                 if method_name == "__init__":
295                     task_id = id(self_obj)
296                     task_name = self.task_mgr.get(str(task_id))
297                     send_message("asyncio_event", event_time, task_name, task_name, "thread", "start", frame.f_code.co_filename,
298                                  frame.f_lineno, frame)
299
300             method_name = frame.f_code.co_name
301             if isinstance(self_obj, asyncio.Lock):
302                 if method_name in ("acquire", "release"):
303                     task_id = self.get_task_id(frame)
304                     task_name = self.task_mgr.get(str(task_id))
305
306                     if method_name == "acquire":
307                         if not self_obj._waiters and not self_obj.locked():
308                             send_message("asyncio_event", event_time, task_name, task_name, "lock",
309                                          method_name+"_begin", frame.f_code.co_filename, frame.f_lineno, frame, lock_id=str(id(self_obj)))
310                         if self_obj.locked():
311                             method_name += "_begin"
312                         else:
313                             method_name += "_end"
314                     elif method_name == "release":
315                         method_name += "_end"
316
317                     send_message("asyncio_event", event_time, task_name, task_name, "lock",
318                                  method_name, frame.f_code.co_filename, frame.f_lineno, frame, lock_id=str(id(self_obj)))
319
320             if isinstance(self_obj, asyncio.Queue):
321                 if method_name in ("put", "get", "_put", "_get"):
322                     task_id = self.get_task_id(frame)
323                     task_name = self.task_mgr.get(str(task_id))
324
325                     if method_name == "put":
326                         send_message("asyncio_event", event_time, task_name, task_name, "lock",
327                                      "acquire_begin", frame.f_code.co_filename, frame.f_lineno, frame, lock_id=str(id(self_obj)))
328                     elif method_name == "_put":
329                         send_message("asyncio_event", event_time, task_name, task_name, "lock",
330                                      "acquire_end", frame.f_code.co_filename, frame.f_lineno, frame, lock_id=str(id(self_obj)))
331                         send_message("asyncio_event", event_time, task_name, task_name, "lock",
332                                      "release", frame.f_code.co_filename, frame.f_lineno, frame, lock_id=str(id(self_obj)))
333                     elif method_name == "get":
334                         back = frame.f_back
335                         if back.f_code.co_name != "send":
336                             send_message("asyncio_event", event_time, task_name, task_name, "lock",
337                                          "acquire_begin", frame.f_code.co_filename, frame.f_lineno, frame, lock_id=str(id(self_obj)))
338                         else:
339                             send_message("asyncio_event", event_time, task_name, task_name, "lock",
340                                          "acquire_end", frame.f_code.co_filename, frame.f_lineno, frame, lock_id=str(id(self_obj)))
341                             send_message("asyncio_event", event_time, task_name, task_name, "lock",
342                                          "release", frame.f_code.co_filename, frame.f_lineno, frame, lock_id=str(id(self_obj)))