[Asterisk-code-review] Scope Trace: Make it easier to trace through synchronous tasks (asterisk[master])

Friendly Automation asteriskteam at digium.com
Tue Jul 7 14:07:59 CDT 2020


Friendly Automation has submitted this change. ( https://gerrit.asterisk.org/c/asterisk/+/14627 )

Change subject: Scope Trace: Make it easier to trace through synchronous tasks
......................................................................

Scope Trace: Make it easier to trace through synchronous tasks

Tracing through synchronous tasks was a little troublesome because
the new thread's stack counter reset to 0.  This change allows
a synchronous task to set its trace level to be the same as the
thread that pushed the task.  For now, the task's level has to be
passed in the task's data structure but a future enhancement to the
taskprocessor subsystem could automatically set the trace level
of the servant to be that of the caller.

This doesn't really make sense for async tasks because you never
know when they're going to run anyway.

Change-Id: Ib8049c0b815063a45d8c7b0cb4e30b7b87b1d825
---
M include/asterisk/logger.h
M main/logger.c
2 files changed, 108 insertions(+), 19 deletions(-)

Approvals:
  Joshua Colp: Looks good to me, but someone else must approve
  Kevin Harwell: Looks good to me, approved
  Friendly Automation: Approved for Submit



diff --git a/include/asterisk/logger.h b/include/asterisk/logger.h
index 67e4df7..5514d83 100644
--- a/include/asterisk/logger.h
+++ b/include/asterisk/logger.h
@@ -641,14 +641,16 @@
 	AST_TRACE_INDENT_DEC_BEFORE,
 	/*! Decrement the indent after printing the message */
 	AST_TRACE_INDENT_DEC_AFTER,
+	/*! Set the indent to the one provided */
+	AST_TRACE_INDENT_PROVIDED,
 	/*! Don't use or alter the level */
 	AST_TRACE_INDENT_NONE,
 };
 
 #ifdef AST_DEVMODE
 
-void __attribute__((format (printf, 5, 6))) __ast_trace(const char *file, int line, const char *func,
-	enum ast_trace_indent_type indent_type, const char* format, ...);
+void __attribute__((format (printf, 6, 7))) __ast_trace(const char *file, int line, const char *func,
+	enum ast_trace_indent_type indent_type, unsigned long indent, const char* format, ...);
 
 /*!
  * \brief Print a trace message
@@ -661,7 +663,7 @@
  */
 #define ast_trace_raw(level, indent_type, ...) \
 	if (TRACE_ATLEAST(level)) { \
-		__ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, indent_type, " " __VA_ARGS__); \
+		__ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, indent_type, 0, " " __VA_ARGS__); \
 	}
 
 /*!
@@ -675,10 +677,42 @@
  */
 #define ast_trace(level, ...) \
 	if (TRACE_ATLEAST(level)) { \
-		__ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_SAME, " " __VA_ARGS__); \
+		__ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_SAME, 0, " " __VA_ARGS__); \
 	}
 
 /*!
+ * \brief Get the current indent level
+ *
+ * \returns The current indent level
+ */
+unsigned long _ast_trace_get_indent(void);
+#define ast_trace_get_indent() _ast_trace_get_indent()
+
+/*!
+ * \brief Set the current indent level
+ *
+ * \param indent The new indent level
+ */
+void _ast_trace_set_indent(unsigned long indent);
+#define ast_trace_set_indent(indent) _ast_trace_set_indent(indent)
+
+/*!
+ * \brief Increment the indent level
+ *
+ * \returns The new indent level
+ */
+unsigned long _ast_trace_inc_indent(void);
+#define ast_trace_inc_indent() _ast_trace_inc_indent()
+
+/*!
+ * \brief Decrement the indent level
+ *
+ * \returns The new indent level
+ */
+unsigned long _ast_trace_dec_indent(void);
+#define ast_trace_dec_indent() _ast_trace_dec_indent()
+
+/*!
  * \brief Print a trace message with details when a scope is entered or existed.
  *
  * \param level The trace level
@@ -702,14 +736,14 @@
 	auto void __scopevar ## __LINE__ ## __EXIT(void * v); \
 	void __scopevar ## __LINE__ ## __EXIT(void * v __attribute__((unused))) { \
 		if (TRACE_ATLEAST(level)) { \
-			__ast_trace(__FILE__, __LINE__, __trace_funcname, AST_TRACE_INDENT_DEC_BEFORE, " " __VA_ARGS__); \
+			__ast_trace(__FILE__, __LINE__, __trace_funcname, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \
 		} \
 	} \
 	void *__scopevar ## __LINE__ ## __TRACER __attribute__((cleanup(__scopevar ## __LINE__ ## __EXIT))) = (void *) __PRETTY_FUNCTION__ ; \
 	auto int __scopevar ## __LINE__ ## __ENTER(void); \
 	int __scopevar ## __LINE__ ## __ENTER(void) { \
 		if (TRACE_ATLEAST(level)) { \
-			__ast_trace(__FILE__, __LINE__, __trace_funcname, AST_TRACE_INDENT_INC_AFTER, " " __VA_ARGS__); \
+			__ast_trace(__FILE__, __LINE__, __trace_funcname, AST_TRACE_INDENT_INC_AFTER, 0, " " __VA_ARGS__); \
 		} \
 		return 0; \
 	} \
@@ -730,8 +764,16 @@
  */
 #define SCOPE_ENTER(level, ...) \
 	int __scope_level = level; \
