The attached patch has these improvements:
1) Fix logging & tracing to show micro-seconds, greatly aids debugging
performance issues.
2) Change some pass-by-value string arguments to const string& in router-mgr.
This will improve
performance and a small bit of memory usage.
3) Remove 1 second timeout in 'commit' path. At best, the timeout might have
worked around
a race condition, but I can see no reason to leave it in. I tested with it
set to zero
timeout and things work fine. This makes commits last around 200ms instead
of 1.2ms, which is
a big improvement when scripting xorp.
Thanks,
Ben
--
Ben Greear <[email protected]>
Candela Technologies Inc http://www.candelatech.com
diff --git a/libxorp/debug.c b/libxorp/debug.c
index 8245c12..593d32f 100644
--- a/libxorp/debug.c
+++ b/libxorp/debug.c
@@ -59,16 +59,21 @@ _xdebug_preamble(const char* file,
sbuf = (char*)realloc(sbuf, sbuf_bytes);
}
- /* Format is <pid> +<line> <file> [<function>] <users_debug_message>
+ struct timeval tv;
+ gettimeofday(&tv, NULL);
+ unsigned long long us = tv.tv_usec;
+ us += (tv.tv_sec * 1000000);
+
+ /* Format is <pid> [time-us] +<line> <file> [<function>]
<users_debug_message>
*
* The <line> and <file> formatting is for cutting and pasting as
* arguments to emacs, vi, vim, nedit, etc, but not ed :-(
*/
if (func) {
- snprintf(sbuf, sbuf_bytes, "[ %d %+5d %s %s ] ", spid, line, file,
+ snprintf(sbuf, sbuf_bytes, "[ %d %llu %+5d %s %s ] ", spid, us, line,
file,
func);
} else {
- snprintf(sbuf, sbuf_bytes, "[ %d %+5d %s ] ", spid, line, file);
+ snprintf(sbuf, sbuf_bytes, "[ %d %llu %+5d %s ] ", spid, us, line,
file);
}
return sbuf;
}
diff --git a/libxorp/xlog.c b/libxorp/xlog.c
index 54363ab..69287fc 100644
--- a/libxorp/xlog.c
+++ b/libxorp/xlog.c
@@ -112,7 +112,7 @@ static void xlog_record_va(xlog_level_t log_level, const
char* module_name,
static int xlog_write(FILE* fp, const char* fmt, ...);
static int xlog_write_va(FILE* fp, const char* fmt, va_list ap);
static int xlog_flush(FILE* fp);
-static const char* xlog_localtime2string_short(void);
+//static const char* xlog_localtime2string_short(void);
/*
* ****************************************************************************
@@ -643,7 +643,7 @@ xlog_record_va(xlog_level_t log_level, const char
*module_name,
case XLOG_VERBOSE_LOW: /* The minimum log information */
x_asprintf(&buf_preamble_ptr, "[ %s %s %s %s ] ",
- xlog_localtime2string_short(),
+ xlog_localtime2string(),
xlog_level_names[log_level],
process_name_lead,
module_name);
@@ -651,7 +651,7 @@ xlog_record_va(xlog_level_t log_level, const char
*module_name,
case XLOG_VERBOSE_MEDIUM: /* Add preamble string if non-NULL */
x_asprintf(&buf_preamble_ptr, "[ %s %s %s %s %s ] ",
- xlog_localtime2string_short(),
+ xlog_localtime2string(),
preamble_lead,
xlog_level_names[log_level],
process_name_lead,
@@ -661,7 +661,7 @@ xlog_record_va(xlog_level_t log_level, const char
*module_name,
case XLOG_VERBOSE_HIGH: /* Most verbose */
default:
x_asprintf(&buf_preamble_ptr, "[ %s %s %s %s:%d %s %s ] ",
- xlog_localtime2string_short(),
+ xlog_localtime2string(),
preamble_lead,
xlog_level_names[log_level],
process_name_lead,
@@ -1099,6 +1099,7 @@ xlog_remove_default_output(void)
* Return value: A statically allocated string with the local time using
* the format described above.
**/
+/*
static const char*
xlog_localtime2string_short(void)
{
@@ -1111,7 +1112,7 @@ xlog_localtime2string_short(void)
return (buf);
}
-
+*/
/**
* xlog_localtime2string:
* @void:
diff --git a/rtrmgr/master_conf_tree.cc b/rtrmgr/master_conf_tree.cc
index 730f715..e23ea7a 100644
--- a/rtrmgr/master_conf_tree.cc
+++ b/rtrmgr/master_conf_tree.cc
@@ -18,6 +18,8 @@
// http://xorp.net
+//#define DEBUG_LOGGING
+
#include "rtrmgr_module.h"
@@ -374,7 +376,7 @@ MasterConfigTree::find_inactive_modules() const
for (final_iter = ordered_all_modules.begin();
final_iter != ordered_all_modules.end();
++final_iter) {
- debug_msg("%s ", final_iter->c_str());
+ debug_msg(" %s\n", final_iter->c_str());
}
debug_msg("\n");
@@ -514,7 +516,7 @@ MasterConfigTree::order_module_list(const set<string>&
module_set,
for (final_iter = ordered_modules.begin();
final_iter != ordered_modules.end();
++final_iter) {
- debug_msg("%s ", final_iter->c_str());
+ debug_msg(" %s\n", final_iter->c_str());
}
debug_msg("\n");
}
@@ -600,6 +602,7 @@ MasterConfigTree::commit_changes_pass1(CallBack cb)
}
#endif // 0
+ debug_msg("Queueing commit_pass1_done callback.\n");
_task_manager->run(callback(this, &MasterConfigTree::commit_pass1_done));
}
diff --git a/rtrmgr/module_command.cc b/rtrmgr/module_command.cc
index 3b168ac..4eb432b 100644
--- a/rtrmgr/module_command.cc
+++ b/rtrmgr/module_command.cc
@@ -322,6 +322,7 @@ ModuleCommand::startup_validation(TaskManager& taskmgr)
const
}
return NULL;
} else {
+ XLOG_WARNING("WARNING: Using DelayValidation, module_name: %s",
_module_name.c_str());
return new DelayValidation(_module_name, taskmgr.eventloop(), 2000,
_verbose);
}
@@ -342,6 +343,7 @@ ModuleCommand::config_validation(TaskManager& taskmgr) const
}
return NULL;
} else {
+ XLOG_WARNING("WARNING: Using DelayValidation, module_name: %s",
_module_name.c_str());
return new DelayValidation(_module_name, taskmgr.eventloop(), 2000,
_verbose);
}
@@ -362,6 +364,7 @@ ModuleCommand::ready_validation(TaskManager& taskmgr) const
}
return NULL;
} else {
+ XLOG_WARNING("WARNING: Using DelayValidation, module_name: %s",
_module_name.c_str());
return new DelayValidation(_module_name, taskmgr.eventloop(), 2000,
_verbose);
}
@@ -382,6 +385,7 @@ ModuleCommand::shutdown_validation(TaskManager& taskmgr)
const
}
return NULL;
} else {
+ XLOG_WARNING("WARNING: Using DelayValidation, module_name: %s",
_module_name.c_str());
return new DelayValidation(_module_name, taskmgr.eventloop(), 2000,
_verbose);
}
diff --git a/rtrmgr/task.cc b/rtrmgr/task.cc
index 1ae8244..12fef6b 100644
--- a/rtrmgr/task.cc
+++ b/rtrmgr/task.cc
@@ -148,7 +148,10 @@ XrlStatusValidation::validate(RunShellCommand::ExecId
exec_id, CallBack cb)
// that the xrl_done response gets the right arguments even
// though we're not going to call the XRL.
//
- _retry_timer = eventloop().new_oneoff_after_ms(1000,
+ // This used to be a 1000-milisecond sleep, but that seems lame. This
would make
+ // commit changes take 1+ seconds of real-time, which sucks when you're
scripting xorp.
+ // Changing it to zero. --Ben
+ _retry_timer = eventloop().new_oneoff_after_ms(0,
callback(this, &XrlStatusValidation::dummy_response));
}
}
@@ -1870,7 +1873,7 @@ Task::step3_config()
}
void
-Task::item_done(bool success, bool fatal, string errmsg)
+Task::item_done(bool success, bool fatal, const string& errmsg)
{
debug_msg("item_done (%s)\n", _module_name.c_str());
@@ -1996,7 +1999,7 @@ Task::step8_report()
}
void
-Task::task_fail(string errmsg, bool fatal)
+Task::task_fail(const string& errmsg, bool fatal)
{
debug_msg("%s\n", errmsg.c_str());
@@ -2240,9 +2243,9 @@ TaskManager::run_task()
}
void
-TaskManager::task_done(bool success, string errmsg)
+TaskManager::task_done(bool success, const string& errmsg)
{
- debug_msg("TaskManager::task_done\n");
+ debug_msg("TaskManager::task_done, success: %i errmsg: %s\n",
(int)(success), errmsg.c_str());
if (! success) {
debug_msg("task failed\n");
diff --git a/rtrmgr/task.hh b/rtrmgr/task.hh
index 42b47e6..dc636fe 100644
--- a/rtrmgr/task.hh
+++ b/rtrmgr/task.hh
@@ -409,7 +409,7 @@ private:
class Task {
public:
- typedef XorpCallback2<void, bool, string>::RefPtr CallBack;
+ typedef XorpCallback2<void, bool, const string&>::RefPtr CallBack;
Task(const string& name, TaskManager& taskmgr);
~Task();
@@ -425,7 +425,7 @@ public:
Validation* ready_validation() const { return _ready_validation; }
bool will_shutdown_module() const { return _stop_module; }
void run(CallBack cb);
- void item_done(bool success, bool fatal, string errmsg);
+ void item_done(bool success, bool fatal, const string& errmsg);
bool do_exec() const;
bool is_verification() const;
XorpClient& xorp_client() const;
@@ -479,7 +479,7 @@ protected:
void step7_kill();
void step8_report();
- void task_fail(string errmsg, bool fatal);
+ void task_fail(const string& errmsg, bool fatal);
private:
string _name; // The name of the task
@@ -564,7 +564,7 @@ public:
private:
void reorder_tasks();
void run_task();
- void task_done(bool success, string errmsg);
+ void task_done(bool success, const string& errmsg);
void fail_tasklist_initialization(const string& errmsg);
Task& find_task(const string& module_name);
void null_callback();
diff --git a/rtrmgr/xrl_rtrmgr_interface.cc b/rtrmgr/xrl_rtrmgr_interface.cc
index 56cc87e..ac75e80 100644
--- a/rtrmgr/xrl_rtrmgr_interface.cc
+++ b/rtrmgr/xrl_rtrmgr_interface.cc
@@ -570,7 +570,6 @@ XrlRtrmgrInterface::rtrmgr_0_1_apply_config_change(
ConfigChangeCallBack cb;
cb = callback(this, &XrlRtrmgrInterface::apply_config_change_done,
user_id, string(target));
-
if (_master_config_tree->apply_config_change(user_id, error_msg, deltas,
deletions, cb) != true) {
return XrlCmdError::COMMAND_FAILED(error_msg);
_______________________________________________
Xorp-hackers mailing list
[email protected]
http://mailman.ICSI.Berkeley.EDU/mailman/listinfo/xorp-hackers
