Add Action timing points #87

admin/oik-bwtrace.php

@@ -125,6 +125,8 @@ function oik_action_options() {
 	BW_::bw_textarea_arr( "bw_action_options", __( "Trace attached hook functions", "oik-bwtrace" ), $options, "hook_funcs", 80 );
 	BW_::bw_textarea_arr( "bw_action_options", __( "Hooks to debug backtrace", "oik-bwtrace" ), $options, "backtrace", 80 );
 	BW_::bw_textarea_arr( "bw_action_options", __( "'String watch' for this string", "oik-bwtrace" ), $options, "stringwatch", 80 );
+	BW_::bw_textarea_arr( "bw_action_options", __( 'Action timing points', 'oik-bwtrace'), $options, 'action_timing', 80 );
+
   etag( "table" ); 			
   BW_::p( isubmit( "ok", __( "Save changes", "oik-bwtrace" ), null, "button-primary" ) );
   etag( "form" );

includes/oik-action-counts.php

@@ -1,4 +1,4 @@
-<?php // (C) Copyright Bobbing Wide 2014-2016
+<?php // (C) Copyright Bobbing Wide 2014-2016,2021
 
 /**
  * Activate / deactivate _oik-bwtrace-mu processing
@@ -337,17 +337,18 @@ function bw_trace_is_timing_point_hook( $hook ) {
  *
  */
 function bw_trace_get_timing_point_hooks() {
- $timing_point_hooks = bw_assoc( bw_as_array( 'the_post' ));
- return $timing_point_hooks;
+	global $bw_action_options;
+	$action_timing = bw_array_get( $bw_action_options, "action_timing", [] );
+    $timing_point_hooks = bw_assoc( bw_as_array( $action_timing ));
+    return $timing_point_hooks;
 }
 /**
  * Returns the time that the hook was invoked
  *
  * $microtime is the current time stored as a floating point number
  * we need to subtract the request start time to show the elapsed time.
  *
- * And we can determine the elapsed time from the previous request
- * if we save that figure as well.
+ * And we can determine the elapsed time from the previous request if we save that figure as well.
  *
  * @param $end_hook
  * @return mixed
@@ -370,6 +371,14 @@ function bw_trace_get_hook_start_time( $end_hook=null ) {
 	    }
     }
     $elapsed = $microtime - $previous;
+	/**
+	 * If the event appears to have happened earlier than the previous event then ignore this, but still produce the output.
+	 * This can happen if the action was run before timing logic kicked in.
+	 * eg when __oik-lib-mu is loaded before __oik-bwtrace-mu.
+	 */
+    if ( $elapsed < 0 ) {
+    	$elapsed = 0;
+    }
     $total += $elapsed;
 
     $previous = $microtime;

includes/oik-actions.php

@@ -251,9 +251,10 @@ function bw_trace_fetch_queries_execution_time() {
     global $wpdb;
     $wpdb->elapsed_query_time = 0;
     $queries = [];
+    $accum = 0;
     if (count($wpdb->queries)) {
          $count = 0;
-         $accum = 0;
+
          foreach ($wpdb->queries as $key => $query) {
              $execution = $query[1];
              $accum += $execution;
@@ -374,7 +375,7 @@ function bw_trace_plugin_loaded_report() {
 	global $bw_trace_anonymous;
 	$saved_anon = $bw_trace_anonymous;
 	$bw_trace_anonymous = true;
-	bw_trace2( $bw_trace_plugins_loaded, 'bw_trace_plugins_loaded', false);
+	//bw_trace2( $bw_trace_plugins_loaded, 'bw_trace_plugins_loaded', false);
 	//bw_trace2( $bw_trace_plugins_loaded_unkeyed, 'bw_trace_plugins_loaded_unkeyed', false);
 	$prev = $_SERVER['REQUEST_TIME_FLOAT'];
 	$accum = 0;