+	int __scope_task = 0; \
 	if (TRACE_ATLEAST(level)) { \
-		__ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_INC_AFTER, " " __VA_ARGS__); \
+		__ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_INC_AFTER, 0, " " __VA_ARGS__); \
+	} \
+
+#define SCOPE_ENTER_TASK(level, indent, ...) \
+	int __scope_level = level; \
+	int __scope_task = 1; \
+	if (TRACE_ATLEAST(level)) { \
+		__ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_PROVIDED, indent, " " __VA_ARGS__); \
 	} \
 
 /*!
@@ -745,7 +787,10 @@
  */
 #define SCOPE_EXIT(...) \
 	if (TRACE_ATLEAST(__scope_level)) { \
-		__ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_DEC_BEFORE, " " __VA_ARGS__); \
+		__ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \
+		if (__scope_task) { \
+			_ast_trace_set_indent(0); \
+		} \
 	} \
 
 /*!
@@ -770,7 +815,10 @@
  */
 #define SCOPE_EXIT_EXPR(__expr, ...) \
 	if (TRACE_ATLEAST(__scope_level)) { \
-		__ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_DEC_BEFORE, " " __VA_ARGS__); \
+		__ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \
+		if (__scope_task) { \
+			_ast_trace_set_indent(0); \
+		} \
 	} \
 	__expr
 
@@ -786,7 +834,10 @@
  */
 #define SCOPE_EXIT_RTN(...) \
 	if (TRACE_ATLEAST(__scope_level)) { \
-		__ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_DEC_BEFORE, " " __VA_ARGS__); \
+		__ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \
+		if (__scope_task) { \
+			_ast_trace_set_indent(0); \
+		} \
 	} \
 	return
 
@@ -803,19 +854,27 @@
  */
 #define SCOPE_EXIT_RTN_VALUE(__return_value, ...) \
 	if (TRACE_ATLEAST(__scope_level)) { \
-		__ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_DEC_BEFORE, " " __VA_ARGS__); \
+		__ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \
+		if (__scope_task) { \
+			_ast_trace_set_indent(0); \
+		} \
 	} \
 	return(__return_value)
 
 #else
 #define ast_trace_raw(__level, __indent_type, ...)
 #define ast_trace(__level, ...)
+#define ast_trace_get_indent() (0)
+#define ast_trace_set_indent(indent)
+#define ast_trace_inc_indent()
+#define ast_trace_dec_indent()
 #define SCOPE_TRACE(__level, ...)
 #define SCOPE_ENTER(level, ...)
+#define SCOPE_ENTER_TASK(level, indent, ...)
 #define SCOPE_EXIT(...)
-#define SCOPE_EXIT_EXPR(__expr, ...)
-#define SCOPE_EXIT_RTN(...)
-#define SCOPE_EXIT_RTN_VALUE(__return_value, ...)
+#define SCOPE_EXIT_EXPR(__expr, ...) __expr
+#define SCOPE_EXIT_RTN(...) return
+#define SCOPE_EXIT_RTN_VALUE(__return_value, ...) return __return_value
 #endif
 
 #if defined(__cplusplus) || defined(c_plusplus)
