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