[3804] Measure total execution time for all callouts for the hook.

diff --git a/src/lib/hooks/callout_manager.cc b/src/lib/hooks/callout_manager.cc
index dabdb12308d2477acaddf6362e22fd1dd6bc67e6..2582941bd2809584aea9ceb3ecd42c36c1e6b5d2 100644 (file)
--- a/src/lib/hooks/callout_manager.cc
+++ b/src/lib/hooks/callout_manager.cc
@@ -135,8 +135,14 @@ CalloutManager::callCallouts(int hook_index, CalloutHandle& callout_handle) {
         // change and potentially affect the iteration through that vector.
         CalloutVector callouts(hook_vector_[hook_index]);
 
+        // This object will be used to measure execution time of each callout
+        // and the total time spent in callouts for this hook point.
         util::Stopwatch stopwatch;
 
+        // Mark that the callouts begin for the hook.
+        LOG_DEBUG(hooks_logger, HOOKS_DBG_CALLS, HOOKS_CALLOUTS_BEGIN)
+            .arg(server_hooks_.getName(current_hook_));
+
         // Call all the callouts.
         for (CalloutVector::const_iterator i = callouts.begin();
              i != callouts.end(); ++i) {
@@ -175,6 +181,12 @@ CalloutManager::callCallouts(int hook_index, CalloutHandle& callout_handle) {
 
         }
 
+        // Mark end of callout execution. Include the total execution
+        // time for callouts.
+        LOG_DEBUG(hooks_logger, HOOKS_DBG_CALLS, HOOKS_CALLOUTS_COMPLETE)
+            .arg(server_hooks_.getName(current_hook_))
+            .arg(stopwatch.logFormatTotalDuration());
+
         // Reset the current hook and library indexs to an invalid value to
         // catch any programming errors.
         current_hook_ = -1;

diff --git a/src/lib/hooks/hooks_messages.mes b/src/lib/hooks/hooks_messages.mes
index d0c40e603ad438f8ea2cb3e9d7639d853b3c3088..35a396df6883e91eba44333802b4ffa11755b2ed 100644 (file)
--- a/src/lib/hooks/hooks_messages.mes
+++ b/src/lib/hooks/hooks_messages.mes
@@ -20,6 +20,15 @@ by the library with the given index were removed.  This is similar to
 the HOOKS_CALLOUTS_REMOVED message (and the two are likely to be seen
 together), but is issued at a lower-level in the hook framework.
 
+% HOOKS_CALLOUTS_BEGIN begin all callouts for hook %1
+This debug message is issued when callout manager begins to invoke callouts
+for the hook. The argument specifies the hook name.
+
+% HOOKS_CALLOUTS_COMPLETE completed callouts for hook %1 (total callouts duration: %2)
+This debug message is issued when callout manager has completed execution
+of all callouts for the particular hook. The arguments specify the hook
+name and total execution time for all callouts.
+
 % HOOKS_CALLOUTS_REMOVED callouts removed from hook %1 for library %2
 This is a debug message issued during library unloading.  It notes that
 one of more callouts registered by that library have been removed from