diff --git a/main/logger.c b/main/logger.c
index c66d820..8894b05 100644
--- a/main/logger.c
+++ b/main/logger.c
@@ -2287,9 +2287,36 @@
 AST_THREADSTORAGE_RAW(trace_indent);
 #define LOTS_O_SPACES "                                                                                            "
 
+unsigned long _ast_trace_get_indent(void)
+{
+	return (unsigned long)ast_threadstorage_get_ptr(&trace_indent);
+}
+
+void _ast_trace_set_indent(unsigned long indent)
+{
+	ast_threadstorage_set_ptr(&trace_indent, (void*)indent);
+}
+
+unsigned long _ast_trace_inc_indent(void)
+{
+	unsigned long indent = (unsigned long)ast_threadstorage_get_ptr(&trace_indent);
+	indent++;
+	ast_threadstorage_set_ptr(&trace_indent, (void*)indent);
+
+	return indent;
+}
+
+unsigned long _ast_trace_dec_indent(void)
+{
+	unsigned long indent = (unsigned long)ast_threadstorage_get_ptr(&trace_indent);
+	indent--;
+	ast_threadstorage_set_ptr(&trace_indent, (void*)indent);
+
+	return indent;
+}
 
 void __ast_trace(const char *file, int line, const char *func, enum ast_trace_indent_type indent_type,
-	const char* format, ...)
+	unsigned long new_indent, const char* format, ...)
 {
 	va_list ap;
 	unsigned long indent = (unsigned long)ast_threadstorage_get_ptr(&trace_indent);
@@ -2300,11 +2327,13 @@
 		return;
 	}
 
-	if (indent_type == AST_TRACE_INDENT_INC_BEFORE) {
+	if (indent_type == AST_TRACE_INDENT_PROVIDED) {
+		indent = new_indent;
+		ast_threadstorage_set_ptr(&trace_indent, (void*)indent);
+	} else if (indent_type == AST_TRACE_INDENT_INC_BEFORE) {
 		indent++;
 		ast_threadstorage_set_ptr(&trace_indent, (void*)indent);
-	}
-	if (indent_type == AST_TRACE_INDENT_DEC_BEFORE) {
+	} else if (indent_type == AST_TRACE_INDENT_DEC_BEFORE) {
 		indent--;
 		ast_threadstorage_set_ptr(&trace_indent, (void*)indent);
 	}
@@ -2316,6 +2345,7 @@
 		break;
 	case AST_TRACE_INDENT_INC_BEFORE:
 	case AST_TRACE_INDENT_INC_AFTER:
+	case AST_TRACE_INDENT_PROVIDED:
 		direction = "--> ";
 		break;
 	case AST_TRACE_INDENT_DEC_BEFORE:
@@ -2327,7 +2357,7 @@
 	ast_str_set(&fmt, 0, "%2d %-.*s%s%s:%d %s: %s", (int)indent, (indent_type == AST_TRACE_INDENT_NONE ? 0 : (int)(indent * 4)),
 		LOTS_O_SPACES, direction, file, line, func, S_OR(ast_skip_blanks(format), "\n"));
 
-	if (indent_type == AST_TRACE_INDENT_INC_AFTER) {
+	if (indent_type == AST_TRACE_INDENT_INC_AFTER || indent_type == AST_TRACE_INDENT_PROVIDED) {
 		indent++;
 		ast_threadstorage_set_ptr(&trace_indent, (void*)indent);
 	}

-- 
To view, visit https://gerrit.asterisk.org/c/asterisk/+/14627
To unsubscribe, or for help writing mail filters, visit https://gerrit.asterisk.org/settings

Gerrit-Project: asterisk
Gerrit-Branch: master
Gerrit-Change-Id: Ib8049c0b815063a45d8c7b0cb4e30b7b87b1d825
Gerrit-Change-Number: 14627
Gerrit-PatchSet: 3
Gerrit-Owner: George Joseph <gjoseph at digium.com>
Gerrit-Reviewer: Benjamin Keith Ford <bford at digium.com>
Gerrit-Reviewer: Friendly Automation
Gerrit-Reviewer: Joshua Colp <jcolp at sangoma.com>
Gerrit-Reviewer: Kevin Harwell <kharwell at digium.com>
Gerrit-MessageType: merged
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-code-review/attachments/20200707/340137d4/attachment-0001.html>


More information about the asterisk-code-review mailing list