Skip to content

Commit

Permalink
fea: add lineno prefix in event handls log (#52)
Browse files Browse the repository at this point in the history
  • Loading branch information
@aeeeeeep
aeeeeeep authored Jan 8, 2025
1 parent 8494543 commit 1492501
Show file tree
Hide file tree
Showing 8 changed files with 199 additions and 249 deletions.
70 changes: 35 additions & 35 deletions README.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -134,44 +134,44 @@ When running the above script, ObjWatch will generate logs similar to the follow
<summary>Expected Log Output</summary>

```
[2025-01-04 19:15:13] [DEBUG] objwatch: Processed targets:
[2025-01-08 20:02:10] [DEBUG] objwatch: Processed targets:
>>>>>>>>>>
examples/example_usage.py
<<<<<<<<<<
[2025-01-04 19:15:13] [WARNING] objwatch: wrapper 'BaseLogger' loaded
[2025-01-04 19:15:13] [INFO] objwatch: Starting ObjWatch tracing.
[2025-01-04 19:15:13] [INFO] objwatch: Starting tracing.
[2025-01-04 19:15:13] [DEBUG] objwatch: run main <-
[2025-01-04 19:15:13] [DEBUG] objwatch: | run SampleClass.__init__ <- '0':(type)SampleClass, '1':10
[2025-01-04 19:15:13] [DEBUG] objwatch: | end SampleClass.__init__ -> None
[2025-01-04 19:15:13] [DEBUG] objwatch: | run SampleClass.increment <- '0':(type)SampleClass
[2025-01-04 19:15:13] [DEBUG] objwatch: | | upd SampleClass.value None -> 10
[2025-01-04 19:15:13] [DEBUG] objwatch: | | upd SampleClass.value 10 -> 11
[2025-01-04 19:15:13] [DEBUG] objwatch: | end SampleClass.increment -> None
[2025-01-04 19:15:13] [DEBUG] objwatch: | run SampleClass.increment <- '0':(type)SampleClass
[2025-01-04 19:15:13] [DEBUG] objwatch: | | upd SampleClass.value 11 -> 12
[2025-01-04 19:15:13] [DEBUG] objwatch: | end SampleClass.increment -> None
[2025-01-04 19:15:13] [DEBUG] objwatch: | run SampleClass.increment <- '0':(type)SampleClass
[2025-01-04 19:15:13] [DEBUG] objwatch: | | upd SampleClass.value 12 -> 13
[2025-01-04 19:15:13] [DEBUG] objwatch: | end SampleClass.increment -> None
[2025-01-04 19:15:13] [DEBUG] objwatch: | run SampleClass.increment <- '0':(type)SampleClass
[2025-01-04 19:15:13] [DEBUG] objwatch: | | upd SampleClass.value 13 -> 14
[2025-01-04 19:15:13] [DEBUG] objwatch: | end SampleClass.increment -> None
[2025-01-04 19:15:13] [DEBUG] objwatch: | run SampleClass.increment <- '0':(type)SampleClass
[2025-01-04 19:15:13] [DEBUG] objwatch: | | upd SampleClass.value 14 -> 15
[2025-01-04 19:15:13] [DEBUG] objwatch: | end SampleClass.increment -> None
[2025-01-04 19:15:13] [DEBUG] objwatch: | run SampleClass.decrement <- '0':(type)SampleClass
[2025-01-04 19:15:13] [DEBUG] objwatch: | | upd SampleClass.value 15 -> 14
[2025-01-04 19:15:13] [DEBUG] objwatch: | end SampleClass.decrement -> None
[2025-01-04 19:15:13] [DEBUG] objwatch: | run SampleClass.decrement <- '0':(type)SampleClass
[2025-01-04 19:15:13] [DEBUG] objwatch: | | upd SampleClass.value 14 -> 13
[2025-01-04 19:15:13] [DEBUG] objwatch: | end SampleClass.decrement -> None
[2025-01-04 19:15:13] [DEBUG] objwatch: | run SampleClass.decrement <- '0':(type)SampleClass
[2025-01-04 19:15:13] [DEBUG] objwatch: | | upd SampleClass.value 13 -> 12
[2025-01-04 19:15:13] [DEBUG] objwatch: | end SampleClass.decrement -> None
[2025-01-04 19:15:13] [DEBUG] objwatch: end main -> None
[2025-01-04 19:15:13] [INFO] objwatch: Stopping ObjWatch tracing.
[2025-01-04 19:15:13] [INFO] objwatch: Stopping tracing.
[2025-01-08 20:02:10] [WARNING] objwatch: wrapper 'BaseLogger' loaded
[2025-01-08 20:02:10] [INFO] objwatch: Starting ObjWatch tracing.
[2025-01-08 20:02:10] [INFO] objwatch: Starting tracing.
[2025-01-08 20:02:10] [DEBUG] objwatch: 22 run main <-
[2025-01-08 20:02:10] [DEBUG] objwatch: 10 | run SampleClass.__init__ <- '0':(type)SampleClass, '1':10
[2025-01-08 20:02:10] [DEBUG] objwatch: 11 | end SampleClass.__init__ -> None
[2025-01-08 20:02:10] [DEBUG] objwatch: 13 | run SampleClass.increment <- '0':(type)SampleClass
[2025-01-08 20:02:10] [DEBUG] objwatch: 14 | | upd SampleClass.value None -> 10
[2025-01-08 20:02:10] [DEBUG] objwatch: 15 | | upd SampleClass.value 10 -> 11
[2025-01-08 20:02:10] [DEBUG] objwatch: 15 | end SampleClass.increment -> None
[2025-01-08 20:02:10] [DEBUG] objwatch: 13 | run SampleClass.increment <- '0':(type)SampleClass
[2025-01-08 20:02:10] [DEBUG] objwatch: 15 | | upd SampleClass.value 11 -> 12
[2025-01-08 20:02:10] [DEBUG] objwatch: 15 | end SampleClass.increment -> None
[2025-01-08 20:02:10] [DEBUG] objwatch: 13 | run SampleClass.increment <- '0':(type)SampleClass
[2025-01-08 20:02:10] [DEBUG] objwatch: 15 | | upd SampleClass.value 12 -> 13
[2025-01-08 20:02:10] [DEBUG] objwatch: 15 | end SampleClass.increment -> None
[2025-01-08 20:02:10] [DEBUG] objwatch: 13 | run SampleClass.increment <- '0':(type)SampleClass
[2025-01-08 20:02:10] [DEBUG] objwatch: 15 | | upd SampleClass.value 13 -> 14
[2025-01-08 20:02:10] [DEBUG] objwatch: 15 | end SampleClass.increment -> None
[2025-01-08 20:02:10] [DEBUG] objwatch: 13 | run SampleClass.increment <- '0':(type)SampleClass
[2025-01-08 20:02:10] [DEBUG] objwatch: 15 | | upd SampleClass.value 14 -> 15
[2025-01-08 20:02:10] [DEBUG] objwatch: 15 | end SampleClass.increment -> None
[2025-01-08 20:02:10] [DEBUG] objwatch: 17 | run SampleClass.decrement <- '0':(type)SampleClass
[2025-01-08 20:02:10] [DEBUG] objwatch: 19 | | upd SampleClass.value 15 -> 14
[2025-01-08 20:02:10] [DEBUG] objwatch: 19 | end SampleClass.decrement -> None
[2025-01-08 20:02:10] [DEBUG] objwatch: 17 | run SampleClass.decrement <- '0':(type)SampleClass
[2025-01-08 20:02:10] [DEBUG] objwatch: 19 | | upd SampleClass.value 14 -> 13
[2025-01-08 20:02:10] [DEBUG] objwatch: 19 | end SampleClass.decrement -> None
[2025-01-08 20:02:10] [DEBUG] objwatch: 17 | run SampleClass.decrement <- '0':(type)SampleClass
[2025-01-08 20:02:10] [DEBUG] objwatch: 19 | | upd SampleClass.value 13 -> 12
[2025-01-08 20:02:11] [DEBUG] objwatch: 19 | end SampleClass.decrement -> None
[2025-01-08 20:02:11] [DEBUG] objwatch: 26 end main -> None
[2025-01-08 20:02:11] [INFO] objwatch: Stopping ObjWatch tracing.
[2025-01-08 20:02:11] [INFO] objwatch: Stopping tracing.
```

</details>
Expand Down
70 changes: 35 additions & 35 deletions README_zh.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -133,44 +133,44 @@ if __name__ == '__main__':
<summary>Expected Log Output</summary>

```
[2025-01-04 19:15:13] [DEBUG] objwatch: Processed targets:
[2025-01-08 20:02:10] [DEBUG] objwatch: Processed targets:
>>>>>>>>>>
examples/example_usage.py
<<<<<<<<<<
[2025-01-04 19:15:13] [WARNING] objwatch: wrapper 'BaseLogger' loaded
[2025-01-04 19:15:13] [INFO] objwatch: Starting ObjWatch tracing.
[2025-01-04 19:15:13] [INFO] objwatch: Starting tracing.
[2025-01-04 19:15:13] [DEBUG] objwatch: run main <-
[2025-01-04 19:15:13] [DEBUG] objwatch: | run SampleClass.__init__ <- '0':(type)SampleClass, '1':10
[2025-01-04 19:15:13] [DEBUG] objwatch: | end SampleClass.__init__ -> None
[2025-01-04 19:15:13] [DEBUG] objwatch: | run SampleClass.increment <- '0':(type)SampleClass
[2025-01-04 19:15:13] [DEBUG] objwatch: | | upd SampleClass.value None -> 10
[2025-01-04 19:15:13] [DEBUG] objwatch: | | upd SampleClass.value 10 -> 11
[2025-01-04 19:15:13] [DEBUG] objwatch: | end SampleClass.increment -> None
[2025-01-04 19:15:13] [DEBUG] objwatch: | run SampleClass.increment <- '0':(type)SampleClass
[2025-01-04 19:15:13] [DEBUG] objwatch: | | upd SampleClass.value 11 -> 12
[2025-01-04 19:15:13] [DEBUG] objwatch: | end SampleClass.increment -> None
[2025-01-04 19:15:13] [DEBUG] objwatch: | run SampleClass.increment <- '0':(type)SampleClass
[2025-01-04 19:15:13] [DEBUG] objwatch: | | upd SampleClass.value 12 -> 13
[2025-01-04 19:15:13] [DEBUG] objwatch: | end SampleClass.increment -> None
[2025-01-04 19:15:13] [DEBUG] objwatch: | run SampleClass.increment <- '0':(type)SampleClass
[2025-01-04 19:15:13] [DEBUG] objwatch: | | upd SampleClass.value 13 -> 14
[2025-01-04 19:15:13] [DEBUG] objwatch: | end SampleClass.increment -> None
[2025-01-04 19:15:13] [DEBUG] objwatch: | run SampleClass.increment <- '0':(type)SampleClass
[2025-01-04 19:15:13] [DEBUG] objwatch: | | upd SampleClass.value 14 -> 15
[2025-01-04 19:15:13] [DEBUG] objwatch: | end SampleClass.increment -> None
[2025-01-04 19:15:13] [DEBUG] objwatch: | run SampleClass.decrement <- '0':(type)SampleClass
[2025-01-04 19:15:13] [DEBUG] objwatch: | | upd SampleClass.value 15 -> 14
[2025-01-04 19:15:13] [DEBUG] objwatch: | end SampleClass.decrement -> None
[2025-01-04 19:15:13] [DEBUG] objwatch: | run SampleClass.decrement <- '0':(type)SampleClass
[2025-01-04 19:15:13] [DEBUG] objwatch: | | upd SampleClass.value 14 -> 13
[2025-01-04 19:15:13] [DEBUG] objwatch: | end SampleClass.decrement -> None
[2025-01-04 19:15:13] [DEBUG] objwatch: | run SampleClass.decrement <- '0':(type)SampleClass
[2025-01-04 19:15:13] [DEBUG] objwatch: | | upd SampleClass.value 13 -> 12
[2025-01-04 19:15:13] [DEBUG] objwatch: | end SampleClass.decrement -> None
[2025-01-04 19:15:13] [DEBUG] objwatch: end main -> None
[2025-01-04 19:15:13] [INFO] objwatch: Stopping ObjWatch tracing.
[2025-01-04 19:15:13] [INFO] objwatch: Stopping tracing.
[2025-01-08 20:02:10] [WARNING] objwatch: wrapper 'BaseLogger' loaded
[2025-01-08 20:02:10] [INFO] objwatch: Starting ObjWatch tracing.
[2025-01-08 20:02:10] [INFO] objwatch: Starting tracing.
[2025-01-08 20:02:10] [DEBUG] objwatch: 22 run main <-
[2025-01-08 20:02:10] [DEBUG] objwatch: 10 | run SampleClass.__init__ <- '0':(type)SampleClass, '1':10
[2025-01-08 20:02:10] [DEBUG] objwatch: 11 | end SampleClass.__init__ -> None
[2025-01-08 20:02:10] [DEBUG] objwatch: 13 | run SampleClass.increment <- '0':(type)SampleClass
[2025-01-08 20:02:10] [DEBUG] objwatch: 14 | | upd SampleClass.value None -> 10
[2025-01-08 20:02:10] [DEBUG] objwatch: 15 | | upd SampleClass.value 10 -> 11
[2025-01-08 20:02:10] [DEBUG] objwatch: 15 | end SampleClass.increment -> None
[2025-01-08 20:02:10] [DEBUG] objwatch: 13 | run SampleClass.increment <- '0':(type)SampleClass
[2025-01-08 20:02:10] [DEBUG] objwatch: 15 | | upd SampleClass.value 11 -> 12
[2025-01-08 20:02:10] [DEBUG] objwatch: 15 | end SampleClass.increment -> None
[2025-01-08 20:02:10] [DEBUG] objwatch: 13 | run SampleClass.increment <- '0':(type)SampleClass
[2025-01-08 20:02:10] [DEBUG] objwatch: 15 | | upd SampleClass.value 12 -> 13
[2025-01-08 20:02:10] [DEBUG] objwatch: 15 | end SampleClass.increment -> None
[2025-01-08 20:02:10] [DEBUG] objwatch: 13 | run SampleClass.increment <- '0':(type)SampleClass
[2025-01-08 20:02:10] [DEBUG] objwatch: 15 | | upd SampleClass.value 13 -> 14
[2025-01-08 20:02:10] [DEBUG] objwatch: 15 | end SampleClass.increment -> None
[2025-01-08 20:02:10] [DEBUG] objwatch: 13 | run SampleClass.increment <- '0':(type)SampleClass
[2025-01-08 20:02:10] [DEBUG] objwatch: 15 | | upd SampleClass.value 14 -> 15
[2025-01-08 20:02:10] [DEBUG] objwatch: 15 | end SampleClass.increment -> None
[2025-01-08 20:02:10] [DEBUG] objwatch: 17 | run SampleClass.decrement <- '0':(type)SampleClass
[2025-01-08 20:02:10] [DEBUG] objwatch: 19 | | upd SampleClass.value 15 -> 14
[2025-01-08 20:02:10] [DEBUG] objwatch: 19 | end SampleClass.decrement -> None
[2025-01-08 20:02:10] [DEBUG] objwatch: 17 | run SampleClass.decrement <- '0':(type)SampleClass
[2025-01-08 20:02:10] [DEBUG] objwatch: 19 | | upd SampleClass.value 14 -> 13
[2025-01-08 20:02:10] [DEBUG] objwatch: 19 | end SampleClass.decrement -> None
[2025-01-08 20:02:10] [DEBUG] objwatch: 17 | run SampleClass.decrement <- '0':(type)SampleClass
[2025-01-08 20:02:10] [DEBUG] objwatch: 19 | | upd SampleClass.value 13 -> 12
[2025-01-08 20:02:11] [DEBUG] objwatch: 19 | end SampleClass.decrement -> None
[2025-01-08 20:02:11] [DEBUG] objwatch: 26 end main -> None
[2025-01-08 20:02:11] [INFO] objwatch: Stopping ObjWatch tracing.
[2025-01-08 20:02:11] [INFO] objwatch: Stopping tracing.
```

</details>
Expand Down
33 changes: 25 additions & 8 deletions objwatch/event_handls.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -50,12 +50,13 @@ def __init__(self, output_xml: Optional[str] = None) -> None:
atexit.register(self.save_xml)

def handle_run(
self, func_info: Dict[str, Any], function_wrapper: Optional[Any], call_depth: int, rank_info: str
self, lineno: int, func_info: Dict[str, Any], function_wrapper: Optional[Any], call_depth: int, rank_info: str
) -> None:
"""
Handle the 'run' event indicating the start of a function or method execution.
Args:
lineno (int): The line number where the event is called.
func_info (Dict[str, Any]): Information about the function being executed.
function_wrapper (Optional[Any]): Custom wrapper for additional processing.
call_depth (int): Current depth of the call stack.
Expand All @@ -67,14 +68,14 @@ def handle_run(
logger_msg = f"{class_name}.{func_name}"
else:
logger_msg = f"{func_name}"
attrib = {'name': logger_msg}
attrib = {'name': logger_msg, 'run_line': str(lineno)}

if function_wrapper:
call_msg = function_wrapper.wrap_call(func_name, func_info['frame'])
attrib['call_msg'] = call_msg
logger_msg += ' <- ' + call_msg

prefix = "| " * call_depth
prefix = f"{lineno:>5} " + "| " * call_depth
log_debug(f"{rank_info}{prefix}{EventType.RUN.label} {logger_msg}")

if self.output_xml:
Expand All @@ -84,6 +85,7 @@ def handle_run(

def handle_end(
self,
lineno: int,
func_info: Dict[str, Any],
function_wrapper: Optional[Any],
call_depth: int,
Expand All @@ -94,6 +96,7 @@ def handle_end(
Handle the 'end' event indicating the end of a function or method execution.
Args:
lineno (int): The line number where the event is called.
func_info (Dict[str, Any]): Information about the function that has ended.
function_wrapper (Optional[Any]): Custom wrapper for additional processing.
call_depth (int): Current depth of the call stack.
Expand All @@ -112,15 +115,17 @@ def handle_end(
return_msg = function_wrapper.wrap_return(func_name, result)
logger_msg += ' -> ' + return_msg

prefix = "| " * call_depth
prefix = f"{lineno:>5} " + "| " * call_depth
log_debug(f"{rank_info}{prefix}{EventType.END.label} {logger_msg}")

if self.output_xml and len(self.current_node) > 1:
self.current_node[-1].set('return_msg', return_msg)
self.current_node[-1].set('end_line', str(lineno))
self.current_node.pop()

def handle_upd(
self,
lineno: int,
class_name: str,
key: str,
old_value: Any,
Expand All @@ -133,6 +138,7 @@ def handle_upd(
Handle the 'upd' event representing the creation or updating of a variable.
Args:
lineno (int): The line number where the event is called.
class_name (str): Name of the class containing the variable.
key (str): Variable name.
old_value (Any): Previous value of the variable.
Expand All @@ -149,18 +155,24 @@ def handle_upd(

diff_msg = f" {old_msg} -> {current_msg}"
logger_msg = f"{class_name}.{key}{diff_msg}"
prefix = "| " * call_depth
prefix = f"{lineno:>5} " + "| " * call_depth
log_debug(f"{rank_info}{prefix}{EventType.UPD.label} {logger_msg}")

if self.output_xml:
upd_element = ET.Element(
EventType.UPD.label,
attrib={'name': f"{class_name}.{key}", 'old': f"{old_msg}", 'new': f"{current_msg}"},
attrib={
'name': f"{class_name}.{key}",
'line': str(lineno),
'old': f"{old_msg}",
'new': f"{current_msg}",
},
)
self.current_node[-1].append(upd_element)

def handle_apd(
self,
lineno: int,
class_name: str,
key: str,
value_type: type,
Expand All @@ -173,6 +185,7 @@ def handle_apd(
Handle the 'apd' event denoting the addition of elements to data structures.
Args:
lineno (int): The line number where the event is called.
class_name (str): Name of the class containing the data structure.
key (str): Name of the data structure.
value_type (type): Type of the elements being added.
Expand All @@ -183,14 +196,15 @@ def handle_apd(
"""
diff_msg = f" ({value_type.__name__})(len){old_value_len} -> {current_value_len}"
logger_msg = f"{class_name}.{key}{diff_msg}"
prefix = "| " * call_depth
prefix = f"{lineno:>5} " + "| " * call_depth
log_debug(f"{rank_info}{prefix}{EventType.APD.label} {logger_msg}")

if self.output_xml:
apd_element = ET.Element(
EventType.APD.label,
attrib={
'name': f"{class_name}.{key}",
'line': str(lineno),
'old': f"({value_type.__name__})(len){old_value_len}",
'new': f"({value_type.__name__})(len){current_value_len}",
},
Expand All @@ -199,6 +213,7 @@ def handle_apd(

def handle_pop(
self,
lineno: int,
class_name: str,
key: str,
value_type: type,
Expand All @@ -211,6 +226,7 @@ def handle_pop(
Handle the 'pop' event marking the removal of elements from data structures.
Args:
lineno (int): The line number where the event is called.
class_name (str): Name of the class containing the data structure.
key (str): Name of the data structure.
value_type (type): Type of the elements being removed.
Expand All @@ -221,14 +237,15 @@ def handle_pop(
"""
diff_msg = f" ({value_type.__name__})(len){old_value_len} -> {current_value_len}"
logger_msg = f"{class_name}.{key}{diff_msg}"
prefix = "| " * call_depth
prefix = f"{lineno:>5} " + "| " * call_depth
log_debug(f"{rank_info}{prefix}{EventType.POP.label} {logger_msg}")

if self.output_xml:
pop_element = ET.Element(
EventType.POP.label,
attrib={
'name': f"{class_name}.{key}",
'line': str(lineno),
'old': f"({value_type.__name__})(len){old_value_len}",
'new': f"({value_type.__name__})(len){current_value_len}",
},
Expand Down
Loading

0 comments on commit 1492501

Please sign in to comment.